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