Uploaded image for project: 'ZooKeeper'
  1. ZooKeeper
  2. ZOOKEEPER-1700

FLETest consistently failing - setLastSeenQuorumVerifier seems to be hanging

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 3.5.0
    • Fix Version/s: 3.5.0
    • Component/s: quorum
    • Labels:
      None

      Description

      I'm consistently seeing a failure on my laptop when running the FLETest "testJoin" test. What seems to be happening is that the call to setLastSeenQuorumVerifier is hanging.

      See the following log from the test, notice 17:35:57 for the period in question. Note that I turned on debug logging and added a few log messages around the call to setLastSeenQuorumVerifier (you can see the code enter but never leave)

      Note: I've applied ZOOKEEPER-1324 to trunk code and then run this test but that doesn't seem to help. Also note that this test is passing consistently when run against branch-3.4.

      2013-05-07 17:35:57,859 [myid:] - INFO  [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11221:Follower@65] - FOLLOWING - LEADER ELECTION TOOK - 16
      2013-05-07 17:35:57,859 [myid:] - INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:Leader@436] - LEADING - LEADER ELECTION TOOK - 17
      2013-05-07 17:35:57,863 [myid:] - INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:FileTxnSnapLog@270] - Snapshotting: 0x0 to /home/phunt/dev/zookeeper-trunk/build/test/tmp/test3690487600947307322.junit.dir/version-2/snapshot.0
      2013-05-07 17:35:57,873 [myid:] - INFO  [LearnerHandler-/127.0.0.1:34262:LearnerHandler@269] - Follower sid: 0 : info : 0.0.0.0:11222:11223:participant;0.0.0.0:11221
      2013-05-07 17:35:57,878 [myid:] - INFO  [LearnerHandler-/127.0.0.1:34262:LearnerHandler@328] - Synchronizing with Follower sid: 0 maxCommittedLog=0x0 minCommittedLog=0x0 peerLastZxid=0x0
      2013-05-07 17:35:57,878 [myid:] - DEBUG [LearnerHandler-/127.0.0.1:34262:LearnerHandler@395] - committedLog is empty but leader and follower are in sync, zxid=0x0
      2013-05-07 17:35:57,878 [myid:] - INFO  [LearnerHandler-/127.0.0.1:34262:LearnerHandler@404] - Sending DIFF
      2013-05-07 17:35:57,879 [myid:] - DEBUG [LearnerHandler-/127.0.0.1:34262:LearnerHandler@411] - Sending NEWLEADER message to 0
      2013-05-07 17:35:57,880 [myid:] - INFO  [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11221:Learner@331] - Getting a diff from the leader 0x0
      2013-05-07 17:35:57,885 [myid:] - INFO  [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11221:Learner@457] - Learner received NEWLEADER message
      2013-05-07 17:35:57,885 [myid:] - INFO  [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11221:Learner@460] - NEWLEADER calling configfromstring
      2013-05-07 17:35:57,885 [myid:] - INFO  [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11221:Learner@462] - NEWLEADER setting quorum verifier
      2013-05-07 17:35:57,886 [myid:] - WARN  [QuorumPeer[myid=0]/0:0:0:0:0:0:0:0:11221:QuorumPeer@1218] - setLastSeenQuorumVerifier called with stale config 0. Current version: 0
      2013-05-07 17:36:01,880 [myid:] - INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:Leader@585] - Shutting down
      2013-05-07 17:36:01,881 [myid:] - INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:Leader@591] - Shutdown called
      java.lang.Exception: shutdown Leader! reason: Waiting for a quorum of followers, only synced with sids: [ [1] ]
      	at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:591)
      	at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:487)
      	at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:949)
      2013-05-07 17:36:01,881 [myid:] - INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:ZooKeeperServer@398] - shutting down
      2013-05-07 17:36:01,881 [myid:] - INFO  [LearnerCnxAcceptor-0.0.0.0/0.0.0.0:11225:Leader$LearnerCnxAcceptor@398] - exception while shutting down acceptor: java.net.SocketException: Socket closed
      2013-05-07 17:36:01,882 [myid:] - WARN  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:QuorumPeer@979] - PeerState set to LOOKING
      2013-05-07 17:36:01,882 [myid:] - INFO  [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:QuorumPeer@863] - LOOKING
      2013-05-07 17:36:01,883 [myid:] - DEBUG [QuorumPeer[myid=1]/0:0:0:0:0:0:0:0:11224:QuorumPeer@792] - Initializing leader election protocol...
      

        Attachments

        1. ZOOKEEPER-1700.patch
          0.6 kB
          Flavio Junqueira
        2. ZOOKEEPER-1700.patch
          2 kB
          Patrick Hunt

          Activity

            People

            • Assignee:
              phunt Patrick Hunt
              Reporter:
              phunt Patrick Hunt
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: