Zookeeper, mail # user - Re: Ephemeral node not getting deleted

Ephemeral node not getting deleted

Deepa 2012-12-04, 10:53

Hi,

I have zookeeper cluster of size 3,with the following parameters set
across all the servers:
tickTime=2000
initLimit=10
syncLimit=5

Session timeout is set to 40sec and using zookeeper 3.4.4. My application
works something like this:
It creates ephemeral nodes if it can grab and serve a range from a list of
ranges . It basically creates 2 ephemerals if its successful in finding a
range. From the zookeeper server logs, I see that only one of the ephemeral
node is getting deleted while bringing down servers randomly and restarting
them.

Please find the log snippet below:

2012-12-03 19:22:52,360 [myid:2] - DEBUG
[FollowerRequestProcessor:2:CommitProcessor@171] - Processing request::
sessionid:0x23b6109f83e0001 type:createSession cxid:0x0
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
2012-12-03 19:22:52,362 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:CommitProcessor@161] - Committing
request:: sessionid:0x23b6109f83e0001 type:createSession cxid:0x0
zxid:0x3000000013 txntype:-10 reqpath:n/a
2012-12-03 19:22:52,362 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
sessionid:*0x23b6109f83e0001* type:createSession cxid:0x0 zxid:0x3000000013
txntype:-10 reqpath:n/a
2012-12-03 19:22:52,363 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@160] - sessionid:*0x23b6109f83e0001
*type:createSession cxid:0x0 zxid:0x3000000013 txntype:-10 reqpath:n/a
2012-12-03 19:22:52,364 [myid:2] - INFO
[CommitProcessor:2:ZooKeeperServer@595] - Established session
*0x23b6109f83e0001 *with negotiated timeout 40000 for client
/192.168.11.94:3566

2012-12-03 19:23:01,143 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
sessionid:*0x23b6109f83e0001 *type:create cxid:0x50bdb440 zxid:0x300000002d
txntype:1 reqpath:/CONFIGNODE/NP2147483647
2012-12-03 19:23:01,144 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@160] - sessionid:*0x23b6109f83e0001
*type:create cxid:0x50bdb440 zxid:0x300000002d txntype:1
reqpath:*/CONFIGNODE/NP2147483647*

2012-12-03 19:23:01,157 [myid:2] - DEBUG
[FollowerRequestProcessor:2:CommitProcessor@171] - Processing request::
sessionid:*0x23b6109f83e0001 *type:create cxid:0x50bdb444
zxid:0xfffffffffffffffe txntype:unknown reqpath:*/ACTIVE/NP2147483647*
2012-12-03 19:23:01,159 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:CommitProcessor@161] - Committing
request:: sessionid:0x23b6109f83e0001 type:create cxid:0x50bdb444
zxid:0x3000000032 txntype:1 reqpath:n/a
2012-12-03 19:23:01,159 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
sessionid:0x23b6109f83e0001 type:create cxid:0x50bdb444 zxid:0x3000000032
txntype:1 reqpath:/ACTIVE/NP2147483647
2012-12-03 19:23:01,160 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@160] - sessionid:0x23b6109f83e0001
type:create cxid:0x50bdb444 zxid:0x3000000032 txntype:1
reqpath:*/ACTIVE/NP2147483647*
2012-12-03 19:45:16,672 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
sessionid:0x23b6109f83e0001 type:ping cxid:0xfffffffffffffffe
zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
2012-12-03 19:45:16,672 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@160] - sessionid:0x23b6109f83e0001
type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown
reqpath:n/a
2012-12-03 19:45:26,966 [myid:2] - WARN
[RecvWorker:1:QuorumCnxManager$RecvWorker@762] - Connection broken for id 1,
my id = 2, error =
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:747)
2012-12-03 19:45:26,972 [myid:2] - WARN
[RecvWorker:1:QuorumCnxManager$RecvWorker@765] - Interrupting SendWorker
2012-12-03 19:45:26,973 [myid:2] - DEBUG
[RecvWorker:1:QuorumCnxManager$SendWorker@588] - Calling finish for 1
2012-12-03 19:45:26,973 [myid:2] - DEBUG
[RecvWorker:1:QuorumCnxManager$SendWorker@608] - Removing entry from
senderWorkerMap sid=1
2012-12-03 19:45:26,973 [myid:2] - WARN
[SendWorker:1:QuorumCnxManager$SendWorker@679] - Interrupted while waiting
for message on queue
java.lang.InterruptedException
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2094)
at
java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:370)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:831)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:62)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:667)
2012-12-03 19:45:26,974 [myid:2] - DEBUG
[SendWorker:1:QuorumCnxManager$SendWorker@588] - Calling finish for 1
2012-12-03 19:45:26,974 [myid:2] - WARN
[SendWorker:1:QuorumCnxManager$SendWorker@688] - Send worker leaving thread
2012-12-03 19:46:25,059 [myid:] - INFO [main:QuorumPeerConfig@101] -
Reading configuration from: /usr/zookeeper/bin/../conf/zoo.cfg
2012-12-03 19:46:25,066 [myid:] - INFO [main:QuorumPeerConfig@334] -
Defaulting to majority quorums
2012-12-03 19:46:25,071 [myid:2] - INFO [main:DatadirCleanupManager@78] -
autopurge.snapRetainCount set to 3
2012-12-03 19:46:25,072 [myid:2] - INFO [main:DatadirCleanupManager@79] -
autopurge.purgeInterval set to 0
2012-12-03 19:46:25,073 [myid:2] - INFO [main:DatadirCleanupManager@101] -
Purge task is not scheduled.
2012-12-03 19:46:25,080 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:hiearchy=default
2012-12-03 19:46:25,081 [myid:2] - DEBUG [main:HierarchyDynamicMBean@254] -
postRegister is called.
2012-12-03 19:46:25,084 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. S

Re: Ephemeral node not getting deleted

Camille Fournier 2012-12-04, 15:10

This is probably not debuggable with just this log snippet, or at least
nothing jumps out at me. Can you open a jira ticket and include the
transaction logs from all 3 zookeepers in the ticket?

Thanks,
Camille

On Tue, Dec 4, 2012 at 5:53 AM, Deepa <[EMAIL PROTECTED]> wrote:

> Hi,
>
> I have zookeeper cluster of size 3,with the following parameters set
> across all the servers:
> tickTime=2000
> initLimit=10
> syncLimit=5
>
> Session timeout is set to 40sec and using zookeeper 3.4.4. My application
> works something like this:
> It creates ephemeral nodes if it can grab and serve a range from a list of
> ranges . It basically creates 2 ephemerals if its successful in finding a
> range. From the zookeeper server logs, I see that only one of the ephemeral
> node is getting deleted while bringing down servers randomly and restarting
> them.
>
> Please find the log snippet below:
>
> 2012-12-03 19:22:52,360 [myid:2] - DEBUG
> [FollowerRequestProcessor:2:CommitProcessor@171] - Processing request::
> sessionid:0x23b6109f83e0001 type:createSession cxid:0x0
> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
> 2012-12-03 19:22:52,362 [myid:2] - DEBUG
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:CommitProcessor@161] - Committing
> request:: sessionid:0x23b6109f83e0001 type:createSession cxid:0x0
> zxid:0x3000000013 txntype:-10 reqpath:n/a
> 2012-12-03 19:22:52,362 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
> sessionid:*0x23b6109f83e0001* type:createSession cxid:0x0 zxid:0x3000000013
> txntype:-10 reqpath:n/a
> 2012-12-03 19:22:52,363 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@160] -
> sessionid:*0x23b6109f83e0001
> *type:createSession cxid:0x0 zxid:0x3000000013 txntype:-10 reqpath:n/a
> 2012-12-03 19:22:52,364 [myid:2] - INFO
> [CommitProcessor:2:ZooKeeperServer@595] - Established session
> *0x23b6109f83e0001 *with negotiated timeout 40000 for client
> /192.168.11.94:3566
>
> 2012-12-03 19:23:01,143 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
> sessionid:*0x23b6109f83e0001 *type:create cxid:0x50bdb440 zxid:0x300000002d
> txntype:1 reqpath:/CONFIGNODE/NP2147483647
> 2012-12-03 19:23:01,144 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@160] -
> sessionid:*0x23b6109f83e0001
> *type:create cxid:0x50bdb440 zxid:0x300000002d txntype:1
> reqpath:*/CONFIGNODE/NP2147483647*
>
> 2012-12-03 19:23:01,157 [myid:2] - DEBUG
> [FollowerRequestProcessor:2:CommitProcessor@171] - Processing request::
> sessionid:*0x23b6109f83e0001 *type:create cxid:0x50bdb444
> zxid:0xfffffffffffffffe txntype:unknown reqpath:*/ACTIVE/NP2147483647*
> 2012-12-03 19:23:01,159 [myid:2] - DEBUG
> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:CommitProcessor@161] - Committing
> request:: sessionid:0x23b6109f83e0001 type:create cxid:0x50bdb444
> zxid:0x3000000032 txntype:1 reqpath:n/a
> 2012-12-03 19:23:01,159 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
> sessionid:0x23b6109f83e0001 type:create cxid:0x50bdb444 zxid:0x3000000032
> txntype:1 reqpath:/ACTIVE/NP2147483647
> 2012-12-03 19:23:01,160 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@160] -
> sessionid:0x23b6109f83e0001
> type:create cxid:0x50bdb444 zxid:0x3000000032 txntype:1
> reqpath:*/ACTIVE/NP2147483647*
> 2012-12-03 19:45:16,672 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
> sessionid:0x23b6109f83e0001 type:ping cxid:0xfffffffffffffffe
> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
> 2012-12-03 19:45:16,672 [myid:2] - DEBUG
> [CommitProcessor:2:FinalRequestProcessor@160] -
> sessionid:0x23b6109f83e0001
> type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown
> reqpath:n/a
> 2012-12-03 19:45:26,966 [myid:2] - WARN
> [RecvWorker:1:QuorumCnxManager$RecvWorker@762] - Connection broken for id
> 1,
> my id = 2, error > java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)

Re: Ephemeral node not getting deleted

Patrick Hunt 2012-12-04, 17:30

Yes, a jira with the zookeeper log4j logs and the datadir (tar.gz)
from all three servers would be great.
https://issues.apache.org/jira/browse/ZOOKEEPER

Thanks,

Patrick

On Tue, Dec 4, 2012 at 7:10 AM, Camille Fournier <[EMAIL PROTECTED]> wrote:
> This is probably not debuggable with just this log snippet, or at least
> nothing jumps out at me. Can you open a jira ticket and include the
> transaction logs from all 3 zookeepers in the ticket?
>
> Thanks,
> Camille
>
> On Tue, Dec 4, 2012 at 5:53 AM, Deepa <[EMAIL PROTECTED]> wrote:
>
>> Hi,
>>
>> I have zookeeper cluster of size 3,with the following parameters set
>> across all the servers:
>> tickTime=2000
>> initLimit=10
>> syncLimit=5
>>
>> Session timeout is set to 40sec and using zookeeper 3.4.4. My application
>> works something like this:
>> It creates ephemeral nodes if it can grab and serve a range from a list of
>> ranges . It basically creates 2 ephemerals if its successful in finding a
>> range. From the zookeeper server logs, I see that only one of the ephemeral
>> node is getting deleted while bringing down servers randomly and restarting
>> them.
>>
>> Please find the log snippet below:
>>
>> 2012-12-03 19:22:52,360 [myid:2] - DEBUG
>> [FollowerRequestProcessor:2:CommitProcessor@171] - Processing request::
>> sessionid:0x23b6109f83e0001 type:createSession cxid:0x0
>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>> 2012-12-03 19:22:52,362 [myid:2] - DEBUG
>> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:CommitProcessor@161] - Committing
>> request:: sessionid:0x23b6109f83e0001 type:createSession cxid:0x0
>> zxid:0x3000000013 txntype:-10 reqpath:n/a
>> 2012-12-03 19:22:52,362 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
>> sessionid:*0x23b6109f83e0001* type:createSession cxid:0x0 zxid:0x3000000013
>> txntype:-10 reqpath:n/a
>> 2012-12-03 19:22:52,363 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@160] -
>> sessionid:*0x23b6109f83e0001
>> *type:createSession cxid:0x0 zxid:0x3000000013 txntype:-10 reqpath:n/a
>> 2012-12-03 19:22:52,364 [myid:2] - INFO
>> [CommitProcessor:2:ZooKeeperServer@595] - Established session
>> *0x23b6109f83e0001 *with negotiated timeout 40000 for client
>> /192.168.11.94:3566
>>
>> 2012-12-03 19:23:01,143 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
>> sessionid:*0x23b6109f83e0001 *type:create cxid:0x50bdb440 zxid:0x300000002d
>> txntype:1 reqpath:/CONFIGNODE/NP2147483647
>> 2012-12-03 19:23:01,144 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@160] -
>> sessionid:*0x23b6109f83e0001
>> *type:create cxid:0x50bdb440 zxid:0x300000002d txntype:1
>> reqpath:*/CONFIGNODE/NP2147483647*
>>
>> 2012-12-03 19:23:01,157 [myid:2] - DEBUG
>> [FollowerRequestProcessor:2:CommitProcessor@171] - Processing request::
>> sessionid:*0x23b6109f83e0001 *type:create cxid:0x50bdb444
>> zxid:0xfffffffffffffffe txntype:unknown reqpath:*/ACTIVE/NP2147483647*
>> 2012-12-03 19:23:01,159 [myid:2] - DEBUG
>> [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:CommitProcessor@161] - Committing
>> request:: sessionid:0x23b6109f83e0001 type:create cxid:0x50bdb444
>> zxid:0x3000000032 txntype:1 reqpath:n/a
>> 2012-12-03 19:23:01,159 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
>> sessionid:0x23b6109f83e0001 type:create cxid:0x50bdb444 zxid:0x3000000032
>> txntype:1 reqpath:/ACTIVE/NP2147483647
>> 2012-12-03 19:23:01,160 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@160] -
>> sessionid:0x23b6109f83e0001
>> type:create cxid:0x50bdb444 zxid:0x3000000032 txntype:1
>> reqpath:*/ACTIVE/NP2147483647*
>> 2012-12-03 19:45:16,672 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
>> sessionid:0x23b6109f83e0001 type:ping cxid:0xfffffffffffffffe
>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>> 2012-12-03 19:45:16,672 [myid:2] - DEBUG
>> [CommitProcessor:2:FinalRequestProcessor@160] -