Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 4481F200C24 for ; Thu, 23 Feb 2017 13:24:54 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 430A9160B62; Thu, 23 Feb 2017 12:24:54 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 5FB18160B50 for ; Thu, 23 Feb 2017 13:24:53 +0100 (CET) Received: (qmail 80807 invoked by uid 500); 23 Feb 2017 12:24:52 -0000 Mailing-List: contact dev-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list dev@zookeeper.apache.org Received: (qmail 80794 invoked by uid 99); 23 Feb 2017 12:24:52 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 23 Feb 2017 12:24:52 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id DDEB318190C for ; Thu, 23 Feb 2017 12:24:51 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -1.999 X-Spam-Level: X-Spam-Status: No, score=-1.999 tagged_above=-999 required=6.31 tests=[KAM_LAZY_DOMAIN_SECURITY=1, RP_MATCHES_RCVD=-2.999] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id tu6-t8FQDt8X for ; Thu, 23 Feb 2017 12:24:49 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTP id 8B91C5F2C5 for ; Thu, 23 Feb 2017 12:24:48 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 595F9E05F0 for ; Thu, 23 Feb 2017 12:24:44 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 0FC9A2412D for ; Thu, 23 Feb 2017 12:24:44 +0000 (UTC) Date: Thu, 23 Feb 2017 12:24:44 +0000 (UTC) From: "Steve Fitzgerald (JIRA)" To: dev@zookeeper.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (ZOOKEEPER-2705) Container node remains indefinitely after session has long expired! MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Thu, 23 Feb 2017 12:24:54 -0000 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)