[
https://issues.apache.org/jira/browse/ZOOKEEPER-919?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Vishal K updated ZOOKEEPER-919:
-------------------------------
Attachment: logs3.tar.gz
Hi Ben,
I think the ZooKeeper server is dropping multiple transactions after
it rejoins the cluster. As a result, it drops the transaction that
delets the ephemeral znode (and many more transactions).
I have attached the logs. It would good to track the
createsession/deletessesion/create transactions for all sessions in
sessions.txt file.
Log entries that shows the fact that the server is dropping transaction:
2010-12-14 05:59:19,144 - INFO [Thread-2:files...@82] - Reading snapshot
/var/zookeeper/version-2/snapshot.200000016 ===> ***** THIS DOES NOT CONTAIN DT
till 200000016 ****
2010-12-14 05:59:19,147 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 12ce374d71f0001 with timeout: 30000
2010-12-14 05:59:19,148 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 22ce37526bd0001 with timeout: 30000
2010-12-14 05:59:19,148 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 12ce374d71f0000 with timeout: 30000
2010-12-14 05:59:19,148 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 22ce37526bd0002 with timeout: 30000
2010-12-14 05:59:19,148 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 22ce37526bd0003 with timeout: 30000
2010-12-14 05:59:19,149 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 22ce3757b780003 with timeout: 30000
2010-12-14 05:59:19,149 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 22ce3757b780002 with timeout: 30000
2010-12-14 05:59:19,149 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 22ce3757b780001 with timeout: 30000
2010-12-14 05:59:19,150 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 22ce3757b780000 with timeout: 9000
2010-12-14 05:59:19,150 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 2ce374f6b80000 with timeout: 30000
2010-12-14 05:59:19,150 - TRACE [Thread-2:zootr...@70] - loadData --- session
in archive: 2ce374f6b80001 with timeout: 30000
2010-12-14 05:59:19,156 - DEBUG [Thread-2:datat...@1072] - VK DEBUG: in
desrialize
2010-12-14 05:59:19,156 - DEBUG [Thread-2:datat...@1096] - VK DEBUG Adding path
/Online for 22ce3757b780000
2010-12-14 05:59:19,157 - DEBUG [Thread-2:datat...@1226] - VK DEBUG: Stack
trace
java.lang.Thread.getStackTrace(Thread.java:1436)org.apache.zookeeper.server.DataTree.logStack(DataTree.java:1221)org.apache.zookeeper.server.DataTree.deserialize(DataTree.java:1097)org.apache.zookeeper.server.util.SerializeUtils.deserializeSnapshot(SerializeUtils.java:95)org.apache.zookeeper.server.persistence.FileSnap.deserialize(FileSnap.java:126)org.apache.zookeeper.server.persistence.FileSnap.deserialize(FileSnap.java:86)org.apache.zookeeper.server.persistence.FileTxnSnapLog.restore(FileTxnSnapLog.java:124)org.apache.zookeeper.server.ZKDatabase.loadDataBase(ZKDatabase.java:197)org.apache.zookeeper.server.quorum.QuorumPeer.start(QuorumPeer.java:397)org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:143)org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:103)com.vmware.sva.zkmgmtserver.ZkQuorumPeer.access$200(ZkQuorumPeer.java:26)com.vmware.sva.zkmgmtserver.ZkQuorumPeer$ZooKeeperInstance.run(ZkQuorumPeer.java:78)
2010-12-14 05:59:19,157 - DEBUG [Thread-2:datat...@1230] - Printing DataTree
2010-12-14 05:59:19,158 - DEBUG [Thread-2:datat...@1232] - Path=/
node=org.apache.zookeeper.server.datan...@3ba42792
2010-12-14 05:59:19,158 - DEBUG [Thread-2:datat...@1232] - Path=/Online
node=org.apache.zookeeper.server.datan...@162200d5
2010-12-14 05:59:19,158 - DEBUG [Thread-2:datat...@1232] - Path=
node=org.apache.zookeeper.server.datan...@3ba42792
2010-12-14 05:59:19,158 - DEBUG [Thread-2:datat...@1232] - Path=/zookeeper
node=org.apache.zookeeper.server.datan...@1264ab4d
2010-12-14 05:59:19,159 - DEBUG [Thread-2:datat...@1232] -
Path=/zookeeper/quota node=org.apache.zookeeper.server.datan...@f2a55aa
2010-12-14 05:59:19,162 - DEBUG [Thread-2:filetxnlog$filetxnitera...@527] -
Created new input stream /var/zookeeper/version-2/log.200000011 ==> ****** THIS
DOES NOT CONTAIN TX FROM 200000011 - 200000016 *********
2010-12-14 05:59:19,167 - DEBUG [Thread-2:filetxnlog$filetxnitera...@530] -
Created new input archive /var/zookeeper/version-2/log.200000011
2010-12-14 05:59:19,168 - DEBUG [Thread-2:filetxnsnap...@178] - VK debug:
156750179351724034,0,8589934614,1292306326006,-11
The problem is that snapshot snapshot.200000016 does not contain all
transactions till snapshot.200000016. Log log.200000011 will contain
transactions 200000011 - 200000015, but the server will ignore them
since it thinks snapshot.200000016 has those transactions. As a
result, it will drop those transactions.
I think the zxid management during startup is buggy. Possibly one or
more of the following issues is causing trouble:
1. Race conditions/ incorrect zxid received from leader at two places
a) newLeaderZxid different from zxid received on qp in Learner.syncWithLeader()
zk.getZKDatabase().setlastProcessedZxid(newLeaderZxid);
The dataTree.lastProcessedZxid is probably getting set incorrectly
(higher than the correct zxid). This is causing transactions from the
correct zxid to lastProcessed to be dropped during log replay in
FileTxnSnapLog.java. I think this is the main cause.
b) Learner does not wait until it receives the entire snapshot from
the leader (see snapshot.200000016)
-Vishal
> Ephemeral nodes remains in one of ensemble after deliberate SIGKILL
> -------------------------------------------------------------------
>
> Key: ZOOKEEPER-919
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-919
> Project: ZooKeeper
> Issue Type: Bug
> Components: server
> Affects Versions: 3.3.1
> Environment: Linux CentOS 5.3 64bit, JDK 1.6.0-22
> SLES 11
> Reporter: Chang Song
> Priority: Blocker
> Fix For: 3.3.3, 3.4.0
>
> Attachments: logs.tar.gz, logs2.tar.gz, logs3.tar.gz
>
>
> I was testing stability of Zookeeper ensemble for production deployment.
> Three node ensemble cluster configuration.
> In a loop, I kill/restart three Zookeeper clients that created one ephemeral
> node each, and at the same time,
> I killed Java process on one of ensemble (dont' know if it was a leader or
> not). Then I restarted Zookeeper on the server,
> It turns out that on two zookeeper ensemble servers, all the ephemeral nodes
> are gone (it should), but on the newly started
> Zookeeper server, the two old ephemeral nodes stayed. The zookeeper didn't
> restart in standalone mode since new ephemeral
> nodes gets created on all ensemble servers.
> I captured the log.
> 2010-11-04 17:48:50,201 - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:17288:nioservercnxn$fact...@250] -
> Accepted socket connection from /10.25.131.21:11191
> 2010-11-04 17:48:50,202 - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:17288:nioserverc...@776] - Client
> attempting to establish new session at /10.25.131.21:11191
> 2010-11-04 17:48:50,203 - INFO [CommitProcessor:1:nioserverc...@1579] -
> Established session 0x12c160c31fc000b with negotiated timeout 30000 for
> client /10.25.131.21:11191
> 2010-11-04 17:48:50,206 - WARN
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:17288:nioserverc...@633] -
> EndOfStreamException: Unable to read additional data from client sessionid
> 0x12c160c31fc000b, likely client has closed socket
> 2010-11-04 17:48:50,207 - INFO
> [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:17288:nioserverc...@1434] - Closed
> socket connection for client /10.25.131.21:11191 which had sessionid
> 0x12c160c31fc000b
> 2010-11-04 17:48:50,207 - ERROR [CommitProcessor:1:nioserverc...@444] -
> Unexpected Exception:
> java.nio.channels.CancelledKeyException
> at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
> at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
> at
> org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:417)
> at
> org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1508)
> at
> org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:367)
> at
> org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:73)
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
