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

Container node remains indefinitely after session has long expired!

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Duplicate
    • 3.5.1
    • None
    • quorum
    • None

    • 5 x RHEL 2.6.32-431.29.2.el6.x86_64

    Description

      Zookeeper version: 3.5.1-alpha
      Curator Framework version: 3.2.0

      We have a 5 node cluster. When we register a service instance everything is created within zookeeper successfully, e.g. for a service names "fake-test-service" I can see the following created:

      1. /api/enablement/fake-test-service
      2. /api/enablement/fake-test-service/bb831396-5c55-4456-a7c0-5950ba294fd5

      When I abnormally kill (kill -9) the process that the service is registered from I expect both of the above to get removed by zookeeper when it expires the session. But only /api/enablement/fake-test-service/bb831396-5c55-4456-a7c0-5950ba294fd5 gets removed successfully.

      Here is a snippet of the log file:

      2017-02-23 05:50:00,977 [myid:5] - TRACE [SessionTracker:SessionTrackerImpl@208][] - Session closing: 0x502dbce4df60000
2017-02-23 05:50:00,977 [myid:5] - INFO  [SessionTracker:ZooKeeperServer@384][] - Expiring session 0x502dbce4df60000, timeout of 40000ms exceeded
2017-02-23 05:50:00,977 [myid:5] - INFO  [SessionTracker:QuorumZooKeeperServer@132][] - Submitting global closeSession request for session 0x502dbce4df60000
2017-02-23 05:50:00,977 [myid:5] - TRACE [ProcessThread(sid:5 cport:-1)::ZooTrace@90][] - :Psessionid:0x502dbce4df60000 type:closeSession cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
2017-02-23 05:50:00,978 [myid:5] - TRACE [ProcessThread(sid:5 cport:-1)::SessionTrackerImpl@208][] - Session closing: 0x502dbce4df60000
2017-02-23 05:50:00,978 [myid:5] - INFO  [ProcessThread(sid:5 cport:-1)::PrepRequestProcessor@649][] - Processed session termination for sessionid: 0x502dbce4df60000
2017-02-23 05:50:00,978 [myid:5] - DEBUG [ProcessThread(sid:5 cport:-1)::CommitProcessor@340][] - Processing request:: sessionid:0x502dbce4df60000 type:closeSession cxid:0x0 zxid:0x1d00000003 txntype:-11 reqpath:n/a
2017-02-23 05:50:00,978 [myid:5] - DEBUG [ProcessThread(sid:5 cport:-1)::Leader@1066][] - Proposing:: sessionid:0x502dbce4df60000 type:closeSession cxid:0x0 zxid:0x1d00000003 txntype:-11 reqpath:n/a
2017-02-23 05:50:00,981 [myid:5] - TRACE [SyncThread:5:Leader@787][] - Ack zxid: 0x1d00000003
2017-02-23 05:50:00,981 [myid:5] - TRACE [SyncThread:5:Leader@790][] - outstanding proposal: 0x1d00000003
2017-02-23 05:50:00,981 [myid:5] - TRACE [SyncThread:5:Leader@793][] - outstanding proposals all
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.164:38716:Leader@787][] - Ack zxid: 0x1d00000003
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.164:38716:Leader@790][] - outstanding proposal: 0x1d00000003
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.164:38716:Leader@793][] - outstanding proposals all
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.161:55588:Leader@787][] - Ack zxid: 0x1d00000003
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.161:55588:Leader@790][] - outstanding proposal: 0x1d00000003
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.161:55588:Leader@793][] - outstanding proposals all
2017-02-23 05:50:00,982 [myid:5] - DEBUG [LearnerHandler-/10.24.128.161:55588:CommitProcessor@327][] - Committing request:: sessionid:0x502dbce4df60000 type:closeSession cxid:0x0 zxid:0x1d00000003 txntype:-11 reqpath:n/a
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.162:47580:Leader@787][] - Ack zxid: 0x1d00000003
2017-02-23 05:50:00,982 [myid:5] - TRACE [LearnerHandler-/10.24.128.162:47580:Leader@793][] - outstanding proposals all
2017-02-23 05:50:00,983 [myid:5] - DEBUG [LearnerHandler-/10.24.128.162:47580:Leader@808][] - outstanding is 0
2017-02-23 05:50:00,983 [myid:5] - TRACE [LearnerHandler-/10.24.128.160:41119:Leader@787][] - Ack zxid: 0x1d00000003
2017-02-23 05:50:00,983 [myid:5] - TRACE [LearnerHandler-/10.24.128.160:41119:Leader@793][] - outstanding proposals all
2017-02-23 05:50:00,983 [myid:5] - DEBUG [LearnerHandler-/10.24.128.160:41119:Leader@808][] - outstanding is 0
2017-02-23 05:50:00,983 [myid:5] - DEBUG [CommitProcWorkThread-1:FinalRequestProcessor@91][] - Processing request:: sessionid:0x502dbce4df60000 type:closeSession cxid:0x0 zxid:0x1d00000003 txntype:-11 reqpath:n/a
2017-02-23 05:50:00,983 [myid:5] - TRACE [CommitProcWorkThread-1:ZooTrace@90][] - :Esessionid:0x502dbce4df60000 type:closeSession cxid:0x0 zxid:0x1d00000003 txntype:-11 reqpath:n/a
2017-02-23 05:50:00,983 [myid:5] - DEBUG [CommitProcWorkThread-1:DataTree@1034][] - Deleting ephemeral node /api/enablement/fake-test-service/bb831396-5c55-4456-a7c0-5950ba294fd5 for session 0x502dbce4df60000
2017-02-23 05:50:00,983 [myid:5] - DEBUG [CommitProcWorkThread-1:SessionTrackerImpl@218][] - Removing session 0x502dbce4df60000
2017-02-23 05:50:00,983 [myid:5] - TRACE [CommitProcWorkThread-1:ZooTrace@71][] - SessionTrackerImpl --- Removing session 0x502dbce4df60000
2017-02-23 05:50:00,984 [myid:5] - DEBUG [CommitProcWorkThread-1:NettyServerCnxnFactory@411][] - closeSession sessionid:0x361092599260774400
2017-02-23 05:50:00,984 [myid:5] - DEBUG [CommitProcWorkThread-1:NettyServerCnxnFactory@411][] - closeSession sessionid:0x361092599260774400
2017-02-23 05:50:03,525 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxnFactory$CnxnChannelHandler@156][] - message received called BigEndianHeapChannelBuffer(ridx=0, widx=12, cap=12)
2017-02-23 05:50:03,527 [myid:5] - DEBUG [New I/O worker #5:NettyServerCnxnFactory$CnxnChannelHandler@160][] - New message [id: 0xd28589b8, /10.24.128.113:41935 => /10.24.128.165:2281] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=12, cap=12) from [id: 0xd28589b8, /10.24.128.113:41935 => /10.24.128.165:2281]
2017-02-23 05:50:03,527 [myid:5] - DEBUG [New I/O worker #5:NettyServerCnxnFactory$CnxnChannelHandler@175][] - 502d2842d930004 queuedBuffer: null
2017-02-23 05:50:03,527 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxnFactory$CnxnChannelHandler@202][] - 502d2842d930004 buf 0x00000008fffffffe0000000b
2017-02-23 05:50:03,527 [myid:5] - DEBUG [New I/O worker #5:NettyServerCnxnFactory$CnxnChannelHandler@221][] - not throttled
2017-02-23 05:50:03,527 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@355][] - message readable 12 bblenrem 4
2017-02-23 05:50:03,528 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@360][] - 502d2842d930004 bbLen 0x
2017-02-23 05:50:03,528 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@375][] - 502d2842d930004 bbLen 0x00000008
2017-02-23 05:50:03,528 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@382][] - 502d2842d930004 bbLen len is 8
2017-02-23 05:50:03,528 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@302][] - message readable 8 bb len 8 java.nio.HeapByteBuffer[pos=0 lim=8 cap=8]
2017-02-23 05:50:03,529 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@306][] - 502d2842d930004 bb 0x
2017-02-23 05:50:03,529 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@320][] - after readBytes message readable 0 bb len 0 java.nio.HeapByteBuffer[pos=8 lim=8 cap=8]
2017-02-23 05:50:03,529 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxn@325][] - after readbytes 502d2842d930004 bb 0xfffffffe0000000b
2017-02-23 05:50:03,530 [myid:5] - DEBUG [ProcessThread(sid:5 cport:-1)::SessionTrackerImpl@291][] - Checking session 0x502d2842d930004
2017-02-23 05:50:03,530 [myid:5] - DEBUG [ProcessThread(sid:5 cport:-1)::CommitProcessor@340][] - Processing request:: sessionid:0x502d2842d930004 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
2017-02-23 05:50:03,530 [myid:5] - DEBUG [CommitProcWorkThread-1:FinalRequestProcessor@91][] - Processing request:: sessionid:0x502d2842d930004 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
2017-02-23 05:50:03,530 [myid:5] - DEBUG [CommitProcWorkThread-1:FinalRequestProcessor@178][] - sessionid:0x502d2842d930004 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
2017-02-23 05:50:03,531 [myid:5] - TRACE [New I/O worker #5:NettyServerCnxnFactory$CnxnChannelHandler@267][] - write complete [id: 0xd28589b8, /10.24.128.113:41935 => /10.24.128.165:2281] WRITTEN_AMOUNT: 85
2017-02-23 05:50:04,275 [myid:5] - ERROR [ContainerManagerTask:ContainerManager$1@84][] - Error checking containers
java.lang.NullPointerException
	at org.apache.zookeeper.server.ContainerManager.getCandidates(ContainerManager.java:151)
	at org.apache.zookeeper.server.ContainerManager.checkContainers(ContainerManager.java:111)
	at org.apache.zookeeper.server.ContainerManager$1.run(ContainerManager.java:78)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
2017-02-23 05:50:11,569 [myid:5] - TRACE [New I/O worker #2:NettyServerCnxnFactory$CnxnChannelHandler@156][] - message received called BigEndianHeapChannelBuffer(ridx=0, widx=12, cap=12)
2017-02-23 05:50:11,569 [myid:5] - DEBUG [New I/O worker #2:NettyServerCnxnFactory$CnxnChannelHandler@160][] - New message [id: 0x677c2a25, /10.157.130.185:60591 => /10.24.128.165:2181] RECEIVED: BigEndianHeapChannelBuffer(ridx=0, widx=12, cap=12) from [id: 0x677c2a25, /10.157.130.185:60591 => /10.24.128.165:2181]
2017-02-23 05:50:11,570 [myid:5] - DEBUG [New I/O worker #2:NettyServerCnxnFactory$CnxnChannelHandler@175][] - 10145a3f4f803e5 queuedBuffer: null
2017-02-23 05:50:11,570 [myid:5] - TRACE [New I/O worker #2:NettyServerCnxnFactory$CnxnChannelHandler@202][] - 10145a3f4f803e5 buf 0x00000008fffffffe0000000b

      I believe the NullPointerException in the log above is what makes it fail to remove the remaining /api/enablement/fake-test-service directory.

      Could someone shed some light on why this might be happening?

      Attachments

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. ZOOKEEPER-2464 NullPointerException on ContainerManager

          • Major - Major loss of function.
          • Closed

          Activity

            People

              Unassigned Unassigned
              stondofitz Steve Fitzgerald
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: