will-hu-0 / fabric-sample-with-kafka

Fabric sample with kafka orderer type
Apache License 2.0
54 stars 44 forks source link

./byfn.sh up throws error #1

Open anirudhkabi opened 6 years ago

anirudhkabi commented 6 years ago

Error: Got unexpected status: SERVICE_UNAVAILABLE Even after increasing CLI_TIMEOUT and CLI_DELAY to 100, the error occurs

will-hu-0 commented 6 years ago

Hey @anirudhkabi, thanks for raising the issue for it. My assumption is that: (1) Not sure what's your OS? From my end it runs well under Ubuntu (16.04) and Travis CI (Ubuntu as well). (2) Check your local port is being used, check 9092 and 2181 by

netstat -nlp|grep 2181 
sudo lsof -i:9092

Kill or close them if they are being used.

If all the steps above is okay, check the following debug steps (manually).

I will provide some steps to try to understand your local issue, hopefully you may follow it to provide valuable information. Because we will debug it by manual script, so...

  1. Mark the code in byfn.sh by
    
    function networkUp () {
    ......

sleep 12

docker exec cli scripts/script.sh $CHANNEL_NAME $CLI_DELAY $LANGUAGE $CLI_TIMEOUT

....


2.1 Run the following script in one new console (console1):

./byfn.sh up

You will see something in the end like:

Creating orderer.example.com ... Creating orderer.example.com ... done Creating cli ... Creating cli ... done

Make sure you see orderer.example.com is done.

2.2 Open another console (console2) to run and see the log from orderer (If you have another tool like kitematic, you do not necessarily run by yourself)

docker logs -f orderer.example.com


**BE NOTED**: step2.1 and 2.2 should be running in **parallel** because you need to verify the kafka self-checking log during the starting up of orderer service:

... [sarama] 2018/03/04 05:54:48.198800 broker.go:146: Connected to broker at kafka2.example.com:9092 (unregistered) [sarama] 2018/03/04 05:54:48.200471 client.go:397: client/brokers registered new broker #0 at 85ad5b5c61e9:9092 [sarama] 2018/03/04 05:54:48.200486 client.go:397: client/brokers registered new broker #1 at 66abc42c12b7:9092 [sarama] 2018/03/04 05:54:48.200493 client.go:397: client/brokers registered new broker #2 at 45f18a960094:9092 [sarama] 2018/03/04 05:54:48.200500 client.go:397: client/brokers registered new broker #3 at 41b8aba2be14:9092 ... 2018-03-04 05:54:48.214 UTC [orderer/kafka] processMessagesToBlocks -> DEBU 108 [channel: testchainid] Successfully unmarshalled consumed message, offset is 0. Inspecting type... 2018-03-04 05:54:48.214 UTC [orderer/kafka] processConnect -> DEBU 109 [channel: testchainid] It's a connect message - ignoring

3. If all the steps above runs well, let's manually create the channel in the CLI :)
Open a third console (console3) to run

docker exec -it cli bash

Execute:

export CHANNEL_NAME=mychannel peer channel create -o orderer.example.com:7050 -c $CHANNEL_NAME -f ./channel-artifacts/channel.tx --tls --cafile /opt/gopath/src/github.com/hyperledger/fabric/peer/crypto/ordererOrganizations/example.com/orderers/orderer.example.com/msp/tlscacerts/tlsca.example.com-cert.pem


To see if it is successful? 
If not running well, please copy more log from orderer (console2) here let me check it.
If it runs well, I don't know, you might need to trigger the cli by some other way, we may discuss it later after your test result on your local. Thanks.
anirudhkabi commented 6 years ago
2018-03-05 10:38:08.309 UTC [orderer/kafka] try -> DEBU 0f6 [channel: testchainid] Connecting to the Kafka cluster [sarama] 
2018/03/05 10:38:08.309443 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.309537 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.309562 client.go:601: client/metadata fetching metadata for all topics from broker kafka1.example.com:9092 [sarama] 
2018/03/05 10:38:08.314199 broker.go:96: Failed to connect to broker kafka1.example.com:9092: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.314252 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.314269 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.314298 client.go:601: client/metadata fetching metadata for all topics from broker kafka0.example.com:9092 [sarama] 
2018/03/05 10:38:08.315215 broker.go:96: Failed to connect to broker kafka0.example.com:9092: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.315257 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.315273 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.315299 client.go:601: client/metadata fetching metadata for all topics from broker kafka2.example.com:9092 [sarama] 
2018/03/05 10:38:08.316713 broker.go:96: Failed to connect to broker kafka2.example.com:9092: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.316752 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.316768 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.316793 client.go:601: client/metadata fetching metadata for all topics from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:08.318071 broker.go:96: Failed to connect to broker kafka3.example.com:9092: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.318103 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.318116 client.go:626: client/metadata no available broker to send metadata request to [sarama] 
2018/03/05 10:38:08.318127 client.go:428: client/brokers resurrecting 4 dead seed brokers [sarama] 
2018/03/05 10:38:08.318139 client.go:590: client/metadata retrying after 250ms... (3 attempts remaining) [sarama] 
2018/03/05 10:38:08.568380 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.568483 client.go:601: client/metadata fetching metadata for all topics from broker kafka1.example.com:9092 [sarama] 
2018/03/05 10:38:08.570440 broker.go:96: Failed to connect to broker kafka1.example.com:9092: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.570567 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.570583 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.570625 client.go:601: client/metadata fetching metadata for all topics from broker kafka0.example.com:9092 [sarama] 
2018/03/05 10:38:08.571908 broker.go:96: Failed to connect to broker kafka0.example.com:9092: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.572014 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.572032 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.572073 client.go:601: client/metadata fetching metadata for all topics from broker kafka2.example.com:9092 [sarama] 
2018/03/05 10:38:08.573380 broker.go:96: Failed to connect to broker kafka2.example.com:9092: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.574321 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.574339 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.574427 client.go:601: client/metadata fetching metadata for all topics from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:08.576145 broker.go:96: Failed to connect to broker kafka3.example.com:9092: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.576205 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.576219 client.go:626: client/metadata no available broker to send metadata request to [sarama] 
2018/03/05 10:38:08.576277 client.go:428: client/brokers resurrecting 4 dead seed brokers [sarama] 
2018/03/05 10:38:08.576291 client.go:590: client/metadata retrying after 250ms... (2 attempts remaining) [sarama] 
2018/03/05 10:38:08.826636 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.826767 client.go:601: client/metadata fetching metadata for all topics from broker kafka1.example.com:9092 [sarama] 
2018/03/05 10:38:08.833000 broker.go:96: Failed to connect to broker kafka1.example.com:9092: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.833066 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.833110 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.833139 client.go:601: client/metadata fetching metadata for all topics from broker kafka0.example.com:9092 [sarama] 
2018/03/05 10:38:08.846567 broker.go:96: Failed to connect to broker kafka0.example.com:9092: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.846655 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.846671 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.846744 client.go:601: client/metadata fetching metadata for all topics from broker kafka2.example.com:9092 [sarama] 
2018/03/05 10:38:08.871004 broker.go:96: Failed to connect to broker kafka2.example.com:9092: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.871053 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.871069 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:08.871094 client.go:601: client/metadata fetching metadata for all topics from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:08.883073 broker.go:96: Failed to connect to broker kafka3.example.com:9092: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.883127 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:08.883141 client.go:626: client/metadata no available broker to send metadata request to [sarama] 
2018/03/05 10:38:08.883152 client.go:428: client/brokers resurrecting 4 dead seed brokers [sarama] 
2018/03/05 10:38:08.883165 client.go:590: client/metadata retrying after 250ms... (1 attempts remaining) [sarama] 
2018/03/05 10:38:09.133359 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:09.133427 client.go:601: client/metadata fetching metadata for all topics from broker kafka1.example.com:9092 [sarama] 
2018/03/05 10:38:09.134798 broker.go:96: Failed to connect to broker kafka1.example.com:9092: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.134833 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.12:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.134849 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:09.134872 client.go:601: client/metadata fetching metadata for all topics from broker kafka0.example.com:9092 [sarama] 
2018/03/05 10:38:09.147221 broker.go:96: Failed to connect to broker kafka0.example.com:9092: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.147282 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.10:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.147298 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:09.147321 client.go:601: client/metadata fetching metadata for all topics from broker kafka2.example.com:9092 [sarama] 
2018/03/05 10:38:09.154653 broker.go:96: Failed to connect to broker kafka2.example.com:9092: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.154702 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.11:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.154720 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:09.154768 client.go:601: client/metadata fetching metadata for all topics from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:09.178679 broker.go:96: Failed to connect to broker kafka3.example.com:9092: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.178775 client.go:620: client/metadata got error from broker while fetching metadata: dial tcp 172.20.0.9:9092: getsockopt: connection refused [sarama] 
2018/03/05 10:38:09.178793 client.go:626: client/metadata no available broker to send metadata request to [sarama] 
2018/03/05 10:38:09.178805 client.go:428: client/brokers resurrecting 4 dead seed brokers [sarama] 
2018/03/05 10:38:09.178821 client.go:187: Closing Client
2018/03/05 10:38:09.178 UTC [orderer/kafka] try -> DEBU 0f7 [channel: testchainid] Retrying every 1s for a total of 30s
2018/03/05 10:38:10.179 UTC [orderer/kafka] try -> DEBU 0f8 [channel: testchainid] Connecting to the Kafka cluster [sarama] 
2018/03/05 10:38:10.179240 client.go:110: Initializing new client [sarama] 
2018/03/05 10:38:10.179257 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:10.179391 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:10.179415 client.go:601: client/metadata fetching metadata for all topics from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:10.187163 broker.go:146: Connected to broker at kafka3.example.com:9092 (unregistered) [sarama] 
2018/03/05 10:38:10.532725 client.go:154: Successfully initialized new client
2018/03/05 10:38:10.533 UTC [orderer/kafka] try -> DEBU 0f9 [channel: testchainid] Error is nil, breaking the retry loop
2018/03/05 10:38:10.538 UTC [orderer/kafka] startThread -> INFO 0fa [channel: testchainid] Producer set up successfully
2018/03/05 10:38:10.542 UTC [orderer/kafka] sendConnectMessage -> INFO 0fb [channel: testchainid] About to post the CONNECT message...
2018/03/05 10:38:10.542 UTC [orderer/kafka] try -> DEBU 0fc [channel: testchainid] Attempting to post the CONNECT message... [sarama] 
2018/03/05 10:38:10.543030 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:11.100633 client.go:610: client/metadata found some partitions to be leaderless [sarama] 
2018/03/05 10:38:11.100805 client.go:590: client/metadata retrying after 250ms... (3 attempts remaining) [sarama] 
2018/03/05 10:38:11.351050 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:11.369408 client.go:610: client/metadata found some partitions to be leaderless [sarama] 
2018/03/05 10:38:11.375028 client.go:590: client/metadata retrying after 250ms... (2 attempts remaining) [sarama] 
2018/03/05 10:38:11.625323 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:11.661422 client.go:397: client/brokers registered new broker #0 at 8990d75b04fa:9092 [sarama] 
2018/03/05 10:38:11.661805 client.go:397: client/brokers registered new broker #1 at 54aa5a50fc15:9092 [sarama] 
2018/03/05 10:38:11.661955 client.go:397: client/brokers registered new broker #2 at c5af850cb064:9092 [sarama] 
2018/03/05 10:38:11.662103 client.go:397: client/brokers registered new broker #3 at a201c9533fff:9092 [sarama] 
2018/03/05 10:38:11.662266 client.go:610: client/metadata found some partitions to be leaderless [sarama] 
2018/03/05 10:38:11.662417 client.go:590: client/metadata retrying after 250ms... (1 attempts remaining) [sarama] 
2018/03/05 10:38:11.912843 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:11.929541 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:11.934371 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:38:11.934897 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:38:21.934927 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:38:21.934980 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:38:21.935036 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-1] [sarama] 
2018/03/05 10:38:21.935049 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:38:21.935108 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:38:22.035196 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:22.037657 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:22.038166 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:38:22.038189 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:38:22.038232 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:38:22.038256 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-1] [sarama] 
2018/03/05 10:38:22.038266 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:38:32.037951 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:38:32.038035 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:38:32.038074 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-2] [sarama] 
2018/03/05 10:38:32.038086 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:38:32.038170 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:38:32.138460 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:32.142361 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:32.142821 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:38:32.143086 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:38:32.143246 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:38:32.143857 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-2] [sarama] 
2018/03/05 10:38:32.144116 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:38:42.142937 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:38:42.142990 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:38:42.143069 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-3] [sarama] 
2018/03/05 10:38:42.143143 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:38:42.143201 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:38:42.243345 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:42.245854 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:42.246896 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:38:42.247145 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:38:42.247310 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:38:42.247472 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-3] [sarama] 
2018/03/05 10:38:42.247609 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:38:52.246252 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:38:52.246351 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout
2018/03/05 10:38:52.246 UTC [orderer/kafka] try -> DEBU 0fd [channel: testchainid] Retrying every 1s for a total of 30s
2018/03/05 10:38:53.246 UTC [orderer/kafka] try -> DEBU 0fe [channel: testchainid] Attempting to post the CONNECT message... [sarama] 
2018/03/05 10:38:53.246687 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-1] [sarama] 
2018/03/05 10:38:53.246704 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:38:53.246730 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:38:53.346893 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:53.350037 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:53.350798 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:38:53.350928 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:38:53.350983 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:38:53.351175 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-1] [sarama] 
2018/03/05 10:38:53.351241 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:39:03.350868 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:03.350936 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:03.351021 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-2] [sarama] 
2018/03/05 10:39:03.351052 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:39:03.351084 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:39:03.451204 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:39:03.453951 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:39:03.454319 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:39:03.454333 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:39:03.454354 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:39:03.454368 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-2] [sarama] 
2018/03/05 10:39:03.454377 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:39:13.454186 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:13.454248 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:13.454300 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-3] [sarama] 
2018/03/05 10:39:13.454314 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:39:13.454342 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:39:13.554487 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:39:13.556593 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:39:13.556675 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:39:13.556697 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:39:13.556713 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:39:13.556751 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-3] [sarama] 
2018/03/05 10:39:13.556761 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:39:23.556888 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout
2018/03/05 10:39:23.556 UTC [orderer/kafka] try -> DEBU 0ff [channel: testchainid] Attempting to post the CONNECT message... [sarama] 
2018/03/05 10:39:23.556943 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:23.557131 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-1] [sarama] 
2018/03/05 10:39:23.557178 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:39:23.557228 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:39:23.657405 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:39:23.659916 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:39:23.660375 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:39:23.660416 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:39:23.660442 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:39:23.660457 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-1] [sarama] 
2018/03/05 10:39:23.660467 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:39:33.660446 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:33.660505 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:33.660557 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-2] [sarama] 
2018/03/05 10:39:33.660570 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:39:33.660591 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:39:33.760751 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:39:33.763114 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:39:33.764518 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:39:33.764774 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:39:33.764984 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:39:33.765122 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-2] [sarama] 
2018/03/05 10:39:33.765248 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:39:43.763768 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:43.763824 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:43.763862 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-3] [sarama] 
2018/03/05 10:39:43.763877 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:39:43.763919 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:39:43.864064 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:39:43.866328 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:39:43.866809 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:39:43.867612 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:39:43.867758 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:39:43.867872 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-3] [sarama] 
2018/03/05 10:39:43.867976 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:39:53.866588 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:39:53.866658 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout
2018/03/05 10:39:53.866 UTC [orderer/kafka] retry -> DEBU 100 [channel: testchainid] Switching to the long retry interval
2018/03/05 10:39:53.866 UTC [orderer/kafka] try -> DEBU 101 [channel: testchainid] Attempting to post the CONNECT message... [sarama] 
2018/03/05 10:39:53.866866 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-1] [sarama] 
2018/03/05 10:39:53.866884 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:39:53.866913 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:39:53.967075 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:39:53.969776 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:39:53.969935 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:39:53.969962 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:39:53.969982 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:39:53.969995 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-1] [sarama] 
2018/03/05 10:39:53.970005 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:40:03.970046 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:40:03.970240 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:40:03.970345 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-2] [sarama] 
2018/03/05 10:40:03.970364 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:40:03.970386 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:40:04.070531 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:40:04.073103 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:40:04.073599 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:40:04.073629 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:40:04.073647 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:40:04.073902 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-2] [sarama] 
2018/03/05 10:40:04.073913 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:40:14.073489 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:40:14.073546 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 
2018/03/05 10:40:14.073784 async_producer.go:458: producer/leader/testchainid/0 state change to [retrying-3] [sarama] 
2018/03/05 10:40:14.073905 async_producer.go:468: producer/leader/testchainid/0 abandoning broker 1 [sarama] 
2018/03/05 10:40:14.074050 async_producer.go:663: producer/broker/1 shut down [sarama] 
2018/03/05 10:40:14.174239 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:40:14.177434 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:40:14.178324 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:40:14.178353 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
2018/03/05 10:40:14.178377 async_producer.go:446: producer/leader/testchainid/0 selected broker 1 [sarama] 
2018/03/05 10:40:14.178391 async_producer.go:474: producer/leader/testchainid/0 state change to [flushing-3] [sarama] 
2018/03/05 10:40:14.178401 async_producer.go:496: producer/leader/testchainid/0 state change to [normal] [sarama] 
2018/03/05 10:40:24.177739 broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
2018/03/05 10:40:24.177805 async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout
2018/03/05 10:40:24.177 UTC [orderer/kafka] try -> DEBU 102 [channel: testchainid] Retrying every 5m0s for a total of 12h0m0s
anirudhkabi commented 6 years ago

Thanks for your reply and sorry for such a huge log of orderer. What I can understand from the logs is that after lot of retries, the orderer is able to connect to kafka3 and fails to connect to other kafka containers. I am new to using kafka, cant interpret much when it says "not able to elect a leader".

anirudhkabi commented 6 years ago

021A0608AFC3F4D40522...C54F02703B9E94E190618E2F212DC4A3 2018-03-05 10:53:35.920 UTC [msp/identity] Sign -> DEBU 009 Sign: digest: E45E8B3D4854364686069A8E4B25739524EC56E6DB499CB4F03F3C759175B413 2018-03-05 10:53:35.921 UTC [msp] GetLocalMSP -> DEBU 00a Returning existing local MSP 2018-03-05 10:53:35.921 UTC [msp] GetDefaultSigningIdentity -> DEBU 00b Obtaining default signing identity 2018-03-05 10:53:35.921 UTC [msp] GetLocalMSP -> DEBU 00c Returning existing local MSP 2018-03-05 10:53:35.921 UTC [msp] GetDefaultSigningIdentity -> DEBU 00d Obtaining default signing identity 2018-03-05 10:53:35.921 UTC [msp/identity] Sign -> DEBU 00e Sign: plaintext: 0A8C060A074F7267314D53501280062D...53616D706C65436F6E736F727469756D 2018-03-05 10:53:35.921 UTC [msp/identity] Sign -> DEBU 00f Sign: digest: E72D0E68A132F6E2538D037AE5462E628F898076E22ABB01E45B5CE1A3CEABA3 2018-03-05 10:53:35.921 UTC [msp] GetLocalMSP -> DEBU 010 Returning existing local MSP 2018-03-05 10:53:35.921 UTC [msp] GetDefaultSigningIdentity -> DEBU 011 Obtaining default signing identity 2018-03-05 10:53:35.921 UTC [msp] GetLocalMSP -> DEBU 012 Returning existing local MSP 2018-03-05 10:53:35.921 UTC [msp] GetDefaultSigningIdentity -> DEBU 013 Obtaining default signing identity 2018-03-05 10:53:35.921 UTC [msp/identity] Sign -> DEBU 014 Sign: plaintext: 0ABC060A0E08021A0608AFC3F4D40522...9A7AD73B6066BB3D7954691126FE4B6B 2018-03-05 10:53:35.921 UTC [msp/identity] Sign -> DEBU 015 Sign: digest: 0B2DE62DE33C12378F30B5236B1B599AB0114F2142F1AB80FC53E0DE399127A9 Error: Got unexpected status: BAD_REQUEST Usage: peer channel create [flags]

This is the logs for create channel

will-hu-0 commented 6 years ago

I compared my local log with yours, same with my local like

2018/03/05 10:38:11.661422 client.go:397: client/brokers registered new broker #0 at 8990d75b04fa:9092 [sarama] 
2018/03/05 10:38:11.661805 client.go:397: client/brokers registered new broker #1 at 54aa5a50fc15:9092 [sarama] 
2018/03/05 10:38:11.661955 client.go:397: client/brokers registered new broker #2 at c5af850cb064:9092 [sarama] 
2018/03/05 10:38:11.662103 client.go:397: client/brokers registered new broker #3 at a201c9533fff:9092 [sarama] 
2018/03/05 10:38:11.662266 client.go:610: client/metadata found some partitions to be leaderless [sarama] 
2018/03/05 10:38:11.662417 client.go:590: client/metadata retrying after 250ms... (1 attempts remaining) [sarama] 
2018/03/05 10:38:11.912843 client.go:599: client/metadata fetching metadata for [testchainid] from broker kafka3.example.com:9092 [sarama] 
2018/03/05 10:38:11.929541 config.go:329: ClientID is the default of 'sarama', you should consider setting it to something application-specific. [sarama] 
2018/03/05 10:38:11.934371 async_producer.go:584: producer/broker/1 starting up [sarama] 
2018/03/05 10:38:11.934897 async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 

Until the difference here:

async_producer.go:584: producer/broker/1 starting up [sarama] 
async_producer.go:596: producer/broker/1 state change to [open] on testchainid/0 [sarama] 
broker.go:96: Failed to connect to broker 54aa5a50fc15:9092: dial tcp: i/o timeout [sarama] 
async_producer.go:762: producer/broker/1 state change to [closing] because dial tcp: i/o timeout [sarama] 

you got the timeout stuff. Frankly I don't know..I just searched out from online see someone got the same exception as yours: https://github.com/Shopify/sarama/issues/834