zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Ryan Zhang (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (ZOOKEEPER-2684) Fix a crashing bug in the mixed workloads commit processor
Date Tue, 07 Feb 2017 23:24:41 GMT

    [ 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)

Mime
View raw message