Steve Fitzgerald created ZOOKEEPER-2705:
-------------------------------------------
Summary: 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)
