Rejecting broadcast of message from 172.20.0.1:51068 with SERVICE_UNAVAILABLE: about caliper HOT 11 CLOSED

2018-06-15 20:35:40.005 CST [orderer/common/broadcast] Handle -> WARN 009 [channel: mychannel] Rejecting broadcast of message from 172.20.0.1:51068 with SERVICE_UNAVAILABLE: rejected by Consenter: will not enqueue, consenter for this channel hasn't started yet

from caliper.

@pyraman can you try this solution：
1、add depend_on in yaml , such as zookeeper is depend by kafka , kafka is depend by orderer ,orderer is depend by peer
2、start fabric network by command ： docker-compose docker-compose.yaml up ....
3、delete start command in config.json ( about start network)
4、wait some seconds , more than 20s, then exec node command

from caliper.

guolidong:/opt/gopath/src/github.com/hyperledger/caliper$ docker logs zookeeper0
ZooKeeper JMX enabled by default
Using config: /conf/zoo.cfg
2018-06-15 13:37:43,415 [myid:] - INFO [main:QuorumPeerConfig@124] - Reading configuration from: /conf/zoo.cfg
2018-06-15 13:37:43,518 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - Resolved hostname: zookeeper2 to address: zookeeper2/172.20.0.5
2018-06-15 13:37:43,522 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - Resolved hostname: zookeeper1 to address: zookeeper1/172.20.0.6
2018-06-15 13:37:43,523 [myid:] - INFO [main:QuorumPeer$QuorumServer@149] - Resolved hostname: zookeeper0 to address: zookeeper0/172.20.0.4
2018-06-15 13:37:43,524 [myid:] - INFO [main:QuorumPeerConfig@352] - Defaulting to majority quorums
2018-06-15 13:37:43,534 [myid:1] - INFO [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3
2018-06-15 13:37:43,534 [myid:1] - INFO [main:DatadirCleanupManager@79] - autopurge.purgeInterval set to 1
2018-06-15 13:37:43,548 [myid:1] - INFO [PurgeTask:DatadirCleanupManager$PurgeTask@138] - Purge task started.
2018-06-15 13:37:43,577 [myid:1] - INFO [main:QuorumPeerMain@127] - Starting quorum peer
2018-06-15 13:37:43,586 [myid:1] - INFO [PurgeTask:DatadirCleanupManager$PurgeTask@144] - Purge task completed.
2018-06-15 13:37:43,651 [myid:1] - INFO [main:NIOServerCnxnFactory@89] - binding to port 0.0.0.0/0.0.0.0:2181
2018-06-15 13:37:43,661 [myid:1] - INFO [main:QuorumPeer@1019] - tickTime set to 2000
2018-06-15 13:37:43,661 [myid:1] - INFO [main:QuorumPeer@1039] - minSessionTimeout set to -1
2018-06-15 13:37:43,662 [myid:1] - INFO [main:QuorumPeer@1050] - maxSessionTimeout set to -1
2018-06-15 13:37:43,662 [myid:1] - INFO [main:QuorumPeer@1065] - initLimit set to 5
2018-06-15 13:37:43,691 [myid:1] - INFO [main:QuorumPeer@533] - currentEpoch not found! Creating with a reasonable default of 0. This should only happen when you are upgrading your installation
2018-06-15 13:37:43,702 [myid:1] - INFO [main:QuorumPeer@548] - acceptedEpoch not found! Creating with a reasonable default of 0. This should only happen when you are upgrading your installation
2018-06-15 13:37:43,713 [myid:1] - INFO [ListenerThread:QuorumCnxManager$Listener@534] - My election bind port: zookeeper0/172.20.0.4:3888
2018-06-15 13:37:43,735 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:QuorumPeer@774] - LOOKING
2018-06-15 13:37:43,742 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:FastLeaderElection@818] - New election. My id = 1, proposed zxid=0x0
2018-06-15 13:37:43,743 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message format version), 1 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
2018-06-15 13:37:43,764 [myid:1] - WARN [WorkerSender[myid=1]:QuorumCnxManager@400] - Cannot open channel to 2 at election address zookeeper1/172.20.0.6:3888
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433)
at java.lang.Thread.run(Thread.java:748)
2018-06-15 13:37:43,771 [myid:1] - INFO [WorkerSender[myid=1]:QuorumPeer$QuorumServer@149] - Resolved hostname: zookeeper1 to address: zookeeper1/172.20.0.6
2018-06-15 13:37:43,772 [myid:1] - WARN [WorkerSender[myid=1]:QuorumCnxManager@400] - Cannot open channel to 3 at election address zookeeper2/172.20.0.5:3888
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433)
at java.lang.Thread.run(Thread.java:748)
2018-06-15 13:37:43,772 [myid:1] - INFO [WorkerSender[myid=1]:QuorumPeer$QuorumServer@149] - Resolved hostname: zookeeper2 to address: zookeeper2/172.20.0.5
2018-06-15 13:37:43,860 [myid:1] - INFO [zookeeper0/172.20.0.4:3888:QuorumCnxManager$Listener@541] - Received connection request /172.20.0.5:48192
2018-06-15 13:37:43,878 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message format version), 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 3 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
2018-06-15 13:37:43,878 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message format version), 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x0 (n.peerEpoch) LOOKING (my state)
2018-06-15 13:37:43,879 [myid:1] - WARN [WorkerSender[myid=1]:QuorumCnxManager@400] - Cannot open channel to 2 at election address zookeeper1/172.20.0.6:3888
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:381)
at org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:354)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:452)
at org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:433)
at java.lang.Thread.run(Thread.java:748)
2018-06-15 13:37:43,879 [myid:1] - INFO [WorkerSender[myid=1]:QuorumPeer$QuorumServer@149] - Resolved hostname: zookeeper1 to address: zookeeper1/172.20.0.6
2018-06-15 13:37:44,080 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:QuorumPeer@844] - FOLLOWING
2018-06-15 13:37:44,083 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Learner@86] - TCP NoDelay set to: true
2018-06-15 13:37:44,104 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:zookeeper.version=3.4.9-1757313, built on 08/23/2016 06:50 GMT
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:host.name=zookeeper0
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:java.version=1.8.0_151
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:java.vendor=Oracle Corporation
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:java.class.path=/zookeeper-3.4.9/bin/../build/classes:/zookeeper-3.4.9/bin/../build/lib/.jar:/zookeeper-3.4.9/bin/../lib/slf4j-log4j12-1.6.1.jar:/zookeeper-3.4.9/bin/../lib/slf4j-api-1.6.1.jar:/zookeeper-3.4.9/bin/../lib/netty-3.10.5.Final.jar:/zookeeper-3.4.9/bin/../lib/log4j-1.2.16.jar:/zookeeper-3.4.9/bin/../lib/jline-0.9.94.jar:/zookeeper-3.4.9/bin/../zookeeper-3.4.9.jar:/zookeeper-3.4.9/bin/../src/java/lib/.jar:/conf:
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:java.io.tmpdir=/tmp
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:java.compiler=
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:os.name=Linux
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:os.arch=amd64
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:os.version=4.9.87-linuxkit-aufs
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:user.name=zookeeper
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:user.home=/home/zookeeper
2018-06-15 13:37:44,105 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Environment@100] - Server environment:user.dir=/zookeeper-3.4.9
2018-06-15 13:37:44,106 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:ZooKeeperServer@173] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /datalog/version-2 snapdir /data/version-2
2018-06-15 13:37:44,107 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Follower@61] - FOLLOWING - LEADER ELECTION TOOK - 365
2018-06-15 13:37:44,111 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:QuorumPeer$QuorumServer@149] - Resolved hostname: zookeeper2 to address: zookeeper2/172.20.0.5
2018-06-15 13:37:44,161 [myid:1] - INFO [zookeeper0/172.20.0.4:3888:QuorumCnxManager$Listener@541] - Received connection request /172.20.0.6:39628
2018-06-15 13:37:44,172 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEpoch) FOLLOWING (my state)
2018-06-15 13:37:44,173 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@600] - Notification: 1 (message format version), 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEpoch) FOLLOWING (my state)
2018-06-15 13:37:44,183 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Learner@326] - Getting a diff from the leader 0x0
2018-06-15 13:37:44,185 [myid:1] - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:FileTxnSnapLog@240] - Snapshotting: 0x0 to /data/version-2/snapshot.0
2018-06-15 13:37:47,043 [myid:1] - WARN [QuorumPeer[myid=1]/0.0.0.0:2181:Follower@116] - Got zxid 0x100000001 expected 0x1
2018-06-15 13:37:47,044 [myid:1] - INFO [SyncThread:1:FileTxnLog@203] - Creating new log file: log.100000001
2018-06-15 13:37:47,302 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@192] - Accepted socket connection from /172.20.0.9:48164
2018-06-15 13:37:47,328 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@928] - Client attempting to establish new session at /172.20.0.9:48164
2018-06-15 13:37:47,390 [myid:1] - INFO [CommitProcessor:1:ZooKeeperServer@673] - Established session 0x16403aa84f90000 with negotiated timeout 6000 for client /172.20.0.9:48164
guolidong:/opt/gopath/src/github.com/hyperledger/caliper$

from caliper.

the request port is wrong

from caliper.

Hi JulienGuo! I am facing the same issue with message: SERVICE_UNAVAILABLE consenter for this channal hasn't start yet. Please clarify your case.

from caliper.

Hi JulienGuo! I am facing the same issue with message: SERVICE_UNAVAILABLE consenter for this channal hasn't start yet. Please clarify your case.

hi , @pyraman The reason for my problem is " my request port of order is wrong" , the ports config in json config files and yaml config files .

from caliper.

hi @jiangyaoguo here is my problem:

from CLI: ./peer.sh channel create -o orderer0.trade.com:7050 -c tradechannel -f ./tradechannel.tx --cafile tlsca.trade.com-cert.pem

--> Error: got unexpected status: SERVICE_UNAVAILABLE -- will not enqueue, consenter for this channel hasn't started yet.

from Orderer:

--> 2018-10-10 09:52:52.147 ICT [orderer/common/server] Deliver -> DEBU 74a Starting new Deliver handler

2018-10-10 09:52:52.147 ICT [common/deliver] Handle -> DEBU 74b Starting new deliver loop for 192.168.171.146:49401

2018-10-10 09:52:52.148 ICT [common/deliver] Handle -> DEBU 74c Attempting to read seek info message from 192.168.171.146:49401

2018-10-10 09:52:52.149 ICT [orderer/common/server] Broadcast -> DEBU 74d Starting new Broadcast handler

2018-10-10 09:52:52.149 ICT [orderer/common/broadcast] Handle -> DEBU 74e Starting new broadcast loop for 192.168.171.146:49402

2018-10-10 09:52:52.149 ICT [orderer/common/broadcast] Handle -> WARN 74f [channel: tradechannel] Rejecting broadcast of message from 192.168.171.146:49402 with SERVICE_UNAVAILABLE: rejected by Consenter: will not enqueue, consenter for this channel hasn't started yet

2018-10-10 09:52:52.149 ICT [orderer/common/server] func1 -> DEBU 750 Closing Broadcast stream

2018-10-10 09:52:52.153 ICT [grpc] Printf -> DEBU 751 transport: http2Server.HandleStreams failed to read frame: read tcp 192.168.171.33:7050->192.168.171.146:49402: read: connection reset by peer

2018-10-10 09:52:52.153 ICT [common/deliver] Handle -> WARN 752 Error reading from 192.168.171.146:49401: rpc error: code = Canceled desc = context canceled

2018-10-10 09:52:52.154 ICT [orderer/common/server] func1 -> DEBU 753 Closing Deliver stream.

do you have any ideas for my case?

from caliper.

@JulienGuo thanks for supporting but I deploy the network manually without docker on different physical machines. 3 zookeepers, 4 brokers, 3 orderers, 4 orgs (one peer peer org).
https://jira.hyperledger.org/plugins/servlet/mobile#issue/FAB-11088/comment/52064

from caliper.

@JulienGuo Hello, why you create a fabric network with kafka and zookeeper cluster but only have one orderer node? What's the significance? And have you test the multiple orderers?

from caliper.

@pyraman Hello, have you tried the caliper with multiple orderer nodes with kafka and zookeeper cluster?

from caliper.

@cao0507 I've not try with Caliper but I found the reason that the kafka/zookeeper has been configured incorrectly.

from caliper.