You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@zookeeper.apache.org by "Adam J Shook (JIRA)" <ji...@apache.org> on 2018/02/12 17:00:00 UTC
[jira] [Commented] (ZOOKEEPER-2938) Peer with smallest id is unable
to join quorum after connection broken to other peers
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2938?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16361076#comment-16361076 ]
Adam J Shook commented on ZOOKEEPER-2938:
-----------------------------------------
We are experiencing this as well, but the node that continually drops the connection does not have the smallest {{myid}} – here it is 6 but 5 is the smallest (5, 6, 7 are the IDs). ZooKeeper 3.4.6.
{code:java}
2018-02-12 16:29:48,428 [myid:6] - INFO [Thread-1:QuorumCnxManager$Listener@504] - My election bind port: /10.122.11.104:6666
2018-02-12 16:29:48,440 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:QuorumPeer@714] - LOOKING
2018-02-12 16:29:48,443 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:FastLeaderElection@815] - New election. My id = 6, proposed zxid=0x1b00653e67
2018-02-12 16:29:48,453 [myid:6] - INFO [WorkerSender[myid=6]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (7, 6)
2018-02-12 16:29:48,453 [myid:6] - INFO [WorkerReceiver[myid=6]:FastLeaderElection@597] - Notification: 1 (message format version), 6 (n.leader), 0x1b00653e67 (n.zxid), 0x1 (n.round), LOOKING (n.state), 6 (
n.sid), 0x1b (n.peerEpoch) LOOKING (my state)
2018-02-12 16:29:48,657 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:FastLeaderElection@849] - Notification time out: 400
2018-02-12 16:29:48,657 [myid:6] - INFO [WorkerReceiver[myid=6]:FastLeaderElection@597] - Notification: 1 (message format version), 6 (n.leader), 0x1b00653e67 (n.zxid), 0x1 (n.round), LOOKING (n.state), 6 (
n.sid), 0x1b (n.peerEpoch) LOOKING (my state)
2018-02-12 16:29:48,658 [myid:6] - INFO [WorkerSender[myid=6]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (7, 6)
2018-02-12 16:29:49,058 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:FastLeaderElection@849] - Notification time out: 800
2018-02-12 16:29:49,058 [myid:6] - INFO [WorkerReceiver[myid=6]:FastLeaderElection@597] - Notification: 1 (message format version), 6 (n.leader), 0x1b00653e67 (n.zxid), 0x1 (n.round), LOOKING (n.state), 6 (
n.sid), 0x1b (n.peerEpoch) LOOKING (my state)
2018-02-12 16:29:49,859 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:FastLeaderElection@849] - Notification time out: 1600
2018-02-12 16:29:50,058 [myid:6] - INFO [WorkerSender[myid=6]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (7, 6)
2018-02-12 16:29:50,059 [myid:6] - INFO [WorkerReceiver[myid=6]:FastLeaderElection@597] - Notification: 1 (message format version), 6 (n.leader), 0x1b00653e67 (n.zxid), 0x1 (n.round), LOOKING (n.state), 6 (
n.sid), 0x1b (n.peerEpoch) LOOKING (my state)
2018-02-12 16:29:50,059 [myid:6] - INFO [WorkerSender[myid=6]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (7, 6)
2018-02-12 16:29:51,660 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:FastLeaderElection@849] - Notification time out: 3200
2018-02-12 16:29:51,660 [myid:6] - INFO [WorkerReceiver[myid=6]:FastLeaderElection@597] - Notification: 1 (message format version), 6 (n.leader), 0x1b00653e67 (n.zxid), 0x1 (n.round), LOOKING (n.state), 6 (
n.sid), 0x1b (n.peerEpoch) LOOKING (my state)
2018-02-12 16:29:51,660 [myid:6] - INFO [WorkerSender[myid=6]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (7, 6)
2018-02-12 16:29:54,861 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:FastLeaderElection@849] - Notification time out: 6400
2018-02-12 16:29:54,861 [myid:6] - INFO [WorkerReceiver[myid=6]:FastLeaderElection@597] - Notification: 1 (message format version), 6 (n.leader), 0x1b00653e67 (n.zxid), 0x1 (n.round), LOOKING (n.state), 6 (
n.sid), 0x1b (n.peerEpoch) LOOKING (my state)
2018-02-12 16:29:54,862 [myid:6] - INFO [WorkerSender[myid=6]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (7, 6)
2018-02-12 16:30:01,262 [myid:6] - INFO [QuorumPeer[myid=6]/0.0.0.0:4444:FastLeaderElection@849] - Notification time out: 12800
2018-02-12 16:30:01,263 [myid:6] - INFO [WorkerReceiver[myid=6]:FastLeaderElection@597] - Notification: 1 (message format version), 6 (n.leader), 0x1b00653e67 (n.zxid), 0x1 (n.round), LOOKING (n.state), 6 (
n.sid), 0x1b (n.peerEpoch) LOOKING (my state)
2018-02-12 16:30:01,263 [myid:6] - INFO [WorkerSender[myid=6]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (7, 6)
2018-02-12 16:30:02,050 [myid:6] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:4444:NIOServerCnxnFactory@197] - Accepted socket connection from /127.0.0.1:54541
2018-02-12 16:30:02,057 [myid:6] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:4444:NIOServerCnxn@827] - Processing ruok command from /127.0.0.1:54541
2018-02-12 16:30:02,060 [myid:6] - INFO [Thread-2:NIOServerCnxn@1007] - Closed socket connection for client /127.0.0.1:54541 (no session established for client)
2018-02-12 16:30:02,449 [myid:6] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:4444:NIOServerCnxnFactory@197] - Accepted socket connection from /127.0.0.1:54611
2018-02-12 16:30:02,450 [myid:6] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:4444:NIOServerCnxn@827] - Processing ruok command from /127.0.0.1:54611
2018-02-12 16:30:02,451 [myid:6] - INFO [Thread-3:NIOServerCnxn@1007] - Closed socket connection for client /127.0.0.1:54611 (no session established for client)
2018-02-12 16:30:02,789 [myid:6] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:4444:NIOServerCnxnFactory@197] - Accepted socket connection from /127.0.0.1:54671
2018-02-12 16:30:02,790 [myid:6] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:4444:NIOServerCnxn@827] - Processing ruok command from /127.0.0.1:54671
2018-02-12 16:30:02,791 [myid:6] - INFO [Thread-4:NIOServerCnxn@1007] - Closed socket connection for client /127.0.0.1:54671 (no session established for client)
... these messages continue
{code}
> Peer with smallest id is unable to join quorum after connection broken to other peers
> -------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-2938
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2938
> Project: ZooKeeper
> Issue Type: Bug
> Affects Versions: 3.4.6
> Reporter: Abhay Bothra
> Priority: Major
>
> We see the following logs in the node with {{myid: 1}}
> {code}
> 2017-11-08 15:06:28,375 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (2, 1)
> 2017-11-08 15:06:28,375 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (3, 1)
> 2017-11-08 15:07:28,375 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message format version), 1 (n.leader), 0x28e000a8750 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x28e (n.peerEpoch) LOOKING (my state)
> 2017-11-08 15:07:28,375 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (2, 1)
> 2017-11-08 15:07:28,376 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (3, 1)
> 2017-11-08 15:08:28,375 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message format version), 1 (n.leader), 0x28e000a8750 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x28e (n.peerEpoch) LOOKING (my state)
> 2017-11-08 15:08:28,376 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (2, 1)
> 2017-11-08 15:08:28,376 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (3, 1)
> 2017-11-08 15:09:28,376 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message format version), 1 (n.leader), 0x28e000a8750 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x28e (n.peerEpoch) LOOKING (my state)
> 2017-11-08 15:09:28,376 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (2, 1)
> 2017-11-08 15:09:28,376 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (3, 1)
> 2017-11-08 15:10:28,376 [myid:1] - INFO [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message format version), 1 (n.leader), 0x28e000a8750 (n.zxid), 0x1 (n.round), LOOKING (n.state), 1 (n.sid), 0x28e (n.peerEpoch) LOOKING (my state)
> 2017-11-08 15:10:28,376 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (2, 1)
> 2017-11-08 15:10:28,377 [myid:1] - INFO [WorkerSender[myid=1]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (3, 1)
> {code}
> On the nodes with {{myid: 2}} and {{myid: 3}}, we see connection broken events for {{myid: 1}}
> {code}
> 2017-11-07 02:54:32,135 [myid:2] - WARN [RecvWorker:1:QuorumCnxManager$RecvWorker@780] - Connection broken for id 1, my id = 2, error =
> java.net.SocketException: Connection reset
> at java.net.SocketInputStream.read(SocketInputStream.java:209)
> at java.net.SocketInputStream.read(SocketInputStream.java:141)
> at java.net.SocketInputStream.read(SocketInputStream.java:223)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:765)
> 2017-11-07 02:54:32,135 [myid:2] - WARN [RecvWorker:1:QuorumCnxManager$RecvWorker@783] - Interrupting SendWorker
> 2017-11-07 02:54:32,135 [myid:2] - WARN [SendWorker:1:QuorumCnxManager$SendWorker@697] - Interrupted while waiting for message on queue
> java.lang.InterruptedException
> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
> at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:849)
> at org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:64)
> at org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:685)
> 2017-11-07 02:54:32,135 [myid:2] - WARN [SendWorker:1:QuorumCnxManager$SendWorker@706] - Send worker leaving thread
> {code}
> From the reported occurrences, it looks like this is a problem only when the node with the smallest {{myid}} loses connection.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)