zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Steve Fitzgerald (JIRA)" <j...@apache.org>
Subject [jira] [Created] (ZOOKEEPER-2705) Container node remains indefinitely after session has long expired!
Date Thu, 23 Feb 2017 12:24:44 GMT
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)

Mime
View raw message