zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Edward Ribeiro (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (ZOOKEEPER-2705) Container node remains indefinitely after session has long expired!
Date Fri, 24 Feb 2017 16:05:44 GMT

    [ https://issues.apache.org/jira/browse/ZOOKEEPER-2705?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15882972#comment-15882972
] 

Edward Ribeiro commented on ZOOKEEPER-2705:
-------------------------------------------

I am afraid there's no timeline yet. But you can follow and engange on the undergoing discussion
about 3.5.x release at zookeeper-user mailing list thread below.

http://zookeeper-user.578899.n2.nabble.com/Query-3-5-x-version-as-alpha-td7582952.html

Cheers!

> 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