[
https://issues.apache.org/jira/browse/ZOOKEEPER-2705?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15880700#comment-15880700
]
Edward Ribeiro commented on ZOOKEEPER-2705:
-------------------------------------------
Hi [~stondofitz],
Looks like you hit https://issues.apache.org/jira/browse/ZOOKEEPER-2464 that
was recently fixed by https://issues.apache.org/jira/browse/ZOOKEEPER-2680
TL;DR: {{DataNode.getChildren()}} could either return an empty collection or
null, and this broke ContainerManager at line 151, as shown in your log.
Could you confirm it is the same issue, please?
> Container node remains indefinitely after session has long expired!
> -------------------------------------------------------------------
>
> Key: ZOOKEEPER-2705
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2705
> Project: ZooKeeper
> Issue Type: Bug
> Components: quorum
> Affects Versions: 3.5.1
> Environment: 5 x RHEL 2.6.32-431.29.2.el6.x86_64
> Reporter: Steve Fitzgerald
>
> 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:
> {noformat}
> 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
> {noformat}
> 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?
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
