zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Deepa <deepa...@gmail.com>
Subject Ephemeral node not getting deleted
Date Tue, 04 Dec 2012 10:53:58 GMT
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. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=root
2012-12-03 19:46:25,086 [myid:2] - DEBUG [main:LoggerDynamicMBean@256] -
Adding AppenderMBean for appender named CONSOLE
2012-12-03 19:46:25,089 [myid:2] - DEBUG [main:AppenderDynamicMBean@152] -
getMBeanInfo called.
2012-12-03 19:46:25,090 [myid:2] - DEBUG [main:AppenderDynamicMBean@309] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:appender=CONSOLE
2012-12-03 19:46:25,091 [myid:2] - DEBUG [main:AppenderDynamicMBean@191] -
Adding LayoutMBean:CONSOLE,layout=org.apache.log4j.PatternLayout
2012-12-03 19:46:25,093 [myid:2] - DEBUG [main:LayoutDynamicMBean@138] -
getMBeanInfo called.
2012-12-03 19:46:25,095 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:appender=CONSOLE,layout=org.apache.log4j.PatternLayout
2012-12-03 19:46:25,096 [myid:2] - DEBUG [main:LoggerDynamicMBean@256] -
Adding AppenderMBean for appender named ROLLINGFILE
2012-12-03 19:46:25,097 [myid:2] - DEBUG [main:AppenderDynamicMBean@152] -
getMBeanInfo called.
2012-12-03 19:46:25,099 [myid:2] - DEBUG [main:AppenderDynamicMBean@309] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:appender=ROLLINGFILE
2012-12-03 19:46:25,100 [myid:2] - DEBUG [main:AppenderDynamicMBean@191] -
Adding LayoutMBean:ROLLINGFILE,layout=org.apache.log4j.PatternLayout
2012-12-03 19:46:25,101 [myid:2] - DEBUG [main:LayoutDynamicMBean@138] -
getMBeanInfo called.
2012-12-03 19:46:25,102 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:appender=ROLLINGFILE,layout=org.apache.log4j.PatternLayout
2012-12-03 19:46:25,105 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [root] as listener.
2012-12-03 19:46:25,106 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.log4j.jmx.LayoutDynamicMBean
2012-12-03 19:46:25,107 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.log4j.jmx.LayoutDynamicMBean] as listener.
2012-12-03 19:46:25,108 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.zookeeper.server.quorum.QuorumPeerMain
2012-12-03 19:46:25,109 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.zookeeper.server.quorum.QuorumPeerMain] as
listener.
2012-12-03 19:46:25,109 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.log4j.jmx.LoggerDynamicMBean
2012-12-03 19:46:25,110 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.log4j.jmx.LoggerDynamicMBean] as listener.
2012-12-03 19:46:25,110 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.zookeeper.server.quorum.QuorumPeerConfig
2012-12-03 19:46:25,111 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.zookeeper.server.quorum.QuorumPeerConfig] as
listener.
2012-12-03 19:46:25,111 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.zookeeper.jmx.MBeanRegistry
2012-12-03 19:46:25,112 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.zookeeper.jmx.MBeanRegistry] as listener.
2012-12-03 19:46:25,112 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.log4j.jmx.HierarchyDynamicMBean
2012-12-03 19:46:25,113 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.log4j.jmx.HierarchyDynamicMBean] as listener.
2012-12-03 19:46:25,113 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.log4j.jmx.AppenderDynamicMBean
2012-12-03 19:46:25,114 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.log4j.jmx.AppenderDynamicMBean] as listener.
2012-12-03 19:46:25,114 [myid:2] - DEBUG [main:AbstractDynamicMBean@124] -
preRegister called. Server=com.sun.jmx.mbeanserver.JmxMBeanServer@558385e3,
name=log4j:logger=org.apache.zookeeper.server.DatadirCleanupManager
2012-12-03 19:46:25,115 [myid:2] - DEBUG [main:HierarchyDynamicMBean@126] -
---Adding logger [org.apache.zookeeper.server.DatadirCleanupManager] as
listener.
2012-12-03 19:46:25,115 [myid:2] - INFO  [main:QuorumPeerMain@127] -
Starting quorum peer
2012-12-03 19:46:25,135 [myid:2] - INFO  [main:NIOServerCnxnFactory@94] -
binding to port 0.0.0.0/0.0.0.0:2181
2012-12-03 19:46:25,157 [myid:2] - DEBUG [main:FileTxnSnapLog@79] - Opening
datadir:/media/n/zklogs snapDir:/media/n/zookeeper
2012-12-03 19:46:25,163 [myid:2] - INFO  [main:QuorumPeer@913] - tickTime
set to 2000
2012-12-03 19:46:25,163 [myid:2] - INFO  [main:QuorumPeer@933] -
minSessionTimeout set to -1
2012-12-03 19:46:25,164 [myid:2] - INFO  [main:QuorumPeer@944] -
maxSessionTimeout set to -1
2012-12-03 19:46:25,164 [myid:2] - INFO  [main:QuorumPeer@959] - initLimit
set to 10
2012-12-03 19:46:25,207 [myid:2] - INFO  [main:FileSnap@83] - Reading
snapshot /media/n/zookeeper/version-2/snapshot.2f00000045
2012-12-03 19:46:25,282 [myid:2] - DEBUG
[main:FileTxnLog$FileTxnIterator@575] - Created new input stream
/media/n/zklogs/version-2/log.2f0000000a
2012-12-03 19:46:25,283 [myid:2] - DEBUG
[main:FileTxnLog$FileTxnIterator@578] - Created new input archive
/media/n/zklogs/version-2/log.2f0000000a
2012-12-03 19:46:25,287 [myid:2] - DEBUG
[main:FileTxnLog$FileTxnIterator@618] - EOF excepton java.io.EOFException:
Failed to read /media/n/zklogs/version-2/log.2f0000000a
2012-12-03 19:46:25,287 [myid:2] - DEBUG
[main:FileTxnLog$FileTxnIterator@575] - Created new input stream
/media/n/zklogs/version-2/log.3000000001
2012-12-03 19:46:25,288 [myid:2] - DEBUG
[main:FileTxnLog$FileTxnIterator@578] - Created new input archive
/media/n/zklogs/version-2/log.3000000001
2012-12-03 19:46:25,292 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,293 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,295 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,295 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,295 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,295 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,296 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -101
2012-12-03 19:46:25,296 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -101
2012-12-03 19:46:25,296 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,296 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,298 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,298 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,299 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,299 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,300 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,300 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,301 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,301 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,301 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,302 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,302 [myid:2] - DEBUG [main:DataTree@949] - Ignoring
processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,302 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,303 [myid:2] - DEBUG [main:DataTree@968] - Deleting
ephemeral node 2012-12-03 19:46:25,318 [myid:2] - DEBUG [main:DataTree@949]
- Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,318 [myid:2] - DEBUG [main:FileTxnSnapLog@213] -
Ignoring processTxn failure hdr: -1 : error: -110
2012-12-03 19:46:25,319 [myid:2] - DEBUG
[main:FileTxnLog$FileTxnIterator@618] - EOF excepton java.io.EOFException:
Failed to read /media/n/zklogs/version-2/log.3000000001
2012-12-03 19:46:25,322 [myid:2] - INFO 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] -
Accepted socket connection from /192.168.11.39:37452
2012-12-03 19:46:25,324 [myid:2] - INFO 
[Thread-1:QuorumCnxManager$Listener@486] - My election bind port:
0.0.0.0/0.0.0.0:3888
2012-12-03 19:46:25,327 [myid:2] - WARN 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@354] - Exception
causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not
running
2012-12-03 19:46:25,328 [myid:2] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@358] - IOException
stack trace
java.io.IOException: ZooKeeperServer not running
	at
org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCnxn.java:925)
	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:229)
	at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
	at java.lang.Thread.run(Thread.java:679)
2012-12-03 19:46:25,329 [myid:2] - INFO 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed
socket connection for client /192.168.11.39:37452 (no session established
for client)
2012-12-03 19:46:25,329 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@635] - Starting quorum
peer
2012-12-03 19:46:25,333 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@670] - LOOKING
2012-12-03 19:46:25,333 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@601] - Initializing
leader election protocol...
2012-12-03 19:46:25,335 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@641] - Updating
proposal: 2 (newleader), 0x300000004e (newzxid), -1 (oldleader),
0xffffffffffffffff (oldzxid)
2012-12-03 19:46:25,335 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@740] - New
election. My id =  2, proposed zxid=0x300000004e
2012-12-03 19:46:25,335 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@531] - Sending
Notification: 2 (n.leader), 0x300000004e (n.zxid), 0x1 (n.round), 1
(recipient), 2 (myid), 0x30 (n.peerEpoch)
2012-12-03 19:46:25,336 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@531] - Sending
Notification: 2 (n.leader), 0x300000004e (n.zxid), 0x1 (n.round), 2
(recipient), 2 (myid), 0x30 (n.peerEpoch)
2012-12-03 19:46:25,336 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@531] - Sending
Notification: 2 (n.leader), 0x300000004e (n.zxid), 0x1 (n.round), 3
(recipient), 2 (myid), 0x30 (n.peerEpoch)
2012-12-03 19:46:25,336 [myid:2] - DEBUG
[WorkerSender[myid=2]:QuorumCnxManager@350] - Opening channel to server 1
2012-12-03 19:46:25,339 [myid:2] - WARN 
[WorkerSender[myid=2]:QuorumCnxManager@368] - Cannot open channel to 1 at
election address /192.168.11.99:3888
java.net.ConnectException: Connection refused
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:327)
	at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:193)
	at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:180)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:384)
	at java.net.Socket.connect(Socket.java:546)
	at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:354)
	at
org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:327)
	at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:393)
	at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:365)
	at java.lang.Thread.run(Thread.java:679)
2012-12-03 19:46:25,342 [myid:2] - DEBUG
[WorkerSender[myid=2]:QuorumCnxManager@350] - Opening channel to server 3
2012-12-03 19:46:25,343 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@230] -
Receive new notification message. My id = 2
2012-12-03 19:46:25,343 [myid:2] - INFO 
[WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 2
(n.leader), 0x300000004e (n.zxid), 0x1 (n.round), LOOKING (n.state), 2
(n.sid), 0x30 (n.peerEPoch), LOOKING (my state)
2012-12-03 19:46:25,344 [myid:2] - DEBUG
[WorkerSender[myid=2]:QuorumCnxManager@356] - Connected to server 3
2012-12-03 19:46:25,350 [myid:2] - INFO 
[WorkerSender[myid=2]:QuorumCnxManager@190] - Have smaller server
identifier, so dropping the connection: (3, 2)
2012-12-03 19:46:25,351 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@558] - id: 2,
proposed id: 2, zxid: 0x300000004e, proposed zxid: 0x300000004e
2012-12-03 19:46:25,351 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@810] - Adding
vote: from=2, proposed leader=2, proposed zxid=0x300000004e, proposed
election epoch=0x1
2012-12-03 19:46:25,352 [myid:2] - INFO 
[/192.168.11.97:3888:QuorumCnxManager$Listener@493] - Received connection
request /192.168.11.100:59102
2012-12-03 19:46:25,353 [myid:2] - DEBUG
[/192.168.11.97:3888:QuorumCnxManager$SendWorker@570] - Address of remote
peer: 3
2012-12-03 19:46:25,355 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@230] -
Receive new notification message. My id = 2
2012-12-03 19:46:25,355 [myid:2] - INFO 
[WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 3
(n.leader), 0x300000004e (n.zxid), 0x17 (n.round), LOOKING (n.state), 3
(n.sid), 0x30 (n.peerEPoch), LOOKING (my state)
2012-12-03 19:46:25,356 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@230] -
Receive new notification message. My id = 2
2012-12-03 19:46:25,356 [myid:2] - INFO 
[WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 3
(n.leader), 0x300000004e (n.zxid), 0x17 (n.round), LOOKING (n.state), 3
(n.sid), 0x30 (n.peerEPoch), LOOKING (my state)
2012-12-03 19:46:25,356 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@558] - id: 3,
proposed id: 2, zxid: 0x300000004e, proposed zxid: 0x300000004e
2012-12-03 19:46:25,356 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@641] - Updating
proposal: 3 (newleader), 0x300000004e (newzxid), 2 (oldleader), 0x300000004e
(oldzxid)
2012-12-03 19:46:25,357 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@531] - Sending
Notification: 3 (n.leader), 0x300000004e (n.zxid), 0x17 (n.round), 1
(recipient), 2 (myid), 0x30 (n.peerEpoch)
2012-12-03 19:46:25,357 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@531] - Sending
Notification: 3 (n.leader), 0x300000004e (n.zxid), 0x17 (n.round), 2
(recipient), 2 (myid), 0x30 (n.peerEpoch)
2012-12-03 19:46:25,357 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@531] - Sending
Notification: 3 (n.leader), 0x300000004e (n.zxid), 0x17 (n.round), 3
(recipient), 2 (myid), 0x30 (n.peerEpoch)
2012-12-03 19:46:25,357 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@810] - Adding
vote: from=3, proposed leader=3, proposed zxid=0x300000004e, proposed
election epoch=0x17
2012-12-03 19:46:25,357 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@558] - id: 3,
proposed id: 3, zxid: 0x300000004e, proposed zxid: 0x300000004e
2012-12-03 19:46:25,357 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@810] - Adding
vote: from=3, proposed leader=3, proposed zxid=0x300000004e, proposed
election epoch=0x17
2012-12-03 19:46:25,357 [myid:2] - DEBUG
[WorkerSender[myid=2]:QuorumCnxManager@350] - Opening channel to server 1
2012-12-03 19:46:25,358 [myid:2] - WARN 
[WorkerSender[myid=2]:QuorumCnxManager@368] - Cannot open channel to 1 at
election address /192.168.11.99:3888
java.net.ConnectException: Connection refused
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:327)
	at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:193)
	at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:180)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:384)
	at java.net.Socket.connect(Socket.java:546)
	at
org.apache.zookeeper.server.quorum.QuorumCnxManager.connectOne(QuorumCnxManager.java:354)
	at
org.apache.zookeeper.server.quorum.QuorumCnxManager.toSend(QuorumCnxManager.java:327)
	at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.process(FastLeaderElection.java:393)
	at
org.apache.zookeeper.server.quorum.FastLeaderElection$Messenger$WorkerSender.run(FastLeaderElection.java:365)
	at java.lang.Thread.run(Thread.java:679)
2012-12-03 19:46:25,359 [myid:2] - DEBUG
[WorkerSender[myid=2]:QuorumCnxManager@373] - There is a connection already
for server 3
2012-12-03 19:46:25,359 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@230] -
Receive new notification message. My id = 2
2012-12-03 19:46:25,359 [myid:2] - INFO 
[WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 3
(n.leader), 0x300000004e (n.zxid), 0x17 (n.round), LOOKING (n.state), 2
(n.sid), 0x30 (n.peerEPoch), LOOKING (my state)
2012-12-03 19:46:25,359 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@558] - id: 3,
proposed id: 3, zxid: 0x300000004e, proposed zxid: 0x300000004e
2012-12-03 19:46:25,359 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@810] - Adding
vote: from=2, proposed leader=3, proposed zxid=0x300000004e, proposed
election epoch=0x17
2012-12-03 19:46:25,560 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@663] - I'm a
participant: 2
2012-12-03 19:46:25,560 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@493] - About to
leave FLE instance: leader=3, zxid=0x300000004e, my id=2, my state=FOLLOWING
2012-12-03 19:46:25,560 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:QuorumPeer@738] - FOLLOWING
2012-12-03 19:46:25,564 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@85] - TCP NoDelay set to:
true
2012-12-03 19:46:25,569 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:zookeeper.version=3.4.4-1386507, built on 09/17/2012 08:33 GMT
2012-12-03 19:46:25,569 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:host.name=SuryaLinux2
2012-12-03 19:46:25,570 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.version=1.6.0_22
2012-12-03 19:46:25,570 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.vendor=Sun Microsystems Inc.
2012-12-03 19:46:25,570 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.home=/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre
2012-12-03 19:46:25,570 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.class.path=/usr/zookeeper/bin/../build/classes:/usr/zookeeper/bin/../build/lib/*.jar:/usr/zookeeper/bin/../lib/slf4j-log4j12-1.6.1.jar:/usr/zookeeper/bin/../lib/slf4j-api-1.6.1.jar:/usr/zookeeper/bin/../lib/netty-3.2.2.Final.jar:/usr/zookeeper/bin/../lib/log4j-1.2.15.jar:/usr/zookeeper/bin/../lib/jline-0.9.94.jar:/usr/zookeeper/bin/../zookeeper-3.4.4.jar:/usr/zookeeper/bin/../src/java/lib/*.jar:/usr/zookeeper/bin/../conf:
2012-12-03 19:46:25,570 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.library.path=/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64:/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
2012-12-03 19:46:25,570 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.io.tmpdir=/tmp
2012-12-03 19:46:25,571 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:java.compiler=<NA>
2012-12-03 19:46:25,571 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.name=Linux
2012-12-03 19:46:25,571 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.arch=amd64
2012-12-03 19:46:25,571 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:os.version=2.6.32-220.el6.x86_64
2012-12-03 19:46:25,572 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.name=root
2012-12-03 19:46:25,572 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.home=/root
2012-12-03 19:46:25,572 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Environment@100] - Server
environment:user.dir=/usr/zookeeper/bin
2012-12-03 19:46:25,573 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created
server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000
datadir /media/n/zklogs/version-2 snapdir /media/n/zookeeper/version-2
2012-12-03 19:46:25,574 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER
ELECTION TOOK - 239
2012-12-03 19:46:25,595 [myid:2] - INFO 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] -
Accepted socket connection from /192.168.11.39:37455
2012-12-03 19:46:25,595 [myid:2] - WARN 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@354] - Exception
causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not
running
2012-12-03 19:46:25,595 [myid:2] - DEBUG
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@358] - IOException
stack trace
java.io.IOException: ZooKeeperServer not running
	at
org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCnxn.java:925)
	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:229)
	at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
	at java.lang.Thread.run(Thread.java:679)
2012-12-03 19:46:25,596 [myid:2] - INFO 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed
socket connection for client /192.168.11.39:37455 (no session established
for client)
2012-12-03 19:46:25,653 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:Learner@322] - Getting a diff from
the leader 0x300000004e
2012-12-03 19:46:25,655 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@240] - Snapshotting:
0x300000004e to /media/n/zookeeper/version-2/snapshot.300000004e
2012-12-03 19:46:25,696 [myid:2] - INFO 
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FileTxnSnapLog@240] - Snapshotting:
0x300000004e to /media/n/zookeeper/version-2/snapshot.300000004e
2012-12-03 19:46:27,435 [myid:2] - INFO 
[/192.168.11.97:3888:QuorumCnxManager$Listener@493] - Received connection
request /192.168.11.99:52425
2012-12-03 19:46:27,436 [myid:2] - DEBUG
[/192.168.11.97:3888:QuorumCnxManager@265] - Create new connection to
server: 1
2012-12-03 19:46:27,436 [myid:2] - DEBUG
[/192.168.11.97:3888:QuorumCnxManager@350] - Opening channel to server 1
2012-12-03 19:46:27,437 [myid:2] - DEBUG
[/192.168.11.97:3888:QuorumCnxManager@356] - Connected to server 1
2012-12-03 19:46:27,438 [myid:2] - DEBUG
[/192.168.11.97:3888:QuorumCnxManager$SendWorker@570] - Address of remote
peer: 1
2012-12-03 19:46:27,443 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@230] -
Receive new notification message. My id = 2
2012-12-03 19:46:27,443 [myid:2] - INFO 
[WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 1
(n.leader), 0x300000004e (n.zxid), 0x1 (n.round), LOOKING (n.state), 1
(n.sid), 0x30 (n.peerEPoch), FOLLOWING (my state)
2012-12-03 19:46:27,444 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@317] -
Sending new notification. My id =  2 recipient=1 zxid=0x300000004e leader=3
2012-12-03 19:46:27,444 [myid:2] - DEBUG
[WorkerSender[myid=2]:QuorumCnxManager@373] - There is a connection already
for server 1
2012-12-03 19:46:27,448 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@230] -
Receive new notification message. My id = 2
2012-12-03 19:46:27,448 [myid:2] - INFO 
[WorkerReceiver[myid=2]:FastLeaderElection@542] - Notification: 3
(n.leader), 0x300000004e (n.zxid), 0x17 (n.round), LOOKING (n.state), 1
(n.sid), 0x30 (n.peerEPoch), FOLLOWING (my state)
2012-12-03 19:46:27,449 [myid:2] - DEBUG
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@317] -
Sending new notification. My id =  2 recipient=1 zxid=0x300000004e leader=3
2012-12-03 19:46:27,449 [myid:2] - DEBUG
[WorkerSender[myid=2]:QuorumCnxManager@373] - There is a connection already
for server 1


2012-12-03 19:47:07,073 [myid:2] - DEBUG
[QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:CommitProcessor@161] - Committing
request:: sessionid:0x23b6109f83e0001 type:closeSession cxid:0x0
zxid:0x3100000015 txntype:-11 reqpath:n/a
2012-12-03 19:47:07,073 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@160] - sessionid:0x13b60f68db30000
type:exists cxid:0x18f1 zxid:0xfffffffffffffffe txntype:unknown
reqpath:/CONFIGNODE
2012-12-03 19:47:07,073 [myid:2] - DEBUG
[CommitProcessor:2:FinalRequestProcessor@88] - Processing request::
sessionid:0x23b6109f83e0001 type:closeSession cxid:0x0 zxid:0x3100000015
txntype:-11 reqpath:n/a
2012-12-03 19:47:07,074 [myid:2] - DEBUG [CommitProcessor:2:DataTree@968] -
Deleting ephemeral node */CONFIGNODE/NP2147483647* for session
*0x23b6109f83e0001*



 From the above log, session creates two ephemerals:
*/CONFIGNODE/NP2147483647* and */ACTIVE/NP2147483647* but deletes only
/CONFIGNODE/NP2147483647 on closeSession.

Any comment is appreciated.

TIA,
Deepa




--
View this message in context: http://zookeeper-user.578899.n2.nabble.com/Ephemeral-node-not-getting-deleted-tp7578249.html
Sent from the zookeeper-user mailing list archive at Nabble.com.

Mime
View raw message