[
https://issues.apache.org/jira/browse/ZOOKEEPER-2684?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15857018#comment-15857018
]
Ryan Zhang commented on ZOOKEEPER-2684:
---------------------------------------
While I am at it, let me paste the enhanced log of a repo.
The problem was created when there is a session move. When a session just
moved, the new processor starts to get requests from the session so it will
crash when a commit coming from previous session handler comes. Here are the
logs from on repro
Learner A got the session 0x100186ea825fa45 starting from cxid 0xfb6
/var/log/zookeeper/zookeeper-info.log.65:2017-02-06 20:56:03,635 - INFO
[FollowerRequestProcessor:0] - Processing request:: sessionid:0x100186ea825fa45
type:create cxid:0xfb6 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_
/var/log/zookeeper/zookeeper-info.log.65:2017-02-06 20:56:03,636 - INFO
[FollowerRequestProcessor:0] - Processing request:: sessionid:0x100186ea825fa45
type:delete cxid:0xfb7 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1301965514
/var/log/zookeeper/zookeeper-info.log.65:2017-02-06 20:56:03,636 - INFO
[FollowerRequestProcessor:0] - Processing request:: sessionid:0x100186ea825fa45
type:create cxid:0xfb8 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_
/var/log/zookeeper/zookeeper-info.log.65:2017-02-06 20:56:04,123 - INFO
[QuorumPeer[myid=0](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x100186ea825fa45 type:error cxid:0xfb5 zxid:0x8e06e60288
txntype:-1 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.65:2017-02-06 20:56:04,123 - ERROR
[CommitProcessor:0] - Got request sessionid:0x100186ea825fa45 type:error
cxid:0xfb5 zxid:0x8e06e60288 txntype:-1 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.65: expected request
sessionid:0x100186ea825fa45 type:create cxid:0xfb6 zxid:0xfffffffffffffffe
txntype:unknown reqpath:/loadgen/load_
/var/log/zookeeper/zookeeper-info.log.65: for client session id
0x100186ea825fa45
follower B that processed 0xfb5 and got session 0x100186ea825fa45 closed after
0Xfb5
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:34,234 - INFO
[FollowerRequestProcessor:4] - Processing request:: sessionid:0x100186ea825fa45
type:delete cxid:0xfb0 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1301965515
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:34,345 - INFO
[FollowerRequestProcessor:4] - Processing request:: sessionid:0x100186ea825fa45
type:create cxid:0xfb1 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:34,659 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x1001
86ea825fa45 type:delete cxid:0xfae zxid:0x8e06e3c727 txntype:2 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:34,659 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x1001
86ea825fa45 type:create cxid:0xfaf zxid:0x8e06e3c728 txntype:1 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:34,664 - INFO
[FollowerRequestProcessor:4] - Processing request:: sessionid:0x100186ea825fa45
type:delete cxid:0xfb2 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1301965516
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:34,764 - INFO
[FollowerRequestProcessor:4] - Processing request:: sessionid:0x100186ea825fa45
type:create cxid:0xfb3 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:35,056 - INFO
[FollowerRequestProcessor:4] - Processing request:: sessionid:0x100186ea825fa45
type:delete cxid:0xfb4 zxi
d:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1301965517
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:35,363 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x1001
86ea825fa45 type:delete cxid:0xfb0 zxid:0x8e06e3d4bc txntype:2 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:35,465 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x1001
86ea825fa45 type:create cxid:0xfb1 zxid:0x8e06e3d718 txntype:1 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:35,804 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x1001
86ea825fa45 type:delete cxid:0xfb2 zxid:0x8e06e3de59 txntype:2 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:35,882 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x1001
86ea825fa45 type:create cxid:0xfb3 zxid:0x8e06e3dfe6 txntype:1 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:55:36,150 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x1001
86ea825fa45 type:delete cxid:0xfb4 zxid:0x8e06e3e4c8 txntype:2 reqpath:n/a
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:56:03,132 - WARN
[NIOWorkerThread-16] - Unable to read additional data from client sessionid
0x100186ea825fa45, likely clie
nt has closed socket
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:56:03,136 - INFO
[FollowerRequestProcessor:4] - Processing request:: sessionid:0x100186ea825fa45
type:create cxid:0xfb5 zxid:0xfffffffffffffffe txntype:unknown
reqpath:/loadgen/load_
/var/log/zookeeper/zookeeper-info.log.67:2017-02-06 20:56:04,123 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x100186ea825fa45 type:error cxid:0xfb5 zxid:0x8e06e60288
txntype:-1 reqpath:n/a
2017-02-06 20:56:03,136 - INFO [FollowerRequestProcessor:4] - Processing
request:: sessionid:0x100186ea825fa45 type:create cxid:0xfb5
zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_
2017-02-06 20:56:04,123 - INFO
[QuorumPeer[myid=4](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled)] - Committing
request:: sessionid:0x100186ea825fa45 type:error cxid:0xfb5 zxid:0x8e06e60288
txntype:-1 reqpath:n/a
the leader got 0xfb5 first
2017-02-06 20:56:04,122 - INFO [ProcessThread(sid:1 cport:-1):] - Leader
proposing: sessionid:0x100186ea825fa45 type:create cxid:0xfb5 zxid:0x8e06e60288
txntype:-1 reqpath:n/a
2017-02-06 20:56:04,122 - INFO [LearnerHandler-/10.40.89.122:42232] - Commit a
proposal: sessionid:0x100186ea825fa45 type:create cxid:0xfb5 zxid:0x8e06e60288
txntype:-1 reqpath:n/a
and then 0xfb6
2017-02-06 20:56:04,610 - INFO [ProcessThread(sid:1 cport:-1):] - Leader
proposing: sessionid:0x100186ea825fa45 type:create cxid:0xfb6 zxid:0x8e06e60bfb
txntype:1 reqpath:n/a
2017-02-06 20:56:04,611 - INFO [LearnerHandler-/10.40.91.124:52180] - Commit a
proposal: sessionid:0x100186ea825fa45 type:create cxid:0xfb6 zxid:0x8e06e60bfb
txntype:1 reqpath:n/a
So there is no out of order commit but the session queue in the commitProcessor
gets created before the last commit from previous session life comes.
> Fix a crashing bug in the mixed workloads commit processor
> ----------------------------------------------------------
>
> Key: ZOOKEEPER-2684
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2684
> Project: ZooKeeper
> Issue Type: Bug
> Components: server
> Affects Versions: 3.6.0
> Environment: with pretty heavy load on a real cluster
> Reporter: Ryan Zhang
> Assignee: Ryan Zhang
> Priority: Blocker
>
> We deployed our build with ZOOKEEPER-2024 and it quickly started to crash
> with the following error
> atla-buh-05-sr1.prod.twttr.net: 2017-01-18 22:24:42,305 - ERROR
> [CommitProcessor:2]
> -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:268)
> – Got cxid 0x119fa expected 0x11fc5 for client session id 1009079ba470055
> atla-buh-05-sr1.prod.twttr.net: 2017-01-18 22:32:04,746 - ERROR
> [CommitProcessor:2]
> -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:268)
> – Got cxid 0x698 expected 0x928 for client session id 4002eeb3fd0009d
> atla-buh-05-sr1.prod.twttr.net: 2017-01-18 22:34:46,648 - ERROR
> [CommitProcessor:2]
> -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:268)
> – Got cxid 0x8904 expected 0x8f34 for client session id 51b8905c90251
> atla-buh-05-sr1.prod.twttr.net: 2017-01-18 22:43:46,834 - ERROR
> [CommitProcessor:2]
> -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:268)
> – Got cxid 0x3a8d expected 0x3ebc for client session id 2051af11af900cc
> clearly something is not right in the new commit processor per session queue
> implementation.
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
