Ephemeral node not getting deleted

[Deepa]

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

[Camille Fournier]

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 <[hidden email]> 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)
>         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.
>

[Patrick Hunt]

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 <[hidden email]> 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 <[hidden email]> 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)
>>         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.
>>

[Deepa]

Thanks Camille, Patrick. I have raised Jira for this issue:

https://issues.apache.org/jira/browse/ZOOKEEPER-1600

Thanks
Deepa

[Patrick Hunt]

Hi Deepa, afaict this is not a bug, see my comment on the jira
https://issues.apache.org/jira/browse/ZOOKEEPER-1600#comment-13530342

If I'm missing something please add additional comments to the jira.

Regards,

Patrick

On Sun, Dec 9, 2012 at 10:55 PM, Deepa <[hidden email]> wrote:

> Thanks Camille, Patrick. I have raised Jira for this issue:
>
> https://issues.apache.org/jira/browse/ZOOKEEPER-1600
>
> Thanks
> Deepa
>
>
>
> --
> View this message in context: http://zookeeper-user.578899.n2.nabble.com/Ephemeral-node-not-getting-deleted-tp7578249p7578311.html
> Sent from the zookeeper-user mailing list archive at Nabble.com.