Orderer container fails to run Hyperledger Fabric 2.0

Question

I am trying to make my own network on top of the "test-network" provided in fabric-samples. Although the test-network runs fine, when i make my changes into it (like renaming org1 and org2 to some other names) all runs but the orderer container stops running after a few seconds,

docker logs for the container

    2020-12-30 12:38:46.267 UTC [localconfig] completeInitialization -> WARN 001 General.GenesisFile should be replaced by General.BootstrapFile
2020-12-30 12:38:46.268 UTC [localconfig] completeInitialization -> INFO 002 Kafka.Version unset, setting to 0.10.2.0
2020-12-30 12:38:46.268 UTC [orderer.common.server] prettyPrintStruct -> INFO 003 Orderer config values:
    General.ListenAddress = "0.0.0.0"
    General.ListenPort = 7050
    General.TLS.Enabled = true
    General.TLS.PrivateKey = "/var/hyperledger/orderer/tls/server.key"
    General.TLS.Certificate = "/var/hyperledger/orderer/tls/server.crt"
    General.TLS.RootCAs = [/var/hyperledger/orderer/tls/ca.crt]
    General.TLS.ClientAuthRequired = false
    General.TLS.ClientRootCAs = []
    General.TLS.TLSHandshakeTimeShift = 0s
    General.Cluster.ListenAddress = ""
    General.Cluster.ListenPort = 0
    General.Cluster.ServerCertificate = ""
    General.Cluster.ServerPrivateKey = ""
    General.Cluster.ClientCertificate = "/var/hyperledger/orderer/tls/server.crt"
    General.Cluster.ClientPrivateKey = "/var/hyperledger/orderer/tls/server.key"
    General.Cluster.RootCAs = [/var/hyperledger/orderer/tls/ca.crt]
    General.Cluster.DialTimeout = 5s
    General.Cluster.RPCTimeout = 7s
    General.Cluster.ReplicationBufferSize = 20971520
    General.Cluster.ReplicationPullTimeout = 5s
    General.Cluster.ReplicationRetryTimeout = 5s
    General.Cluster.ReplicationBackgroundRefreshInterval = 5m0s
    General.Cluster.ReplicationMaxRetries = 12
    General.Cluster.SendBufferSize = 10
    General.Cluster.CertExpirationWarningThreshold = 168h0m0s
    General.Cluster.TLSHandshakeTimeShift = 0s
    General.Keepalive.ServerMinInterval = 1m0s
    General.Keepalive.ServerInterval = 2h0m0s
    General.Keepalive.ServerTimeout = 20s
    General.ConnectionTimeout = 0s
    General.GenesisMethod = "file"
    General.GenesisFile = "/var/hyperledger/orderer/orderer.genesis.block"
    General.BootstrapMethod = "file"
    General.BootstrapFile = "/var/hyperledger/orderer/orderer.genesis.block"
    General.Profile.Enabled = false
    General.Profile.Address = "0.0.0.0:6060"
    General.LocalMSPDir = "/var/hyperledger/orderer/msp"
    General.LocalMSPID = "OrdererMSP"
    General.BCCSP.ProviderName = "SW"
    General.BCCSP.SwOpts.SecLevel = 256
    General.BCCSP.SwOpts.HashFamily = "SHA2"
    General.BCCSP.SwOpts.Ephemeral = true
    General.BCCSP.SwOpts.FileKeystore.KeyStorePath = ""
    General.BCCSP.SwOpts.DummyKeystore =
    General.BCCSP.SwOpts.InmemKeystore =
    General.Authentication.TimeWindow = 15m0s
    General.Authentication.NoExpirationChecks = false
    FileLedger.Location = "/var/hyperledger/production/orderer"
    FileLedger.Prefix = "hyperledger-fabric-ordererledger"
    Kafka.Retry.ShortInterval = 5s
    Kafka.Retry.ShortTotal = 10m0s
    Kafka.Retry.LongInterval = 5m0s
    Kafka.Retry.LongTotal = 12h0m0s
    Kafka.Retry.NetworkTimeouts.DialTimeout = 10s
    Kafka.Retry.NetworkTimeouts.ReadTimeout = 10s
    Kafka.Retry.NetworkTimeouts.WriteTimeout = 10s
    Kafka.Retry.Metadata.RetryMax = 3
    Kafka.Retry.Metadata.RetryBackoff = 250ms
    Kafka.Retry.Producer.RetryMax = 3
    Kafka.Retry.Producer.RetryBackoff = 100ms
    Kafka.Retry.Consumer.RetryBackoff = 2s
    Kafka.Verbose = true
    Kafka.Version = 0.10.2.0
    Kafka.TLS.Enabled = false
    Kafka.TLS.PrivateKey = ""
    Kafka.TLS.Certificate = ""
    Kafka.TLS.RootCAs = []
    Kafka.TLS.ClientAuthRequired = false
    Kafka.TLS.ClientRootCAs = []
    Kafka.TLS.TLSHandshakeTimeShift = 0s
    Kafka.SASLPlain.Enabled = false
    Kafka.SASLPlain.User = ""
    Kafka.SASLPlain.Password = ""
    Kafka.Topic.ReplicationFactor = 1
    Debug.BroadcastTraceDir = ""
    Debug.DeliverTraceDir = ""
    Consensus = map[SnapDir:/var/hyperledger/production/orderer/etcdraft/snapshot WALDir:/var/hyperledger/production/orderer/etcdraft/wal]
    Operations.ListenAddress = "127.0.0.1:8443"
    Operations.TLS.Enabled = false
    Operations.TLS.PrivateKey = ""
    Operations.TLS.Certificate = ""
    Operations.TLS.RootCAs = []
    Operations.TLS.ClientAuthRequired = false
    Operations.TLS.ClientRootCAs = []
    Operations.TLS.TLSHandshakeTimeShift = 0s
    Metrics.Provider = "disabled"
    Metrics.Statsd.Network = "udp"
    Metrics.Statsd.Address = "127.0.0.1:8125"
    Metrics.Statsd.WriteInterval = 30s
    Metrics.Statsd.Prefix = ""
    ChannelParticipation.Enabled = false
    ChannelParticipation.RemoveStorage = false
2020-12-30 12:38:46.295 UTC [orderer.common.server] initializeServerConfig -> INFO 004 Starting orderer with TLS enabled
2020-12-30 12:38:46.658 UTC [orderer.common.server] Main -> INFO 005 Not bootstrapping the system channel because of existing channels
2020-12-30 12:38:46.761 UTC [orderer.common.server] selectClusterBootBlock -> INFO 006 Cluster boot block is bootstrap (genesis) block; Blocks Header.Number system-channel=0, bootstrap=0
2020-12-30 12:38:46.766 UTC [orderer.common.server] Main -> INFO 007 Starting with system channel: system-channel, consensus type: etcdraft
2020-12-30 12:38:46.766 UTC [orderer.common.server] Main -> INFO 008 Setting up cluster
2020-12-30 12:38:46.766 UTC [orderer.common.server] reuseListener -> INFO 009 Cluster listener is not configured, defaulting to use the general listener on port 7050
2020-12-30 12:38:46.766 UTC [orderer.common.server] reuseListener -> INFO 00a Cluster listener is not configured, defaulting to use the general listener on port 7050
2020-12-30 12:38:46.772 UTC [orderer.common.cluster] loadVerifier -> INFO 00b Loaded verifier for channel system-channel from config block at index 0
2020-12-30 12:38:46.772 UTC [certmonitor] trackCertExpiration -> INFO 00c The enrollment certificate will expire on 2021-12-30 12:39:00 +0000 UTC
2020-12-30 12:38:46.772 UTC [certmonitor] trackCertExpiration -> INFO 00d The server TLS certificate will expire on 2021-12-30 12:39:00 +0000 UTC
2020-12-30 12:38:46.772 UTC [certmonitor] trackCertExpiration -> INFO 00e The client TLS certificate will expire on 2021-12-30 12:39:00 +0000 UTC
2020-12-30 12:38:46.782 UTC [orderer.consensus.etcdraft] detectSelfID -> WARN 00f Could not find -----BEGIN CERTIFICATE-----
MIICyjCCAnGgAwIBAgIUYfzAFhIUFlpkY0tXOAZG+dNHwL0wCgYIKoZIzj0EAwIw
XjELMAkGA1UEBhMCUEsxDzANBgNVBAgTBlB1bmphYjEPMA0GA1UEBxMGTGFob3Jl
MRQwEgYDVQQKEwtzc2gtaGhtLmNvbTEXMBUGA1UEAxMOY2Euc3NjLWhobS5jb20w
HhcNMjAxMjMwMTIzNDAwWhcNMjExMjMwMTIzOTAwWjBgMQswCQYDVQQGEwJVUzEX
MBUGA1UECBMOTm9ydGggQ2Fyb2xpbmExFDASBgNVBAoTC0h5cGVybGVkZ2VyMRAw
DgYDVQQLEwdvcmRlcmVyMRAwDgYDVQQDEwdvcmRlcmVyMFkwEwYHKoZIzj0CAQYI
KoZIzj0DAQcDQgAEGZ/xCBprojm/iSrRdNosCSvGR/3nLZ8mtqPlhkLCTZouptr0
RqYxFqMdCDQe0Sh8a0ZnwvB9cnSQiQpNQdcdBaOCAQkwggEFMA4GA1UdDwEB/wQE
AwIDqDAdBgNVHSUEFjAUBggrBgEFBQcDAQYIKwYBBQUHAwIwDAYDVR0TAQH/BAIw
ADAdBgNVHQ4EFgQUOfdnd2a46tUDkeGYyILJ3hVlXlgwHwYDVR0jBBgwFoAUeDHp
ud9ZRsgehfOLprCK/Wpw0H8wKQYDVR0RBCIwIIITb3JkZXJlci5zc2MtaGhtLmNv
bYIJbG9jYWxob3N0MFsGCCoDBAUGBwgBBE97ImF0dHJzIjp7ImhmLkFmZmlsaWF0
aW9uIjoiIiwiaGYuRW5yb2xsbWVudElEIjoib3JkZXJlciIsImhmLlR5cGUiOiJv
cmRlcmVyIn19MAoGCCqGSM49BAMCA0cAMEQCID1dC/QtexQQDHyUcWh7b9Adti4l
P6XVl9P1V0PtByhAAiBh6UoaAmved5zr9rDvKbVPpte6N+2ANrbft9wV7UrAbw==
-----END CERTIFICATE-----
 among [-----BEGIN CERTIFICATE-----
MIICZDCCAgugAwIBAgIRAKjhbRj45MuremeCXWn8wzIwCgYIKoZIzj0EAwIwbDEL
MAkGA1UEBhMCVVMxEzARBgNVBAgTCkNhbGlmb3JuaWExFjAUBgNVBAcTDVNhbiBG
cmFuY2lzY28xFDASBgNVBAoTC3NzYy1oaG0uY29tMRowGAYDVQQDExF0bHNjYS5z
c2MtaGhtLmNvbTAeFw0yMDEyMjkxMDM2MDBaFw0zMDEyMjcxMDM2MDBaMFgxCzAJ
BgNVBAYTAlVTMRMwEQYDVQQIEwpDYWxpZm9ybmlhMRYwFAYDVQQHEw1TYW4gRnJh
bmNpc2NvMRwwGgYDVQQDExNvcmRlcmVyLnNzYy1oaG0uY29tMFkwEwYHKoZIzj0C
AQYIKoZIzj0DAQcDQgAEL/gYIN8w69hi/abMkdDmCBpJEhokhcPcx1mmICf8+9Aa
dSwfRpCbN4GQ71mOUwfh6U5PglXwMkJrXmn/TczaQKOBoTCBnjAOBgNVHQ8BAf8E
BAMCBaAwHQYDVR0lBBYwFAYIKwYBBQUHAwEGCCsGAQUFBwMCMAwGA1UdEwEB/wQC
MAAwKwYDVR0jBCQwIoAgVk5hX37poZ0h4MjMfqtYZte2PEoJs6DwR0lhPOXMBVsw
MgYDVR0RBCswKYITb3JkZXJlci5zc2MtaGhtLmNvbYIHb3JkZXJlcoIJbG9jYWxo
b3N0MAoGCCqGSM49BAMCA0cAMEQCIFGU5BMMpcmkIG1tmA3rwsm2h0Yn6bOT/GU9
oLxTg57iAiB9TaK9uBaYSF0GkpH+fvmhiQ0egSxRcwaXWi99C/V1rA==
-----END CERTIFICATE-----
]
2020-12-30 12:38:46.782 UTC [orderer.common.onboarding] TrackChain -> INFO 010 Adding system-channel to the set of chains to track
2020-12-30 12:38:46.782 UTC [orderer.commmon.multichannel] Initialize -> INFO 011 Starting system channel 'system-channel' with genesis block hash 8d267aa91012044d668ed2f377d485df675b181a5a02d10addf05ec9ef1c77fc and orderer type etcdraft
2020-12-30 12:38:46.783 UTC [orderer.common.server] Main -> INFO 012 Starting orderer:
 Version: 2.2.1
 Commit SHA: 344fda6
 Go version: go1.14.4
 OS/Arch: linux/amd64
2020-12-30 12:38:46.783 UTC [orderer.common.server] Main -> INFO 013 Beginning to serve requests
2020-12-30 12:38:56.775 UTC [orderer.common.onboarding] replicateDisabledChains -> INFO 014 Found 1 inactive chains: [system-channel]
2020-12-30 12:38:56.776 UTC [orderer.common.cluster] ReplicateChains -> INFO 015 Will now replicate chains [system-channel]
2020-12-30 12:38:56.786 UTC [orderer.common.cluster] discoverChannels -> INFO 016 Discovered 1 channels: [system-channel]
2020-12-30 12:38:56.786 UTC [orderer.common.cluster] channelsToPull -> INFO 017 Evaluating channels to pull: [system-channel]
2020-12-30 12:38:56.786 UTC [orderer.common.cluster] channelsToPull -> INFO 018 Probing whether I should pull channel system-channel
2020-12-30 12:38:56.790 UTC [core.comm] ServerHandshake -> ERRO 019 TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59898
2020-12-30 12:38:57.793 UTC [core.comm] ServerHandshake -> ERRO 01a TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59900
2020-12-30 12:38:59.432 UTC [core.comm] ServerHandshake -> ERRO 01b TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59902
2020-12-30 12:39:01.881 UTC [core.comm] ServerHandshake -> ERRO 01c TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59904
2020-12-30 12:39:03.787 UTC [orderer.common.cluster.replication] probeEndpoint -> WARN 01d Failed connecting to {"CAs":[{"Expired":false,"Issuer":"self","Subject":"CN=tlsca.ssc-hhm.com,O=ssc-hhm.com,L=San Francisco,ST=California,C=US"}],"Endpoint":"orderer.ssc-hhm.com:7050"}: failed to create new connection: context deadline exceeded channel=system-channel
2020-12-30 12:39:03.788 UTC [orderer.common.cluster.replication] func1 -> WARN 01e Received error of type 'failed to create new connection: context deadline exceeded' from {"CAs":[{"Expired":false,"Issuer":"self","Subject":"CN=tlsca.ssc-hhm.com,O=ssc-hhm.com,L=San Francisco,ST=California,C=US"}],"Endpoint":"orderer.ssc-hhm.com:7050"} channel=system-channel
2020-12-30 12:39:03.788 UTC [orderer.common.cluster.replication] HeightsByEndpoints -> INFO 01f Returning the heights of OSNs mapped by endpoints map[] channel=system-channel
2020-12-30 12:39:03.788 UTC [orderer.common.cluster] channelsToPull -> WARN 020 Could not obtain blocks needed for classifying whether I am in the channel,skipping the retrieval of the chan system-channel
2020-12-30 12:39:03.788 UTC [orderer.common.cluster] ReplicateChains -> INFO 021 Found myself in 0 channels out of 1 : {[] [{system-channel 0xc0006e7580}]}
2020-12-30 12:39:03.788 UTC [orderer.common.cluster] appendBlock -> INFO 022 Skipping commit of block [0] for channel system-channel because height is at 1
2020-12-30 12:39:03.788 UTC [orderer.common.cluster] PullChannel -> INFO 023 Pulling channel system-channel
2020-12-30 12:39:03.793 UTC [core.comm] ServerHandshake -> ERRO 024 TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59906
2020-12-30 12:39:04.797 UTC [core.comm] ServerHandshake -> ERRO 025 TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59908
2020-12-30 12:39:06.430 UTC [core.comm] ServerHandshake -> ERRO 026 TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59910
2020-12-30 12:39:08.952 UTC [core.comm] ServerHandshake -> ERRO 027 TLS handshake failed with error remote error: tls: bad certificate server=Orderer remoteaddress=172.21.0.8:59912
2020-12-30 12:39:10.790 UTC [orderer.common.cluster.replication] probeEndpoint -> WARN 028 Failed connecting to {"CAs":[{"Expired":false,"Issuer":"self","Subject":"CN=tlsca.ssc-hhm.com,O=ssc-hhm.com,L=San Francisco,ST=California,C=US"}],"Endpoint":"orderer.ssc-hhm.com:7050"}: failed to create new connection: context deadline exceeded channel=system-channel
2020-12-30 12:39:10.790 UTC [orderer.common.cluster.replication] func1 -> WARN 029 Received error of type 'failed to create new connection: context deadline exceeded' from {"CAs":[{"Expired":false,"Issuer":"self","Subject":"CN=tlsca.ssc-hhm.com,O=ssc-hhm.com,L=San Francisco,ST=California,C=US"}],"Endpoint":"orderer.ssc-hhm.com:7050"} channel=system-channel
2020-12-30 12:39:10.790 UTC [orderer.common.cluster.replication] HeightsByEndpoints -> INFO 02a Returning the heights of OSNs mapped by endpoints map[] channel=system-channel
2020-12-30 12:39:10.790 UTC [orderer.common.cluster] ReplicateChains -> PANI 02b Failed pulling system channel: failed obtaining the latest block for channel system-channel
panic: Failed pulling system channel: failed obtaining the latest block for channel system-channel

goroutine 28 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc000151340, 0x0, 0x0, 0x0)
    /go/src/github.com/hyperledger/fabric/vendor/go.uber.org/zap/zapcore/entry.go:230 +0x545
go.uber.org/zap.(*SugaredLogger).log(0xc000209240, 0xc00044b304, 0x101fc6d, 0x21, 0xc0000f9c40, 0x1, 0x1, 0x0, 0x0, 0x0)
    /go/src/github.com/hyperledger/fabric/vendor/go.uber.org/zap/sugar.go:234 +0x100
go.uber.org/zap.(*SugaredLogger).Panicf(...)
    /go/src/github.com/hyperledger/fabric/vendor/go.uber.org/zap/sugar.go:159
github.com/hyperledger/fabric/common/flogging.(*FabricLogger).Panicf(...)
    /go/src/github.com/hyperledger/fabric/common/flogging/zap.go:74
github.com/hyperledger/fabric/orderer/common/cluster.(*Replicator).ReplicateChains(0xc0003dfe00, 0xc00054e340, 0xc0002c0200, 0xc0003dfe00)
    /go/src/github.com/hyperledger/fabric/orderer/common/cluster/replication.go:166 +0x49d
github.com/hyperledger/fabric/orderer/common/onboarding.(*ReplicationInitiator).ReplicateChains(0xc00027e400, 0xc00054e340, 0xc0002c0000, 0x1, 0x1, 0x0, 0x0, 0x0)
    /go/src/github.com/hyperledger/fabric/orderer/common/onboarding/onboarding.go:185 +0x1e3
github.com/hyperledger/fabric/orderer/common/onboarding.(*InactiveChainReplicator).replicateDisabledChains(0xc000207920)
    /go/src/github.com/hyperledger/fabric/orderer/common/onboarding/onboarding.go:312 +0x225
github.com/hyperledger/fabric/orderer/common/onboarding.(*InactiveChainReplicator).Run(0xc000207920)
    /go/src/github.com/hyperledger/fabric/orderer/common/onboarding/onboarding.go:290 +0x42
created by github.com/hyperledger/fabric/orderer/common/server.initializeEtcdraftConsenter
    /go/src/github.com/hyperledger/fabric/orderer/common/server/main.go:777 +0x218

I am very much new to Fabric. I am trying to make a network for SupplyChain with 3 orgs : Manufacturer, Supplier and Retailer. If anyone could guide me here, their help would be greatly appreciated.

I am using Hyperledger Fabric 2.0 on Ubuntu 18.04.

Answer 1

So I've been fighting with this issue a few days now and thought I'd share my input so far...

The previous comment to check other orderers didn't help since none of my orderers started...

In my case I'm using docker so here's what I did...

Firstly docker doesn't clear down old volumes and in my instance, an old version of the TLS cert was being picked up from a default location, used and causing an error since the cert in use wasn't among the list of registered certs.

So I was seeing something like:

detectSelfID -> Could not find -----BEGIN CERTIFICATE-----
....
-----END CERTIFICATE----- among [
cert1, 
cert2,
...
]

When I checked the certs the cert being used didn't look like it was correct since the valid-from time was a week out of date and the subject alternative names I was playing with weren't being picked up correctly.

I therefore deleted all containers

docker rm -f $(docker ps -aq)

I then deleted all docker volumes

docker volume rm -f $(docker volume ls -q)

Note: docker prune system -f doesn't remove volumes. Even if you include the --volumes flag it won't necessarily remove everything for a clean restart of the docker network

This didn't resolve my issue entirely since when I checked the certificate values using:

openssl x509 -in your-cert.pem -text

The output was showing a certificate that was generated a week ago (valid-from date was not today's date). Turns out the file being picked up by my container was from a default location. That default location was on the root of my machine where I rarely look hence I missed this initially. Once I cleared that out, the correct file that was already mounted to the container was utilised and the problem resolved.

The problem is essentially a bad/invalid certificate.

Answer 2

The prob comes from a bad TLS certificate used by the new ordered. Check the log of other ordereres and you would get some hints about this.

Answer 3

With help of @myeongkil kim I was able to solve this issue. The solution was I just had to remove all the docker volumes by docker volume prune and after this, bringing the network back up solves this problem.