[ 
https://issues.apache.org/jira/browse/ZOOKEEPER-2938?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16361076#comment-16361076
 ] 

Adam J Shook edited comment on ZOOKEEPER-2938 at 2/12/18 5:13 PM:
------------------------------------------------------------------

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.  Killing the leader resulted 
in the full ensemble returning.

{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}


was (Author: adamjshook):
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)

Reply via email to