ZooKeeper
  1. ZooKeeper
  2. ZOOKEEPER-790

Last processed zxid set prematurely while establishing leadership

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 3.3.1
    • Fix Version/s: 3.3.2, 3.4.0
    • Component/s: quorum
    • Labels:
      None
    • Hadoop Flags:
      Reviewed

      Description

      The leader code is setting the last processed zxid to the first of the new epoch even before connecting to a quorum of followers. Because the leader code sets this value before connecting to a quorum of followers (Leader.java:281) and the follower code throws an IOException (Follower.java:73) if the leader epoch is smaller, we have that when the false leader drops leadership and becomes a follower, it finds a smaller epoch and kills itself.

      1. ZOOKEEPER-790.v2.patch
        17 kB
        Flavio Junqueira
      2. ZOOKEEPER-790-3.3.v2.patch
        17 kB
        Flavio Junqueira
      3. ZOOKEEPER-790.v2.patch
        17 kB
        Flavio Junqueira
      4. ZOOKEEPER-790-test.patch
        10 kB
        Sergey Doroshenko
      5. ZOOKEEPER-790.v2.patch
        4 kB
        Flavio Junqueira
      6. ZOOKEEPER-790-follower-request-NPE.log
        16 kB
        Sergey Doroshenko
      7. ZOOKEEPER-790.patch
        13 kB
        Flavio Junqueira
      8. ZOOKEEPER-790-3.3.patch
        13 kB
        Flavio Junqueira
      9. ZOOKEEPER-790.patch
        13 kB
        Flavio Junqueira
      10. ZOOKEEPER-790-3.3.patch
        12 kB
        Flavio Junqueira
      11. ZOOKEEPER-790.patch
        13 kB
        Flavio Junqueira
      12. ZOOKEEPER-790.patch
        3 kB
        Flavio Junqueira
      13. ZOOKEEPER-790.travis.log.bz2
        44 kB
        Travis Crawford
      14. ZOOKEEPER-790.patch
        1 kB
        Flavio Junqueira

        Issue Links

          Activity

          Flavio Junqueira created issue -
          Flavio Junqueira made changes -
          Field Original Value New Value
          Attachment ZOOKEEPER-790.patch [ 12447715 ]
          Patrick Hunt made changes -
          Assignee Flavio Paiva Junqueira [ fpj ]
          Fix Version/s 3.4.0 [ 12314469 ]
          Priority Major [ 3 ] Blocker [ 1 ]
          Patrick Hunt made changes -
          Link This issue relates to ZOOKEEPER-335 [ ZOOKEEPER-335 ]
          Hide
          Vishal Kher added a comment -

          I will try out the patch. I will try it out on 3.3.0 since that is the version we are currently using.

          -Vishal

          Show
          Vishal Kher added a comment - I will try out the patch. I will try it out on 3.3.0 since that is the version we are currently using. -Vishal
          Hide
          Travis Crawford added a comment -

          @vishal - How did your test go? I came across this issue while investigating an issue and believe this is the root cause.

          If your test went well I can also help test.

          Show
          Travis Crawford added a comment - @vishal - How did your test go? I came across this issue while investigating an issue and believe this is the root cause. If your test went well I can also help test.
          Hide
          Vishal Kher added a comment -

          Folks,

          Sorry to the delay. The patch did not work. Any other ideas? Thanks.

          -Vishal

          Show
          Vishal Kher added a comment - Folks, Sorry to the delay. The patch did not work. Any other ideas? Thanks. -Vishal
          Hide
          Flavio Junqueira added a comment -

          Vishal, What exactly didn't work? Do you get the same error messages with the patch? Do you have a reliable way of reproducing it? In general, it would be useful if you could provide more detail.

          Thanks!

          Show
          Flavio Junqueira added a comment - Vishal, What exactly didn't work? Do you get the same error messages with the patch? Do you have a reliable way of reproducing it? In general, it would be useful if you could provide more detail. Thanks!
          Hide
          Vishal Kher added a comment -

          copying comments from email to jira.

          Hi Flavio ,

          I got the same error messages. I can reproduce this quite easily. I will capture the logs again. Is there anything else you would like me to provide? Thanks.

          -Vishal

          Show
          Vishal Kher added a comment - copying comments from email to jira. Hi Flavio , I got the same error messages. I can reproduce this quite easily. I will capture the logs again. Is there anything else you would like me to provide? Thanks. -Vishal
          Hide
          Vishal Kher added a comment -

          copying comments from email to jira.

          I forgot if you have provided already a description of how you reproduce it. If you could point me out to that, I would appreciate.

          -Flavio

          Show
          Vishal Kher added a comment - copying comments from email to jira. I forgot if you have provided already a description of how you reproduce it. If you could point me out to that, I would appreciate. -Flavio
          Hide
          Vishal Kher added a comment -

          From ZOOKEEPER-335..

          Hi,

          I enabled tracing and did some more debugging. Looks like the restarted peer (and trying to join the cluster) determines that it is a leader and increments its epoch. However, rest of the nodes don't acknowledge this node as the leader, and hence, have an older epoch. I will attache the log. Unfortunately, I don't have traces from other nodes. I will repeat the experiment later and attache logs from other nodes.

          Scenario:

          • Form a 3 node cluster. This is not just ZK cluster. It also involves our application cluster that uses ZK.
          • Kill one of the follower
          • After a minute or so restart follower
          • Follower rejects leader with "Leader epoch y is less than our epoch y + 1"

          From logs:

          a) Peer X restarts and starts leader election.
          a) For a small window of time, X thinks that it is the new leader! During this window, for some reason, rest of the nodes tell X that they are also trying to find a leader. I.e., all 3 nodes are in LOOKING state. After seeing that all 3 nodes are in LOOKING state, X decides to be a leader?

          155 2010-06-20 23:22:46,421 - DEBUG [WorkerSender Thread:QuorumCnxManager@346] - Opening channel to server 1
          156 2010-06-20 23:22:46,423 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@214] - Receive new notification message. My id = 0
          157 2010-06-20 23:22:46,424 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 0, 77309411393, 1, 0, LOOKING, LOOKING, 0
          158 2010-06-20 23:22:46,424 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@495] - id: 0, proposed id: 0, zxid: 77309411393, proposed zxid: 77309411393
          159 2010-06-20 23:22:46,424 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@717] - Adding vote: From = 0, Proposed leader = 0, Porposed zxid = 77309411393, Proposed epoch = 1
          160 2010-06-20 23:22:46,426 - INFO [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (1, 0)
          161 2010-06-20 23:22:46,426 - DEBUG [WorkerSender Thread:QuorumCnxManager@346] - Opening channel to server 2
          162 2010-06-20 23:22:46,427 - DEBUG [Thread-1:QuorumCnxManager$Listener@445] - Connection request /192.168.1.182:46701
          163 2010-06-20 23:22:46,427 - DEBUG [Thread-1:QuorumCnxManager$Listener@448] - Connection request: 0
          164 2010-06-20 23:22:46,428 - DEBUG [Thread-1:QuorumCnxManager$SendWorker@504] - Address of remote peer: 1
          165 2010-06-20 23:22:46,428 - INFO [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (2, 0)
          166 2010-06-20 23:22:46,431 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@214] - Receive new notification message. My id = 0
          167 2010-06-20 23:22:46,432 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 1, 77309411372, 1, 0, LOOKING, LOOKING, 1
          168 2010-06-20 23:22:46,432 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@495] - id: 1, proposed id: 0, zxid: 77309411372, proposed zxid: 77309411393
          169 2010-06-20 23:22:46,432 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@717] - Adding vote: From = 1, Proposed leader = 1, Porposed zxid = 77309411372, Proposed epoch = 1
          170 2010-06-20 23:22:46,436 - DEBUG [Thread-1:QuorumCnxManager$Listener@445] - Connection request /192.168.1.183:44310
          171 2010-06-20 23:22:46,436 - DEBUG [Thread-1:QuorumCnxManager$Listener@448] - Connection request: 0
          172 2010-06-20 23:22:46,436 - DEBUG [Thread-1:QuorumCnxManager$SendWorker@504] - Address of remote peer: 2
          173 2010-06-20 23:22:46,440 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@214] - Receive new notification message. My id = 0
          174 2010-06-20 23:22:46,440 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 2, 73014444097, 1, 0, LOOKING, LOOKING, 2
          175 2010-06-20 23:22:46,440 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@495] - id: 2, proposed id: 0, zxid: 73014444097, proposed zxid: 77309411393
          176 2010-06-20 23:22:46,441 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@717] - Adding vote: From = 2, Proposed leader = 2, Porposed zxid = 73014444097, Proposed epoch = 1
          177 2010-06-20 23:22:46,441 - INFO [QuorumPeer:/0.0.0.0:2181:QuorumPeer@647] - LEADING

          b) As a result X increments its epoch. Worse, since this node decided to be a leader, it starts doing transactions. The first set of transactions start removing all ephemeral nodes. But these transactions are only done locally. Other peers do not ack these transactions since they know that this peer is not the leader.

          c) After a few seconds (8 secs), X relinquishes leadership since it does not receive any ack from rest of the peers
          d) It starts leader election again. This time, rests of the peers respond correctly informing X that a leader already exists.
          e) X determines that it should now follow the leader and starts handshake with the leader. However, X has incremented its epoch in the mean time. X thinks that the epoch sent by the leader during handshake is older than the epoch it has noticed before. X aborts connection with the leader.

          Show
          Vishal Kher added a comment - From ZOOKEEPER-335 .. Hi, I enabled tracing and did some more debugging. Looks like the restarted peer (and trying to join the cluster) determines that it is a leader and increments its epoch. However, rest of the nodes don't acknowledge this node as the leader, and hence, have an older epoch. I will attache the log. Unfortunately, I don't have traces from other nodes. I will repeat the experiment later and attache logs from other nodes. Scenario: Form a 3 node cluster. This is not just ZK cluster. It also involves our application cluster that uses ZK. Kill one of the follower After a minute or so restart follower Follower rejects leader with "Leader epoch y is less than our epoch y + 1" From logs: a) Peer X restarts and starts leader election. a) For a small window of time, X thinks that it is the new leader! During this window, for some reason, rest of the nodes tell X that they are also trying to find a leader. I.e., all 3 nodes are in LOOKING state. After seeing that all 3 nodes are in LOOKING state, X decides to be a leader? 155 2010-06-20 23:22:46,421 - DEBUG [WorkerSender Thread:QuorumCnxManager@346] - Opening channel to server 1 156 2010-06-20 23:22:46,423 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@214] - Receive new notification message. My id = 0 157 2010-06-20 23:22:46,424 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 0, 77309411393, 1, 0, LOOKING, LOOKING, 0 158 2010-06-20 23:22:46,424 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@495] - id: 0, proposed id: 0, zxid: 77309411393, proposed zxid: 77309411393 159 2010-06-20 23:22:46,424 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@717] - Adding vote: From = 0, Proposed leader = 0, Porposed zxid = 77309411393, Proposed epoch = 1 160 2010-06-20 23:22:46,426 - INFO [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (1, 0) 161 2010-06-20 23:22:46,426 - DEBUG [WorkerSender Thread:QuorumCnxManager@346] - Opening channel to server 2 162 2010-06-20 23:22:46,427 - DEBUG [Thread-1:QuorumCnxManager$Listener@445] - Connection request /192.168.1.182:46701 163 2010-06-20 23:22:46,427 - DEBUG [Thread-1:QuorumCnxManager$Listener@448] - Connection request: 0 164 2010-06-20 23:22:46,428 - DEBUG [Thread-1:QuorumCnxManager$SendWorker@504] - Address of remote peer: 1 165 2010-06-20 23:22:46,428 - INFO [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (2, 0) 166 2010-06-20 23:22:46,431 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@214] - Receive new notification message. My id = 0 167 2010-06-20 23:22:46,432 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 1, 77309411372, 1, 0, LOOKING, LOOKING, 1 168 2010-06-20 23:22:46,432 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@495] - id: 1, proposed id: 0, zxid: 77309411372, proposed zxid: 77309411393 169 2010-06-20 23:22:46,432 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@717] - Adding vote: From = 1, Proposed leader = 1, Porposed zxid = 77309411372, Proposed epoch = 1 170 2010-06-20 23:22:46,436 - DEBUG [Thread-1:QuorumCnxManager$Listener@445] - Connection request /192.168.1.183:44310 171 2010-06-20 23:22:46,436 - DEBUG [Thread-1:QuorumCnxManager$Listener@448] - Connection request: 0 172 2010-06-20 23:22:46,436 - DEBUG [Thread-1:QuorumCnxManager$SendWorker@504] - Address of remote peer: 2 173 2010-06-20 23:22:46,440 - DEBUG [WorkerReceiver Thread:FastLeaderElection$Messenger$WorkerReceiver@214] - Receive new notification message. My id = 0 174 2010-06-20 23:22:46,440 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 2, 73014444097, 1, 0, LOOKING, LOOKING, 2 175 2010-06-20 23:22:46,440 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@495] - id: 2, proposed id: 0, zxid: 73014444097, proposed zxid: 77309411393 176 2010-06-20 23:22:46,441 - DEBUG [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@717] - Adding vote: From = 2, Proposed leader = 2, Porposed zxid = 73014444097, Proposed epoch = 1 177 2010-06-20 23:22:46,441 - INFO [QuorumPeer:/0.0.0.0:2181:QuorumPeer@647] - LEADING b) As a result X increments its epoch. Worse, since this node decided to be a leader, it starts doing transactions. The first set of transactions start removing all ephemeral nodes. But these transactions are only done locally. Other peers do not ack these transactions since they know that this peer is not the leader. c) After a few seconds (8 secs), X relinquishes leadership since it does not receive any ack from rest of the peers d) It starts leader election again. This time, rests of the peers respond correctly informing X that a leader already exists. e) X determines that it should now follow the leader and starts handshake with the leader. However, X has incremented its epoch in the mean time. X thinks that the epoch sent by the leader during handshake is older than the epoch it has noticed before. X aborts connection with the leader.
          Hide
          Vishal Kher added a comment -

          Hi Flavio,

          I think there are two additional related problems:

          1. Why are the other two nodes that have formed the cluster in LOOKING state? Both should reply with FOLLOWING
          174 2010-06-20 23:22:46,440 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 2, 73014444097, 1, 0, LOOKING, LOOKING, 2

          2. The node attempting to join goes in an infinite loop of join fails. We should add a delay.

          Thanks,
          Vishal

          Show
          Vishal Kher added a comment - Hi Flavio, I think there are two additional related problems: 1. Why are the other two nodes that have formed the cluster in LOOKING state? Both should reply with FOLLOWING 174 2010-06-20 23:22:46,440 - INFO [QuorumPeer:/0.0.0.0:2181:FastLeaderElection@689] - Notification: 2, 73014444097, 1, 0, LOOKING, LOOKING, 2 2. The node attempting to join goes in an infinite loop of join fails. We should add a delay. Thanks, Vishal
          Hide
          Flavio Junqueira added a comment -

          Hi Vishal, Thanks for all the information. I haven't been able to reproduce it yet, but here are some thoughts after looking over your logs again:

          1- It is not a problem that server 0 is declaring itself leader, even though there is another leader running. Server 0 will be ignored by the others and eventually will drop its leadership as you have observed;
          2- The notifications of 1 and 2 say looking because they have been queued at the time 1 and 2 were looking for a leader. That's not an issue;
          3- I don't understand why the patch doesn't work. Let me tell you how I'm interpreting your run. Server 0 is receiving the notifications from 1 and 2, and deciding that it should be the leader. Because in the current trunk code we set the first zxid for the new epoch before hearing from a quorum, once server 0 drops leadership, it has a higher zxid than everyone else. Consequently, it correctly refuses to talk to the current leader. Now, setting the first epoch zxid prematurely is a problem, and the patch I have uploaded should fix it. The bottom line is that I can't understand why the patch I uploaded does not fix it. Have you made sure to apply it before running your new tests? Either way, I would appreciate if you could upload logs out of a run with the current 790 patch.

          Thanks!

          Show
          Flavio Junqueira added a comment - Hi Vishal, Thanks for all the information. I haven't been able to reproduce it yet, but here are some thoughts after looking over your logs again: 1- It is not a problem that server 0 is declaring itself leader, even though there is another leader running. Server 0 will be ignored by the others and eventually will drop its leadership as you have observed; 2- The notifications of 1 and 2 say looking because they have been queued at the time 1 and 2 were looking for a leader. That's not an issue; 3- I don't understand why the patch doesn't work. Let me tell you how I'm interpreting your run. Server 0 is receiving the notifications from 1 and 2, and deciding that it should be the leader. Because in the current trunk code we set the first zxid for the new epoch before hearing from a quorum, once server 0 drops leadership, it has a higher zxid than everyone else. Consequently, it correctly refuses to talk to the current leader. Now, setting the first epoch zxid prematurely is a problem, and the patch I have uploaded should fix it. The bottom line is that I can't understand why the patch I uploaded does not fix it. Have you made sure to apply it before running your new tests? Either way, I would appreciate if you could upload logs out of a run with the current 790 patch. Thanks!
          Hide
          Vishal Kher added a comment -

          Hi Flavio,

          I am going to retry again with the patch. Thanks.

          -Vishal

          Show
          Vishal Kher added a comment - Hi Flavio, I am going to retry again with the patch. Thanks. -Vishal
          Hide
          Patrick Hunt added a comment -

          Vishal, you might add some sort of log message to the code (in addition to the patch) to verify that the code you're running is the patched version.

          Show
          Patrick Hunt added a comment - Vishal, you might add some sort of log message to the code (in addition to the patch) to verify that the code you're running is the patched version.
          Hide
          Vishal Kher added a comment -

          Hi Patrick,

          I had done that earlier. I will do it again to reconfirm. I would also help if Travis or Charity can also try to verify the patch, if possible.

          -Vishal

          Show
          Vishal Kher added a comment - Hi Patrick, I had done that earlier. I will do it again to reconfirm. I would also help if Travis or Charity can also try to verify the patch, if possible. -Vishal
          Hide
          Travis Crawford added a comment -

          Sure, I'll help test this too.

          Show
          Travis Crawford added a comment - Sure, I'll help test this too.
          Hide
          Travis Crawford added a comment -

          I accidentally posted this in ZOOKEEPER-335 – reposting here. Sorry for the posting mixup – the content is correct though

          Unfortunately I still observed the "Leader epoch" issue and needed to manually force a leader election for the cluster to recover. This test was performed with the following base+patches, applied in the order listed.

          Zookeeper 3.3.1
          ZOOKEEPER-744
          ZOOKEEPER-790

          2010-07-15 02:43:57,181 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileSnap@82] - Reading snapshot /data/zookeeper/version-2/snapshot.2300001ac2
          2010-07-15 02:43:57,384 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@649] - New election. My id =  1, Proposed zxid = 154618826848
          2010-07-15 02:43:57,385 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 1, 154618826848, 4, 1, LOOKING, LOOKING, 1
          2010-07-15 02:43:57,385 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@799] - Notification: 2, 146030952153, 3, 1, LOOKING, LEADING, 2
          2010-07-15 02:43:57,385 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@799] - Notification: 2, 146030952153, 3, 1, LOOKING, FOLLOWING, 3
          2010-07-15 02:43:57,385 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@642] - FOLLOWING
          2010-07-15 02:43:57,385 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@151] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /data/zookeeper/txlog/version-2 snapdir /data/zookeeper/version-2
          2010-07-15 02:43:57,387 - FATAL [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@71] - Leader epoch 23 is less than our epoch 24
          2010-07-15 02:43:57,387 - WARN  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@82] - Exception when following the leader 
          java.io.IOException: Error: Epoch of leader is lower
                  at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:73)
                  at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:644)
          2010-07-15 02:43:57,387 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@166] - shutdown called 
          java.lang.Exception: shutdown Follower
                  at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
                  at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:648)
          

          I followed the recipe @vishal provided for recreating.

          (a) Stop one follower in a three node cluster
          (b) Get some tea while it falls behind
          (c) Start the node stopped in (a).

          These timestamps show where the follower was stopped. It also shows when it was turned back on.

          2010-07-15 02:35:36,398 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:NIOServerCnxn@1661] - Established session 0x229aa13cfc6276b with negotiated timeout 10000 for client /10.209.45.114:34562
          2010-07-15 02:39:18,907 - INFO  [main:QuorumPeerConfig@90] - Reading configuration from: /etc/zookeeper/conf/zoo.cfg
          

          This timestamp is the first ``Leader epoch`` line. Everything between these two points will be the interesting bits.

          2010-07-15 02:39:43,339 - FATAL [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@71] - Leader epoch 23 is less than our epoch 24
          
          Show
          Travis Crawford added a comment - I accidentally posted this in ZOOKEEPER-335 – reposting here. Sorry for the posting mixup – the content is correct though Unfortunately I still observed the "Leader epoch" issue and needed to manually force a leader election for the cluster to recover. This test was performed with the following base+patches, applied in the order listed. Zookeeper 3.3.1 ZOOKEEPER-744 ZOOKEEPER-790 2010-07-15 02:43:57,181 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileSnap@82] - Reading snapshot /data/zookeeper/version-2/snapshot.2300001ac2 2010-07-15 02:43:57,384 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@649] - New election. My id = 1, Proposed zxid = 154618826848 2010-07-15 02:43:57,385 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 1, 154618826848, 4, 1, LOOKING, LOOKING, 1 2010-07-15 02:43:57,385 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@799] - Notification: 2, 146030952153, 3, 1, LOOKING, LEADING, 2 2010-07-15 02:43:57,385 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@799] - Notification: 2, 146030952153, 3, 1, LOOKING, FOLLOWING, 3 2010-07-15 02:43:57,385 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@642] - FOLLOWING 2010-07-15 02:43:57,385 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@151] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /data/zookeeper/txlog/version-2 snapdir /data/zookeeper/version-2 2010-07-15 02:43:57,387 - FATAL [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@71] - Leader epoch 23 is less than our epoch 24 2010-07-15 02:43:57,387 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@82] - Exception when following the leader java.io.IOException: Error: Epoch of leader is lower at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:73) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:644) 2010-07-15 02:43:57,387 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@166] - shutdown called java.lang.Exception: shutdown Follower at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:648) I followed the recipe @vishal provided for recreating. (a) Stop one follower in a three node cluster (b) Get some tea while it falls behind (c) Start the node stopped in (a). These timestamps show where the follower was stopped. It also shows when it was turned back on. 2010-07-15 02:35:36,398 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:NIOServerCnxn@1661] - Established session 0x229aa13cfc6276b with negotiated timeout 10000 for client /10.209.45.114:34562 2010-07-15 02:39:18,907 - INFO [main:QuorumPeerConfig@90] - Reading configuration from: /etc/zookeeper/conf/zoo.cfg This timestamp is the first ``Leader epoch`` line. Everything between these two points will be the interesting bits. 2010-07-15 02:39:43,339 - FATAL [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@71] - Leader epoch 23 is less than our epoch 24
          Travis Crawford made changes -
          Attachment ZOOKEEPER-790.travis.log.bz2 [ 12449533 ]
          Hide
          Flavio Junqueira added a comment -

          Thank you both for all the information. I have been able to reproduce and find the source of the bug, but I don't have a patch yet. The problem is deeper than I thought originally. Let me show you what is going on:

          I'm including an excerpt of logs from two runs: one good and one bad. The first run is good (see the excerpt below). I have killed the follower and restarted it as Vishal suggested. When it comes back, it declares itself as leader, also as Vishal and Travis observed. However, different from what Vishal and Travis observed, it drops leadership and follows happily the leader right after.

          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@654] - LEADING
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LEADING (my state)
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@54] - TCP NoDelay set to: true
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:zookeeper.version=3.4.0--1, built on 07/15/2010 10:36 GMT
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:host.name=XXXXXXXXXX.com
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.version=1.6.0_04
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc.
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.home=/usr/java/jdk1.6.0_04/jre
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.class.path=.XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.library.path= XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.io.tmpdir=/tmp
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.compiler=<NA>
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.name=Linux
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.arch=amd64
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.version=2.6.18-53.1.21.el5
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.name=XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.home=XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.dir=XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /XXXXXXXXX/zookeeper/version-2 snapdir /XXXXXXXX/zookeeper/version-2
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXX/zookeeper/version-2/snapshot.100113340
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXX/zookeeper/version-2/snapshot.100113340
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileTxnSnapLog@208] - Snapshotting: 10011f748
          INFO  - [SessionTracker:ZooKeeperServer@315] - Expiring session 0x229d6a9e0ca0000, timeout of 10000ms exceeded
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@394] - Shutdown called
          java.lang.Exception: shutdown Leader! reason: Waiting for a quorum of followers, only synced with: 2: 
                  at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:394)
                  at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:317)
                  at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:657)
          INFO  - [Thread-10:Leader$LearnerCnxAcceptor@243] - exception while shutting down acceptor: java.net.SocketException: Socket closed
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FinalRequestProcessor@378] - shutdown of request processor complete
          INFO  - [SyncThread:2:SyncRequestProcessor@151] - SyncRequestProcessor exited!
          INFO  - [CommitProcessor:2:CommitProcessor@148] - CommitProcessor exited loop!
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@620] - LOOKING
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXXX/zookeeper/version-2/snapshot.10011f748
          INFO  - [SessionTracker:SessionTrackerImpl@158] - SessionTrackerImpl exited loop!
          INFO  - [ProcessThread:-1:PrepRequestProcessor@385] - Processed session termination for sessionid: 0x229d6a9e0ca0000
          ERROR - [ProcessThread:-1:NIOServerCnxn$Factory$1@87] - Thread Thread[ProcessThread:-1,5,main] died
          java.lang.NullPointerException
                  at org.apache.zookeeper.server.quorum.ProposalRequestProcessor.processRequest(ProposalRequestProcessor.java:71)
                  at org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcessor.java:435)
                  at org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.java:114)
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FastLeaderElection@663] - New election. My id =  2, Proposed zxid = 4296144712
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 2 (n.leader), 4296144712 (n.zxid), 2 (n.round), LOOKING (n.state), 2 (n.sid), LOOKING (my state)
          INFO  - [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (3, 2)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 1 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 1 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 1 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state)
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@642] - FOLLOWING
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@72] - TCP NoDelay set to: true
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /XXXXXXXXX/zookeeper/version-2 snapdir /XXXXXXXXX/zookeeper/version-2
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@285] - Getting a snapshot from leader
          FATAL - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@314] - Setting leader epoch 1
          WARN  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@116] - Got zxid 0x100162711 expected 0x1
          WARN  - [SyncThread:2:FileTxnLog@196] - Creating new log file: 100162711
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileTxnSnapLog@208] - Snapshotting: 100164c43
          

          Now, the following run is bad. I followed the same procedure, but this time we get the epoch problem. Looking carefully at the logs, you'll see that the main difference is that this time the zookeeper server created a new log file: log.200000001. This is bad because the zookeeper server will use the zxid in the latest txn log file to determine its last epoch. Given that the current leader is in epoch 1, it will correctly refuse to talk to the leader as we observe below.

          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@654] - LEADING
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@54] - TCP NoDelay set to: true
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:zookeeper.version=3.4.0--1, built on 07/15/2010 10:36 GMT
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:host.name=XXXXXXXX.com
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.version=1.6.0_05
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc.
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.home=/usr/java/jdk1.6.0_05/jre
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.class.path=XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.library.path=XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.io.tmpdir=/tmp
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.compiler=<NA>
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.name=Linux
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.arch= amd64
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.version=2.6.18-92.1.13.el5.perfctr.2.6.36
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.name=XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.home=XXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.dir=XXXXXXXXX
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /xxxxxxx/zookeeper/version-2 snapdir /XXXXXXX/zookeeper/version-2
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXX/zookeeper/version-2/snapshot.1000469b4
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXX/zookeeper/version-2/snapshot.1000469b4
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileTxnSnapLog@208] - Snapshotting: 100055cec
          INFO  - [SessionTracker:ZooKeeperServer@315] - Expiring session 0x129d6b61b5b0000, timeout of 10000ms exceeded
          INFO  - [ProcessThread:-1:PrepRequestProcessor@385] - Processed session termination for sessionid: 0x129d6b61b5b0000
          WARN  - [SyncThread:1:FileTxnLog@196] - Creating new log file: log.200000001
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@394] - Shutdown called
          java.lang.Exception: shutdown Leader! reason: Waiting for a quorum of followers, only synced with: 1: 
                  at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:394)
                  at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:317)
                  at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:657)
          INFO  - [ProcessThread:-1:PrepRequestProcessor@119] - PrepRequestProcessor exited loop!
          INFO  - [CommitProcessor:1:CommitProcessor@148] - CommitProcessor exited loop!
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FinalRequestProcessor@378] - shutdown of request processor complete
          INFO  - [SyncThread:1:SyncRequestProcessor@151] - SyncRequestProcessor exited!
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@620] - LOOKING
          INFO  - [Thread-8:Leader$LearnerCnxAcceptor@243] - exception while shutting down acceptor: java.net.SocketException: Socket closed
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXX/zookeeper/version-2/snapshot.100055cec
          INFO  - [SessionTracker:SessionTrackerImpl@158] - SessionTrackerImpl exited loop!
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FastLeaderElection@663] - New election. My id =  1, Proposed zxid = 8589934593
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 1 (n.leader), 8589934593 (n.zxid), 2 (n.round), LOOKING (n.state), 1 (n.sid), LOOKING (my state)
          INFO  - [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (2, 1)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 2 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 2 (n.sid), LOOKING (my state)
          INFO  - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 2 (n.sid), LOOKING (my state)
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@642] - FOLLOWING
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@72] - TCP NoDelay set to: true
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /xxxxxxx/zookeeper/version-2 snapdir /xxxxxxx/zookeeper/version-2
          FATAL - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@71] - Leader epoch 1 is less than our epoch 2
          WARN  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@82] - Exception when following the leader
          java.io.IOException: Error: Epoch of leader is lower
                  at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:73)
                  at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:644)
          INFO  - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@166] - shutdown called
          java.lang.Exception: shutdown Follower
                  at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
                  at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:648)
          

          Fixing it is not as simple as setting the current zxid to 200000001 after we hear from a quorum because the request processor pipeline starts complaining about an attempt to commit a future proposal.

          Show
          Flavio Junqueira added a comment - Thank you both for all the information. I have been able to reproduce and find the source of the bug, but I don't have a patch yet. The problem is deeper than I thought originally. Let me show you what is going on: I'm including an excerpt of logs from two runs: one good and one bad. The first run is good (see the excerpt below). I have killed the follower and restarted it as Vishal suggested. When it comes back, it declares itself as leader, also as Vishal and Travis observed. However, different from what Vishal and Travis observed, it drops leadership and follows happily the leader right after. INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@654] - LEADING INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LEADING (my state) INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@54] - TCP NoDelay set to: true INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:zookeeper.version=3.4.0--1, built on 07/15/2010 10:36 GMT INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:host.name=XXXXXXXXXX.com INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.version=1.6.0_04 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc. INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.home=/usr/java/jdk1.6.0_04/jre INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.class.path=.XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.library.path= XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.io.tmpdir=/tmp INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.compiler=<NA> INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.name=Linux INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.arch=amd64 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.version=2.6.18-53.1.21.el5 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.name=XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.home=XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.dir=XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /XXXXXXXXX/zookeeper/version-2 snapdir /XXXXXXXX/zookeeper/version-2 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXX/zookeeper/version-2/snapshot.100113340 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXX/zookeeper/version-2/snapshot.100113340 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileTxnSnapLog@208] - Snapshotting: 10011f748 INFO - [SessionTracker:ZooKeeperServer@315] - Expiring session 0x229d6a9e0ca0000, timeout of 10000ms exceeded INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@394] - Shutdown called java.lang.Exception: shutdown Leader! reason: Waiting for a quorum of followers, only synced with: 2: at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:394) at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:317) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:657) INFO - [Thread-10:Leader$LearnerCnxAcceptor@243] - exception while shutting down acceptor: java.net.SocketException: Socket closed INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FinalRequestProcessor@378] - shutdown of request processor complete INFO - [SyncThread:2:SyncRequestProcessor@151] - SyncRequestProcessor exited! INFO - [CommitProcessor:2:CommitProcessor@148] - CommitProcessor exited loop! INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@620] - LOOKING INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXXX/zookeeper/version-2/snapshot.10011f748 INFO - [SessionTracker:SessionTrackerImpl@158] - SessionTrackerImpl exited loop! INFO - [ProcessThread:-1:PrepRequestProcessor@385] - Processed session termination for sessionid: 0x229d6a9e0ca0000 ERROR - [ProcessThread:-1:NIOServerCnxn$Factory$1@87] - Thread Thread[ProcessThread:-1,5,main] died java.lang.NullPointerException at org.apache.zookeeper.server.quorum.ProposalRequestProcessor.processRequest(ProposalRequestProcessor.java:71) at org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcessor.java:435) at org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.java:114) INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FastLeaderElection@663] - New election. My id = 2, Proposed zxid = 4296144712 INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 2 (n.leader), 4296144712 (n.zxid), 2 (n.round), LOOKING (n.state), 2 (n.sid), LOOKING (my state) INFO - [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (3, 2) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 1 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 1 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 1 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state) INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@642] - FOLLOWING INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@72] - TCP NoDelay set to: true INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /XXXXXXXXX/zookeeper/version-2 snapdir /XXXXXXXXX/zookeeper/version-2 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@285] - Getting a snapshot from leader FATAL - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@314] - Setting leader epoch 1 WARN - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@116] - Got zxid 0x100162711 expected 0x1 WARN - [SyncThread:2:FileTxnLog@196] - Creating new log file: 100162711 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileTxnSnapLog@208] - Snapshotting: 100164c43 Now, the following run is bad. I followed the same procedure, but this time we get the epoch problem. Looking carefully at the logs, you'll see that the main difference is that this time the zookeeper server created a new log file: log.200000001. This is bad because the zookeeper server will use the zxid in the latest txn log file to determine its last epoch. Given that the current leader is in epoch 1, it will correctly refuse to talk to the leader as we observe below. INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@654] - LEADING INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@54] - TCP NoDelay set to: true INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:zookeeper.version=3.4.0--1, built on 07/15/2010 10:36 GMT INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:host.name=XXXXXXXX.com INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.version=1.6.0_05 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc. INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.home=/usr/java/jdk1.6.0_05/jre INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.class.path=XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.library.path=XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.io.tmpdir=/tmp INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:java.compiler=<NA> INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.name=Linux INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.arch= amd64 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:os.version=2.6.18-92.1.13.el5.perfctr.2.6.36 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.name=XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.home=XXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Environment@97] - Server environment:user.dir=XXXXXXXXX INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /xxxxxxx/zookeeper/version-2 snapdir /XXXXXXX/zookeeper/version-2 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXX/zookeeper/version-2/snapshot.1000469b4 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXX/zookeeper/version-2/snapshot.1000469b4 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileTxnSnapLog@208] - Snapshotting: 100055cec INFO - [SessionTracker:ZooKeeperServer@315] - Expiring session 0x129d6b61b5b0000, timeout of 10000ms exceeded INFO - [ProcessThread:-1:PrepRequestProcessor@385] - Processed session termination for sessionid: 0x129d6b61b5b0000 WARN - [SyncThread:1:FileTxnLog@196] - Creating new log file: log.200000001 INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Leader@394] - Shutdown called java.lang.Exception: shutdown Leader! reason: Waiting for a quorum of followers, only synced with: 1: at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:394) at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:317) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:657) INFO - [ProcessThread:-1:PrepRequestProcessor@119] - PrepRequestProcessor exited loop! INFO - [CommitProcessor:1:CommitProcessor@148] - CommitProcessor exited loop! INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FinalRequestProcessor@378] - shutdown of request processor complete INFO - [SyncThread:1:SyncRequestProcessor@151] - SyncRequestProcessor exited! INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@620] - LOOKING INFO - [Thread-8:Leader$LearnerCnxAcceptor@243] - exception while shutting down acceptor: java.net.SocketException: Socket closed INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FileSnap@82] - Reading snapshot /XXXXXXXX/zookeeper/version-2/snapshot.100055cec INFO - [SessionTracker:SessionTrackerImpl@158] - SessionTrackerImpl exited loop! INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:FastLeaderElection@663] - New election. My id = 1, Proposed zxid = 8589934593 INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 1 (n.leader), 8589934593 (n.zxid), 2 (n.round), LOOKING (n.state), 1 (n.sid), LOOKING (my state) INFO - [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (2, 1) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 2 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), LEADING (n.state), 3 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 2 (n.sid), LOOKING (my state) INFO - [WorkerReceiver Thread:FastLeaderElection@496] - Notification: 3 (n.leader), 0 (n.zxid), 1 (n.round), FOLLOWING (n.state), 2 (n.sid), LOOKING (my state) INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:QuorumPeer@642] - FOLLOWING INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Learner@72] - TCP NoDelay set to: true INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:ZooKeeperServer@151] - Created server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 60000 datadir /xxxxxxx/zookeeper/version-2 snapdir /xxxxxxx/zookeeper/version-2 FATAL - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@71] - Leader epoch 1 is less than our epoch 2 WARN - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@82] - Exception when following the leader java.io.IOException: Error: Epoch of leader is lower at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:73) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:644) INFO - [QuorumPeer:/0:0:0:0:0:0:0:0:10218:Follower@166] - shutdown called java.lang.Exception: shutdown Follower at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:648) Fixing it is not as simple as setting the current zxid to 200000001 after we hear from a quorum because the request processor pipeline starts complaining about an attempt to commit a future proposal.
          Hide
          Travis Crawford added a comment -

          Good find! I can certainly help test a patch, or collect more info if needed.

          Show
          Travis Crawford added a comment - Good find! I can certainly help test a patch, or collect more info if needed.
          Hide
          Vishal Kher added a comment -

          Likewise.

          Show
          Vishal Kher added a comment - Likewise.
          Hide
          Flavio Junqueira added a comment -

          Some additional information. We create a new transaction log when we try to append a transaction and there is no log file open. Consequently, we only create it when there is something to write. For the bad run above, here is the content of the log:

          ZooKeeper Transactional Log File with dbid 0 txnlog format version 2
          7/15/10 5:27:45 PM CEST session 0x129d6b61b5b0000 cxid 0x0 zxid 0x200000001 closeSession
          EOF reached after 1 txns.
          
          Show
          Flavio Junqueira added a comment - Some additional information. We create a new transaction log when we try to append a transaction and there is no log file open. Consequently, we only create it when there is something to write. For the bad run above, here is the content of the log: ZooKeeper Transactional Log File with dbid 0 txnlog format version 2 7/15/10 5:27:45 PM CEST session 0x129d6b61b5b0000 cxid 0x0 zxid 0x200000001 closeSession EOF reached after 1 txns.
          Hide
          Flavio Junqueira added a comment -

          Hi! I'm attaching a patch that works for my setup (and passes the unit tests as well), so I would appreciate if you could give it a try.

          Show
          Flavio Junqueira added a comment - Hi! I'm attaching a patch that works for my setup (and passes the unit tests as well), so I would appreciate if you could give it a try.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790.patch [ 12449676 ]
          Hide
          Vishal Kher added a comment -

          great! I will give it a try. Thanks.

          Show
          Vishal Kher added a comment - great! I will give it a try. Thanks.
          Hide
          Flavio Junqueira added a comment -

          This patch is very simple: it moves two function calls such that a leader only starts up and sets the the last processed zxid after it has a quorum of supporters. It also includes a unit test. I had to make a few modifications here and there to be able to write this test. I tried to minimize changes as much as possible.

          Show
          Flavio Junqueira added a comment - This patch is very simple: it moves two function calls such that a leader only starts up and sets the the last processed zxid after it has a quorum of supporters. It also includes a unit test. I had to make a few modifications here and there to be able to write this test. I tried to minimize changes as much as possible.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790.patch [ 12449972 ]
          Flavio Junqueira made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Hide
          Hadoop QA added a comment -

          -1 overall. Here are the results of testing the latest attachment
          http://issues.apache.org/jira/secure/attachment/12449972/ZOOKEEPER-790.patch
          against trunk revision 963957.

          +1 @author. The patch does not contain any @author tags.

          +1 tests included. The patch appears to include 6 new or modified tests.

          +1 javadoc. The javadoc tool did not generate any warning messages.

          +1 javac. The applied patch does not increase the total number of javac compiler warnings.

          +1 findbugs. The patch does not introduce any new Findbugs warnings.

          +1 release audit. The applied patch does not increase the total number of release audit warnings.

          -1 core tests. The patch failed core unit tests.

          +1 contrib tests. The patch passed contrib unit tests.

          Test results: http://hudson.zones.apache.org/hudson/job/Zookeeper-Patch-h1.grid.sp2.yahoo.net/150/testReport/
          Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Zookeeper-Patch-h1.grid.sp2.yahoo.net/150/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
          Console output: http://hudson.zones.apache.org/hudson/job/Zookeeper-Patch-h1.grid.sp2.yahoo.net/150/console

          This message is automatically generated.

          Show
          Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12449972/ZOOKEEPER-790.patch against trunk revision 963957. +1 @author. The patch does not contain any @author tags. +1 tests included. The patch appears to include 6 new or modified tests. +1 javadoc. The javadoc tool did not generate any warning messages. +1 javac. The applied patch does not increase the total number of javac compiler warnings. +1 findbugs. The patch does not introduce any new Findbugs warnings. +1 release audit. The applied patch does not increase the total number of release audit warnings. -1 core tests. The patch failed core unit tests. +1 contrib tests. The patch passed contrib unit tests. Test results: http://hudson.zones.apache.org/hudson/job/Zookeeper-Patch-h1.grid.sp2.yahoo.net/150/testReport/ Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Zookeeper-Patch-h1.grid.sp2.yahoo.net/150/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html Console output: http://hudson.zones.apache.org/hudson/job/Zookeeper-Patch-h1.grid.sp2.yahoo.net/150/console This message is automatically generated.
          Hide
          Flavio Junqueira added a comment -

          Uploading patch for the 3.3 branch. I have also checked the results of Hudson, and I couldn't find any java test failure. The -1 on core tests seems to be unrelated to this patch.

          Show
          Flavio Junqueira added a comment - Uploading patch for the 3.3 branch. I have also checked the results of Hudson, and I couldn't find any java test failure. The -1 on core tests seems to be unrelated to this patch.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790-3.3.patch [ 12449980 ]
          Hide
          Travis Crawford added a comment -

          I tested this patch on a build with the following, applied in the listed order: 3.3.1 release + ZOOKEEPER-744.patch + ZOOKEEPER-790-3.3.patch

          Looks good!

          2010-07-20 23:43:34,229 - INFO  [Thread-2545:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:53743 (no session established for client)
          2010-07-20 23:43:34,659 - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129d3fcb5a6f60d, likely client has closed socket
          2010-07-20 23:43:34,660 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.204:59727 which had sessionid 0x129d3fcb5a6f60d
          2010-07-20 23:43:34,684 - INFO  [ProcessThread:-1:PrepRequestProcessor@385] - Processed session termination for sessionid: 0x329d3fcb6594e53
          2010-07-20 23:52:14,522 - INFO  [main:QuorumPeerConfig@90] - Reading configuration from: /etc/zookeeper/conf/zoo.cfg
          2010-07-20 23:52:14,529 - INFO  [main:QuorumPeerConfig@287] - Defaulting to majority quorums
          2010-07-20 23:52:14,540 - INFO  [main:QuorumPeerMain@119] - Starting quorum peer
          2010-07-20 23:52:14,562 - INFO  [main:NIOServerCnxn$Factory@149] - binding to port 0.0.0.0/0.0.0.0:2181
          2010-07-20 23:52:14,578 - INFO  [main:QuorumPeer@818] - tickTime set to 2000
          2010-07-20 23:52:14,579 - INFO  [main:QuorumPeer@829] - minSessionTimeout set to -1
          2010-07-20 23:52:14,579 - INFO  [main:QuorumPeer@840] - maxSessionTimeout set to -1
          2010-07-20 23:52:14,579 - INFO  [main:QuorumPeer@855] - initLimit set to 10
          2010-07-20 23:52:14,798 - INFO  [main:FileSnap@82] - Reading snapshot /data/zookeeper/version-2/snapshot.2500197ee5
          2010-07-20 23:52:15,660 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.45.76:57030
          2010-07-20 23:52:15,661 - INFO  [Thread-1:QuorumCnxManager$Listener@436] - My election bind port: 3888
          2010-07-20 23:52:15,663 - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@644] - Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running
          2010-07-20 23:52:15,664 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.45.76:57030 (no session established for client)
          2010-07-20 23:52:15,670 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@620] - LOOKING
          2010-07-20 23:52:15,672 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@649] - New election. My id =  1, Proposed zxid = 158915472832
          2010-07-20 23:52:15,674 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 1, 158915472832, 1, 1, LOOKING, LOOKING, 1
          2010-07-20 23:52:15,674 - INFO  [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (2, 1)
          2010-07-20 23:52:15,675 - INFO  [WorkerSender Thread:QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (3, 1)
          2010-07-20 23:52:15,676 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 2, 158915472832, 5, 1, LOOKING, LOOKING, 2
          2010-07-20 23:52:15,676 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 3, 158915472832, 5, 1, LOOKING, LOOKING, 2
          2010-07-20 23:52:15,676 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@711] - Updating proposal
          2010-07-20 23:52:15,677 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@799] - Notification: 3, 158915472832, 5, 1, LOOKING, FOLLOWING, 2
          2010-07-20 23:52:15,677 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 3, 158915472832, 5, 1, LOOKING, LOOKING, 3
          2010-07-20 23:52:15,879 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@642] - FOLLOWING
          2010-07-20 23:52:15,885 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@72] - TCP NoDelay set to: true
          2010-07-20 23:52:15,893 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:zookeeper.version=3.3.1-942149, built on 05/07/2010 17:14 GMT
          2010-07-20 23:52:15,893 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:host.name=sjc1k029.twitter.com
          2010-07-20 23:52:15,894 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.version=1.6.0_16
          2010-07-20 23:52:15,894 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc.
          2010-07-20 23:52:15,894 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.home=/usr/java/jdk1.6.0_16/jre
          2010-07-20 23:52:15,894 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.class.path=/etc/zookeeper/conf::/usr/local/zookeeper/../zookeeper-*.jar:/usr/local/zookeeper/../lib/*.jar:/usr/local/zookeeper/../src/java/lib/*.jar:/usr/local/zookeeper/jline-0.9.94.jar:/usr/local/zookeeper/log4j-1.2.15.jar:/usr/local/zookeeper/zookeeper-3.3.2-dev.jar
          2010-07-20 23:52:15,895 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.library.path=/usr/java/jdk1.6.0_16/jre/lib/amd64/server:/usr/java/jdk1.6.0_16/jre/lib/amd64:/usr/java/jdk1.6.0_16/jre/../lib/amd64:/usr/java/packages/lib/amd64:/lib:/usr/lib
          2010-07-20 23:52:15,895 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.io.tmpdir=/tmp
          2010-07-20 23:52:15,895 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.compiler=<NA>
          2010-07-20 23:52:15,896 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.name=Linux
          2010-07-20 23:52:15,896 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.arch=amd64
          2010-07-20 23:52:15,896 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.version=2.6.18-164.6.1.el5
          2010-07-20 23:52:15,897 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.name=root
          2010-07-20 23:52:15,897 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.home=/root
          2010-07-20 23:52:15,897 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.dir=/
          2010-07-20 23:52:15,899 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@151] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /data/zookeeper/txlog/version-2 snapdir /data/zookeeper/version-2
          2010-07-20 23:52:15,911 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@285] - Getting a snapshot from leader
          2010-07-20 23:52:16,152 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@315] - Setting leader epoch 26
          2010-07-20 23:52:16,166 - INFO  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@208] - Snapshotting: 260000195d
          2010-07-20 23:52:16,200 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.21.181:49189
          2010-07-20 23:52:16,200 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1314] - Processing stat command from /10.209.21.181:49189
          2010-07-20 23:52:16,203 - INFO  [Thread-6:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:49189 (no session established for client)
          2010-07-20 23:52:16,446 - WARN  [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@116] - Got zxid 0x260000195e expected 0x1
          2010-07-20 23:52:16,446 - INFO  [SyncThread:1:FileTxnLog@197] - Creating new log file: log.260000195e
          2010-07-20 23:52:19,205 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.21.181:49192
          2010-07-20 23:52:19,205 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1314] - Processing stat command from /10.209.21.181:49192
          2010-07-20 23:52:19,206 - INFO  [Thread-7:NIOServerCnxn$StatCommand@1167] - Stat command output
          2010-07-20 23:52:19,208 - INFO  [Thread-7:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:49192 (no session established for client)
          2010-07-20 23:52:20,562 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.44.180:47281
          2010-07-20 23:52:20,564 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@782] - Client attempting to establish new session at /10.209.44.180:47281
          2010-07-20 23:52:20,574 - INFO  [CommitProcessor:1:NIOServerCnxn@1661] - Established session 0x129f245a01c0000 with negotiated timeout 10000 for client /10.209.44.180:47281
          2010-07-20 23:52:20,581 - INFO  [CommitProcessor:1:PrepRequestProcessor@69] - zookeeper.skipACL=="yes", ACL checks will be skipped
          2010-07-20 23:52:20,586 - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129f245a01c0000, likely client has closed socket
          2010-07-20 23:52:20,587 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.44.180:47281 which had sessionid 0x129f245a01c0000
          2010-07-20 23:52:20,826 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.48.78:52838
          2010-07-20 23:52:20,827 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@782] - Client attempting to establish new session at /10.209.48.78:52838
          2010-07-20 23:52:20,829 - INFO  [CommitProcessor:1:NIOServerCnxn@1661] - Established session 0x129f245a01c0001 with negotiated timeout 10000 for client /10.209.48.78:52838
          2010-07-20 23:52:20,832 - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129f245a01c0001, likely client has closed socket
          2010-07-20 23:52:20,833 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.48.78:52838 which had sessionid 0x129f245a01c0001
          2010-07-20 23:52:22,210 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.21.181:49197
          2010-07-20 23:52:22,210 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1314] - Processing stat command from /10.209.21.181:49197
          2010-07-20 23:52:22,211 - INFO  [Thread-8:NIOServerCnxn$StatCommand@1167] - Stat command output
          2010-07-20 23:52:22,227 - INFO  [Thread-8:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:49197 (no session established for client)
          2010-07-20 23:52:22,551 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.45.104:42183
          2010-07-20 23:52:22,552 - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@782] - Client attempting to establish new session at /10.209.45.104:42183
          2010-07-20 23:52:22,554 - INFO  [CommitProcessor:1:NIOServerCnxn@1661] - Established session 0x129f245a01c0002 with negotiated timeout 10000 for client /10.209.45.104:42183
          2010-07-20 23:52:22,560 - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129f245a01c0002, likely client has closed socket
          
          Show
          Travis Crawford added a comment - I tested this patch on a build with the following, applied in the listed order: 3.3.1 release + ZOOKEEPER-744 .patch + ZOOKEEPER-790 -3.3.patch Looks good! 2010-07-20 23:43:34,229 - INFO [ Thread -2545:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:53743 (no session established for client) 2010-07-20 23:43:34,659 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129d3fcb5a6f60d, likely client has closed socket 2010-07-20 23:43:34,660 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.204:59727 which had sessionid 0x129d3fcb5a6f60d 2010-07-20 23:43:34,684 - INFO [ProcessThread:-1:PrepRequestProcessor@385] - Processed session termination for sessionid: 0x329d3fcb6594e53 2010-07-20 23:52:14,522 - INFO [main:QuorumPeerConfig@90] - Reading configuration from: /etc/zookeeper/conf/zoo.cfg 2010-07-20 23:52:14,529 - INFO [main:QuorumPeerConfig@287] - Defaulting to majority quorums 2010-07-20 23:52:14,540 - INFO [main:QuorumPeerMain@119] - Starting quorum peer 2010-07-20 23:52:14,562 - INFO [main:NIOServerCnxn$Factory@149] - binding to port 0.0.0.0/0.0.0.0:2181 2010-07-20 23:52:14,578 - INFO [main:QuorumPeer@818] - tickTime set to 2000 2010-07-20 23:52:14,579 - INFO [main:QuorumPeer@829] - minSessionTimeout set to -1 2010-07-20 23:52:14,579 - INFO [main:QuorumPeer@840] - maxSessionTimeout set to -1 2010-07-20 23:52:14,579 - INFO [main:QuorumPeer@855] - initLimit set to 10 2010-07-20 23:52:14,798 - INFO [main:FileSnap@82] - Reading snapshot /data/zookeeper/version-2/snapshot.2500197ee5 2010-07-20 23:52:15,660 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.45.76:57030 2010-07-20 23:52:15,661 - INFO [ Thread -1:QuorumCnxManager$Listener@436] - My election bind port: 3888 2010-07-20 23:52:15,663 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@644] - Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running 2010-07-20 23:52:15,664 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.45.76:57030 (no session established for client) 2010-07-20 23:52:15,670 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@620] - LOOKING 2010-07-20 23:52:15,672 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@649] - New election. My id = 1, Proposed zxid = 158915472832 2010-07-20 23:52:15,674 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 1, 158915472832, 1, 1, LOOKING, LOOKING, 1 2010-07-20 23:52:15,674 - INFO [WorkerSender Thread :QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (2, 1) 2010-07-20 23:52:15,675 - INFO [WorkerSender Thread :QuorumCnxManager@162] - Have smaller server identifier, so dropping the connection: (3, 1) 2010-07-20 23:52:15,676 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 2, 158915472832, 5, 1, LOOKING, LOOKING, 2 2010-07-20 23:52:15,676 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 3, 158915472832, 5, 1, LOOKING, LOOKING, 2 2010-07-20 23:52:15,676 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@711] - Updating proposal 2010-07-20 23:52:15,677 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@799] - Notification: 3, 158915472832, 5, 1, LOOKING, FOLLOWING, 2 2010-07-20 23:52:15,677 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FastLeaderElection@689] - Notification: 3, 158915472832, 5, 1, LOOKING, LOOKING, 3 2010-07-20 23:52:15,879 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:QuorumPeer@642] - FOLLOWING 2010-07-20 23:52:15,885 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@72] - TCP NoDelay set to: true 2010-07-20 23:52:15,893 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:zookeeper.version=3.3.1-942149, built on 05/07/2010 17:14 GMT 2010-07-20 23:52:15,893 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:host.name=sjc1k029.twitter.com 2010-07-20 23:52:15,894 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.version=1.6.0_16 2010-07-20 23:52:15,894 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.vendor=Sun Microsystems Inc. 2010-07-20 23:52:15,894 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.home=/usr/java/jdk1.6.0_16/jre 2010-07-20 23:52:15,894 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.class.path=/etc/zookeeper/conf::/usr/local/zookeeper/../zookeeper-*.jar:/usr/local/zookeeper/../lib/*.jar:/usr/local/zookeeper/../src/java/lib/*.jar:/usr/local/zookeeper/jline-0.9.94.jar:/usr/local/zookeeper/log4j-1.2.15.jar:/usr/local/zookeeper/zookeeper-3.3.2-dev.jar 2010-07-20 23:52:15,895 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.library.path=/usr/java/jdk1.6.0_16/jre/lib/amd64/server:/usr/java/jdk1.6.0_16/jre/lib/amd64:/usr/java/jdk1.6.0_16/jre/../lib/amd64:/usr/java/packages/lib/amd64:/lib:/usr/lib 2010-07-20 23:52:15,895 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.io.tmpdir=/tmp 2010-07-20 23:52:15,895 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:java.compiler=<NA> 2010-07-20 23:52:15,896 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.name=Linux 2010-07-20 23:52:15,896 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.arch=amd64 2010-07-20 23:52:15,896 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:os.version=2.6.18-164.6.1.el5 2010-07-20 23:52:15,897 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.name=root 2010-07-20 23:52:15,897 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.home=/root 2010-07-20 23:52:15,897 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:user.dir=/ 2010-07-20 23:52:15,899 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@151] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /data/zookeeper/txlog/version-2 snapdir /data/zookeeper/version-2 2010-07-20 23:52:15,911 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@285] - Getting a snapshot from leader 2010-07-20 23:52:16,152 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Learner@315] - Setting leader epoch 26 2010-07-20 23:52:16,166 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@208] - Snapshotting: 260000195d 2010-07-20 23:52:16,200 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.21.181:49189 2010-07-20 23:52:16,200 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1314] - Processing stat command from /10.209.21.181:49189 2010-07-20 23:52:16,203 - INFO [ Thread -6:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:49189 (no session established for client) 2010-07-20 23:52:16,446 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Follower@116] - Got zxid 0x260000195e expected 0x1 2010-07-20 23:52:16,446 - INFO [SyncThread:1:FileTxnLog@197] - Creating new log file: log.260000195e 2010-07-20 23:52:19,205 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.21.181:49192 2010-07-20 23:52:19,205 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1314] - Processing stat command from /10.209.21.181:49192 2010-07-20 23:52:19,206 - INFO [ Thread -7:NIOServerCnxn$StatCommand@1167] - Stat command output 2010-07-20 23:52:19,208 - INFO [ Thread -7:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:49192 (no session established for client) 2010-07-20 23:52:20,562 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.44.180:47281 2010-07-20 23:52:20,564 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@782] - Client attempting to establish new session at /10.209.44.180:47281 2010-07-20 23:52:20,574 - INFO [CommitProcessor:1:NIOServerCnxn@1661] - Established session 0x129f245a01c0000 with negotiated timeout 10000 for client /10.209.44.180:47281 2010-07-20 23:52:20,581 - INFO [CommitProcessor:1:PrepRequestProcessor@69] - zookeeper.skipACL== "yes" , ACL checks will be skipped 2010-07-20 23:52:20,586 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129f245a01c0000, likely client has closed socket 2010-07-20 23:52:20,587 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.44.180:47281 which had sessionid 0x129f245a01c0000 2010-07-20 23:52:20,826 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.48.78:52838 2010-07-20 23:52:20,827 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@782] - Client attempting to establish new session at /10.209.48.78:52838 2010-07-20 23:52:20,829 - INFO [CommitProcessor:1:NIOServerCnxn@1661] - Established session 0x129f245a01c0001 with negotiated timeout 10000 for client /10.209.48.78:52838 2010-07-20 23:52:20,832 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129f245a01c0001, likely client has closed socket 2010-07-20 23:52:20,833 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1516] - Closed socket connection for client /10.209.48.78:52838 which had sessionid 0x129f245a01c0001 2010-07-20 23:52:22,210 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.21.181:49197 2010-07-20 23:52:22,210 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1314] - Processing stat command from /10.209.21.181:49197 2010-07-20 23:52:22,211 - INFO [ Thread -8:NIOServerCnxn$StatCommand@1167] - Stat command output 2010-07-20 23:52:22,227 - INFO [ Thread -8:NIOServerCnxn@1516] - Closed socket connection for client /10.209.21.181:49197 (no session established for client) 2010-07-20 23:52:22,551 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@256] - Accepted socket connection from /10.209.45.104:42183 2010-07-20 23:52:22,552 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@782] - Client attempting to establish new session at /10.209.45.104:42183 2010-07-20 23:52:22,554 - INFO [CommitProcessor:1:NIOServerCnxn@1661] - Established session 0x129f245a01c0002 with negotiated timeout 10000 for client /10.209.45.104:42183 2010-07-20 23:52:22,560 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - EndOfStreamException: Unable to read additional data from client sessionid 0x129f245a01c0002, likely client has closed socket
          Hide
          Travis Crawford added a comment -

          Just to double-check, I'm really really sure the running jar was freshly built. For example, lsof says:

          java 4473 root mem REG 104,1 1012397 10092999 /usr/local/zookeeper/zookeeper-3.3.2-dev.jar

          Yes, the version number is 3.3.2, but this was built from the 3.3.1 release.

          Looking in the log we see:

          2010-07-20 23:52:15,893 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:zookeeper.version=3.3.1-942149, built on 05/07/2010 17:14 GMT

          Should that say built this afternoon? I've double & tripled checked and believe this is a newly built jar. Looking in the tarball we don't see zookeeper-3.3.2-dev.jar until after building.

          Show
          Travis Crawford added a comment - Just to double-check, I'm really really sure the running jar was freshly built. For example, lsof says: java 4473 root mem REG 104,1 1012397 10092999 /usr/local/zookeeper/zookeeper-3.3.2-dev.jar Yes, the version number is 3.3.2, but this was built from the 3.3.1 release. Looking in the log we see: 2010-07-20 23:52:15,893 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:Environment@97] - Server environment:zookeeper.version=3.3.1-942149, built on 05/07/2010 17:14 GMT Should that say built this afternoon? I've double & tripled checked and believe this is a newly built jar. Looking in the tarball we don't see zookeeper-3.3.2-dev.jar until after building.
          Hide
          Flavio Junqueira added a comment -

          I realized that while working on the patch I removed a private modifier and forgot to add it back for the trunk patch, so I'm uploading an new patch. There is no other significant modification to the patch.

          Show
          Flavio Junqueira added a comment - I realized that while working on the patch I removed a private modifier and forgot to add it back for the trunk patch, so I'm uploading an new patch. There is no other significant modification to the patch.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790.patch [ 12450033 ]
          Hide
          Flavio Junqueira added a comment -

          Just in case will cancel and resubmit.

          Show
          Flavio Junqueira added a comment - Just in case will cancel and resubmit.
          Flavio Junqueira made changes -
          Status Patch Available [ 10002 ] Open [ 1 ]
          Flavio Junqueira made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Hide
          Benjamin Reed added a comment -

          looks great flavio! the only nit i have is that the test case assumes that s1 is not the leader. you might want to check that.

          Show
          Benjamin Reed added a comment - looks great flavio! the only nit i have is that the test case assumes that s1 is not the leader. you might want to check that.
          Flavio Junqueira made changes -
          Status Patch Available [ 10002 ] Open [ 1 ]
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790-3.3.patch [ 12450186 ]
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790.patch [ 12450187 ]
          Hide
          Flavio Junqueira added a comment -

          Thank for reviewing, Ben. Resubmitting with the proposed fix.

          Thanks for testing the patch, Travis. I don't really know why you're observing the wrong dates, though. Anyone else?

          Show
          Flavio Junqueira added a comment - Thank for reviewing, Ben. Resubmitting with the proposed fix. Thanks for testing the patch, Travis. I don't really know why you're observing the wrong dates, though. Anyone else?
          Flavio Junqueira made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Hide
          Benjamin Reed added a comment -

          +1 great job flavio! thanx for your help travis and vishal.

          Show
          Benjamin Reed added a comment - +1 great job flavio! thanx for your help travis and vishal.
          Benjamin Reed made changes -
          Hadoop Flags [Reviewed]
          Hide
          Patrick Hunt added a comment -

          I believe the problem found by Travis is a bug in the build for 3.3.1. If you d/l the latest release, patch it, and run "ant jar" this is included into the output:

          version-info:
          [java] All version-related parameters must be valid integers!
          [java] Exception in thread "main" java.lang.NumberFormatException: For input string: "2-dev"
          [java] at java.lang.NumberFormatException.forInputString(NumberFormatException.java:48)
          [java] at java.lang.Integer.parseInt(Integer.java:458)
          [java] at java.lang.Integer.parseInt(Integer.java:499)
          [java] at org.apache.zookeeper.version.util.VerGen.main(VerGen.java:131)
          [java] Java Result: 1

          the build doesn't fail as the generated Version.java exists in the release, as a result you get the original Version.java, and therefore the old date.

          You can see this better by doing a "ant clean jar", which will fail as the Version.java is cleaned by running ant clean. You can get around this
          problem by running "ant -Dversion=3.3.2 clean jar" (a valid version string), after which you should see the current date in the log.

          I'll fix this in the next rel.

          Show
          Patrick Hunt added a comment - I believe the problem found by Travis is a bug in the build for 3.3.1. If you d/l the latest release, patch it, and run "ant jar" this is included into the output: version-info: [java] All version-related parameters must be valid integers! [java] Exception in thread "main" java.lang.NumberFormatException: For input string: "2-dev" [java] at java.lang.NumberFormatException.forInputString(NumberFormatException.java:48) [java] at java.lang.Integer.parseInt(Integer.java:458) [java] at java.lang.Integer.parseInt(Integer.java:499) [java] at org.apache.zookeeper.version.util.VerGen.main(VerGen.java:131) [java] Java Result: 1 the build doesn't fail as the generated Version.java exists in the release, as a result you get the original Version.java, and therefore the old date. You can see this better by doing a "ant clean jar", which will fail as the Version.java is cleaned by running ant clean. You can get around this problem by running "ant -Dversion=3.3.2 clean jar" (a valid version string), after which you should see the current date in the log. I'll fix this in the next rel.
          Hide
          Benjamin Reed added a comment -

          Committed revision 966960.
          Committed revision 966984.

          Show
          Benjamin Reed added a comment - Committed revision 966960. Committed revision 966984.
          Benjamin Reed made changes -
          Status Patch Available [ 10002 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Hide
          Hudson added a comment -

          Integrated in ZooKeeper-trunk #884 (See http://hudson.zones.apache.org/hudson/job/ZooKeeper-trunk/884/)
          ZOOKEEPER-790. Last processed zxid set prematurely while establishing leadership (fpj via breed)

          Show
          Hudson added a comment - Integrated in ZooKeeper-trunk #884 (See http://hudson.zones.apache.org/hudson/job/ZooKeeper-trunk/884/ ) ZOOKEEPER-790 . Last processed zxid set prematurely while establishing leadership (fpj via breed)
          Hide
          Sergey Doroshenko added a comment -

          It seems this patch introduces a bug: followers get synchronized with leader and start serving clients before leader startups its own zk instance.
          As the result, when a follower forward request to the leader, for example session revalidation request, it fails because leader's sessionTracker is null.

          Previously this was not the case because leader started its zk immediately after quorum peer is switched to LEADING state.

          See attached log.

          Show
          Sergey Doroshenko added a comment - It seems this patch introduces a bug: followers get synchronized with leader and start serving clients before leader startups its own zk instance. As the result, when a follower forward request to the leader, for example session revalidation request, it fails because leader's sessionTracker is null. Previously this was not the case because leader started its zk immediately after quorum peer is switched to LEADING state. See attached log.
          Sergey Doroshenko made changes -
          Attachment ZOOKEEPER-790-follower-request-NPE.log [ 12450504 ]
          Hide
          Sergey Doroshenko added a comment -

          Easy way to reproduce:

          • start 2 out of 3 peers
          • connect to the ensemble by zkCli.sh
          • shutdown a peer, wait a bit
          • start the peer
            Due to NPE (which is not seen in logs however) servers can't form a quorum, and client is unable to reconnect.
          Show
          Sergey Doroshenko added a comment - Easy way to reproduce: start 2 out of 3 peers connect to the ensemble by zkCli.sh shutdown a peer, wait a bit start the peer Due to NPE (which is not seen in logs however) servers can't form a quorum, and client is unable to reconnect.
          Hide
          Vishal Kher added a comment -

          Hi Flavio,

          Apologies for not trying the patch sooner. I will try out the patch soon (altough Sergey has pointed out a potential problem).

          I am still not conviced why the other two nodes that have formed the cluster are in LOOKING state?
          You mentioned that - "The notifications of 1 and 2 say looking because they have been queued at the time 1 and 2 were looking for a leader. That's not an issue".

          However, in this case, we have failed a follower and not a leader. Why would failure of a follower cause the other two nodes (including the leader) to start looking for a leader?
          Am I missing something?

          Thanks.
          -Vishal

          Show
          Vishal Kher added a comment - Hi Flavio, Apologies for not trying the patch sooner. I will try out the patch soon (altough Sergey has pointed out a potential problem). I am still not conviced why the other two nodes that have formed the cluster are in LOOKING state? You mentioned that - "The notifications of 1 and 2 say looking because they have been queued at the time 1 and 2 were looking for a leader. That's not an issue". However, in this case, we have failed a follower and not a leader. Why would failure of a follower cause the other two nodes (including the leader) to start looking for a leader? Am I missing something? Thanks. -Vishal
          Flavio Junqueira made changes -
          Resolution Fixed [ 1 ]
          Status Resolved [ 5 ] Reopened [ 4 ]
          Hide
          Flavio Junqueira added a comment -

          Thanks for pointing this issue out, Sergei. It sounds like the previous patch solved the issue discussed without making sure that the leader was ready to process messages when learner handlers started to read them in. This v2 patch does a number of things:

          1. It moves the startup method to processAck. This way we make sure that start up the leader as soon as we have a quorum of acks for the newleader message;
          2. It moves the initialization of the database in startup to a method startdata. There are two reasons for doing it. First, it didn't sound like a good idea to throw exceptions or catch exceptions in processAck, and they were only necessary because of the call to startup(). Second, the method startup() in ZooKeeperServer throws these exceptions because of loadData(), which is called separately in Leader.lead(), so it is not necessary to call it in processAck after hearing from a quorum;
          3. It waits in LearnerHandler.run() until the leader ready before it starts the while(true) loop. I also had to receive an ack before executing the code to wait, otherwise the leader would never receive acks and form a quorum, thus causing the system to halt.

          To get some feedback on the changes implemented in this patch, I have discussed them with Ben. Thanks, Ben!

          Sergei, I would appreciate if you could give it a try, and if you could tell me if it works for you.

          Show
          Flavio Junqueira added a comment - Thanks for pointing this issue out, Sergei. It sounds like the previous patch solved the issue discussed without making sure that the leader was ready to process messages when learner handlers started to read them in. This v2 patch does a number of things: It moves the startup method to processAck. This way we make sure that start up the leader as soon as we have a quorum of acks for the newleader message; It moves the initialization of the database in startup to a method startdata. There are two reasons for doing it. First, it didn't sound like a good idea to throw exceptions or catch exceptions in processAck, and they were only necessary because of the call to startup(). Second, the method startup() in ZooKeeperServer throws these exceptions because of loadData(), which is called separately in Leader.lead(), so it is not necessary to call it in processAck after hearing from a quorum; It waits in LearnerHandler.run() until the leader ready before it starts the while(true) loop. I also had to receive an ack before executing the code to wait, otherwise the leader would never receive acks and form a quorum, thus causing the system to halt. To get some feedback on the changes implemented in this patch, I have discussed them with Ben. Thanks, Ben! Sergei, I would appreciate if you could give it a try, and if you could tell me if it works for you.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790.v2.patch [ 12450534 ]
          Hide
          Flavio Junqueira added a comment -

          Hi VIshal, Thanks for testing as well. The issue you mention about the LOOKING state, if I understand correctly, is not about the state of the server, but the state reported in the notification.
          If so, then it happens because we always repeat the last message sent. Such duplicate messages cause what you have observed, but they are supposed to be harmless, in the sense that
          I do not expect them to lead to any inconsistency in the ZooKeeper service. Instead, it may only cause some periods in which some process believes incorrectly to be the leader, but again,
          the service is robust to such scenarios.

          Show
          Flavio Junqueira added a comment - Hi VIshal, Thanks for testing as well. The issue you mention about the LOOKING state, if I understand correctly, is not about the state of the server, but the state reported in the notification. If so, then it happens because we always repeat the last message sent. Such duplicate messages cause what you have observed, but they are supposed to be harmless, in the sense that I do not expect them to lead to any inconsistency in the ZooKeeper service. Instead, it may only cause some periods in which some process believes incorrectly to be the leader, but again, the service is robust to such scenarios.
          Hide
          Flavio Junqueira added a comment -

          The latest patch applies to both trunk and 3.3.

          Show
          Flavio Junqueira added a comment - The latest patch applies to both trunk and 3.3.
          Flavio Junqueira made changes -
          Status Reopened [ 4 ] Patch Available [ 10002 ]
          Hide
          Patrick Hunt added a comment -

          Great catch Sergei, thanks!

          Show
          Patrick Hunt added a comment - Great catch Sergei, thanks!
          Hide
          Patrick Hunt added a comment -

          Would be great to have a test for this latest change.

          Show
          Patrick Hunt added a comment - Would be great to have a test for this latest change.
          Hide
          Sergey Doroshenko added a comment -

          Hey Flavio,
          Patch works ok: passes both manual testing and my unit test which was previously failing.
          It looks conceptually correct, I'd give it +1 if I'd have such authority

          Show
          Sergey Doroshenko added a comment - Hey Flavio, Patch works ok: passes both manual testing and my unit test which was previously failing. It looks conceptually correct, I'd give it +1 if I'd have such authority
          Hide
          Mahadev konar added a comment -

          sergey,
          your +1 does count . Also, can you please upload the testcase that was failing? It would be good to include the testcase with the patch as pat mentioned above.

          Show
          Mahadev konar added a comment - sergey, your +1 does count . Also, can you please upload the testcase that was failing? It would be good to include the testcase with the patch as pat mentioned above.
          Hide
          Sergey Doroshenko added a comment -

          The test that was failing was the test for r/o mode, so it wouldn't apply here.

          I've extracted necessary code from it and made it a test case in QuorumTest. It fails against current trunk but passes against latest patch.

          This test case uses QuorumUtil which I also extracted from my r/o mode patch. I made it for convenient quorum testing, it's more handy than current QuorumBase, and I plan to make QuorumBase a special case of it.

          Show
          Sergey Doroshenko added a comment - The test that was failing was the test for r/o mode, so it wouldn't apply here. I've extracted necessary code from it and made it a test case in QuorumTest. It fails against current trunk but passes against latest patch. This test case uses QuorumUtil which I also extracted from my r/o mode patch. I made it for convenient quorum testing, it's more handy than current QuorumBase, and I plan to make QuorumBase a special case of it.
          Sergey Doroshenko made changes -
          Attachment ZOOKEEPER-790-test.patch [ 12450584 ]
          Hide
          Sergey Doroshenko added a comment -

          btw, Flavio, there are a few lines with trailing whitespaces in your patch, fix them

          Show
          Sergey Doroshenko added a comment - btw, Flavio, there are a few lines with trailing whitespaces in your patch, fix them
          Hide
          Flavio Junqueira added a comment -

          Submitting a new patch right after.

          Show
          Flavio Junqueira added a comment - Submitting a new patch right after.
          Flavio Junqueira made changes -
          Status Patch Available [ 10002 ] Open [ 1 ]
          Hide
          Flavio Junqueira added a comment -

          Thanks for providing a code base for the test, Sergey. I liked QuorumUtil so much that I have reimplemented the previous test to use it. This is in fact aligned with a discussion Ben and I had the other day about refactoring QuorumBase. You have introduced pretty much all functionality I was looking for, which simplified the test code.

          I hope you don't mind that I have made some modifications to your original test. My proposed modifications are to make sure that we induce the right set of events. In the modified version, I have made sure that we have a client connecting to a follower and that we kill the leader so that we force a new election. In fact, the test was not always reliable for me in its original form.

          The patch works for me.

          Show
          Flavio Junqueira added a comment - Thanks for providing a code base for the test, Sergey. I liked QuorumUtil so much that I have reimplemented the previous test to use it. This is in fact aligned with a discussion Ben and I had the other day about refactoring QuorumBase. You have introduced pretty much all functionality I was looking for, which simplified the test code. I hope you don't mind that I have made some modifications to your original test. My proposed modifications are to make sure that we induce the right set of events. In the modified version, I have made sure that we have a client connecting to a follower and that we kill the leader so that we force a new election. In fact, the test was not always reliable for me in its original form. The patch works for me.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790.v2.patch [ 12450598 ]
          Hide
          Flavio Junqueira added a comment -

          Need to generate a version for 3.3, but the one uploaded is ready to be reviewed for me.

          Show
          Flavio Junqueira added a comment - Need to generate a version for 3.3, but the one uploaded is ready to be reviewed for me.
          Flavio Junqueira made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Hide
          Benjamin Reed added a comment -

          +1 excellent work you guys. i also like QuorumUtil sergey! thanx for implementing it.

          Show
          Benjamin Reed added a comment - +1 excellent work you guys. i also like QuorumUtil sergey! thanx for implementing it.
          Hide
          Mahadev konar added a comment - - edited

          flavio, the patch looks good. Any reason you have this code in learnerhandler?

          @@ -475,6 +497,7 @@
                   } catch (IOException e) {
                       LOG.warn("Ignoring unexpected exception during socket close", e);
                   }
          +        this.interrupt();
                   leader.removeLearnerHandler(this);
               }
           
          

          The interrupt? Why is this necessary?

          Show
          Mahadev konar added a comment - - edited flavio, the patch looks good. Any reason you have this code in learnerhandler? @@ -475,6 +497,7 @@ } catch (IOException e) { LOG.warn( "Ignoring unexpected exception during socket close" , e); } + this .interrupt(); leader.removeLearnerHandler( this ); } The interrupt? Why is this necessary?
          Hide
          Flavio Junqueira added a comment -

          Thanks for reviewing, Mahadev. The interrupt is necessary to guarantee that we will break this loop:

          +            /*
          +             * Wait until leader starts up
          +             */
          +            synchronized(leader.zk){
          +                while(!leader.zk.isRunning()){
          +                    leader.zk.wait(500);
          +                }
          +            }
          

          when shutting down the learner handler.

          Show
          Flavio Junqueira added a comment - Thanks for reviewing, Mahadev. The interrupt is necessary to guarantee that we will break this loop: + /* + * Wait until leader starts up + */ + synchronized(leader.zk){ + while(!leader.zk.isRunning()){ + leader.zk.wait(500); + } + } when shutting down the learner handler.
          Flavio Junqueira made changes -
          Status Patch Available [ 10002 ] Open [ 1 ]
          Hide
          Flavio Junqueira added a comment -

          Fixed issue pointed out by Mahadev. Submitting patch for 3.3 first.

          Show
          Flavio Junqueira added a comment - Fixed issue pointed out by Mahadev. Submitting patch for 3.3 first.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790-3.3.v2.patch [ 12450761 ]
          Hide
          Flavio Junqueira added a comment -

          Now uploading trunk version.

          Show
          Flavio Junqueira added a comment - Now uploading trunk version.
          Flavio Junqueira made changes -
          Attachment ZOOKEEPER-790.v2.patch [ 12450762 ]
          Flavio Junqueira made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Hide
          Vishal Kher added a comment -

          Hi,

          I tested the patch and it works really well. I have a test that fails and restarts zookeeper server in a loop. I kept it going for 150 rounds and found no issues.
          Thanks a lot.

          -Vishal

          Show
          Vishal Kher added a comment - Hi, I tested the patch and it works really well. I have a test that fails and restarts zookeeper server in a loop. I kept it going for 150 rounds and found no issues. Thanks a lot. -Vishal
          Hide
          Mahadev konar added a comment -

          +1 the patch looks good. I will go ahead and commit it.

          Show
          Mahadev konar added a comment - +1 the patch looks good. I will go ahead and commit it.
          Hide
          Mahadev konar added a comment -

          I just committed this. thanks flavio and others!

          Show
          Mahadev konar added a comment - I just committed this. thanks flavio and others!
          Mahadev konar made changes -
          Status Patch Available [ 10002 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Hide
          Hudson added a comment -

          Integrated in ZooKeeper-trunk #890 (See http://hudson.zones.apache.org/hudson/job/ZooKeeper-trunk/890/)
          ZOOKEEPER-790. Last processed zxid set prematurely while establishing leadership (flavio via mahadev)

          Show
          Hudson added a comment - Integrated in ZooKeeper-trunk #890 (See http://hudson.zones.apache.org/hudson/job/ZooKeeper-trunk/890/ ) ZOOKEEPER-790 . Last processed zxid set prematurely while establishing leadership (flavio via mahadev)
          Mahadev konar made changes -
          Status Resolved [ 5 ] Closed [ 6 ]

            People

            • Assignee:
              Flavio Junqueira
              Reporter:
              Flavio Junqueira
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development