Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 6F88D200C1D for ; Thu, 16 Feb 2017 07:53:51 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 6E192160B61; Thu, 16 Feb 2017 06:53:51 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 6DD5F160B57 for ; Thu, 16 Feb 2017 07:53:50 +0100 (CET) Received: (qmail 71987 invoked by uid 500); 16 Feb 2017 06:53:49 -0000 Mailing-List: contact dev-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list dev@zookeeper.apache.org Received: (qmail 71973 invoked by uid 99); 16 Feb 2017 06:53:49 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 16 Feb 2017 06:53:49 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id D359CC198A for ; Thu, 16 Feb 2017 06:53:48 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -1.999 X-Spam-Level: X-Spam-Status: No, score=-1.999 tagged_above=-999 required=6.31 tests=[KAM_LAZY_DOMAIN_SECURITY=1, RP_MATCHES_RCVD=-2.999] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id FSCCGSUV2dl0 for ; Thu, 16 Feb 2017 06:53:46 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 534915FB6B for ; Thu, 16 Feb 2017 06:53:46 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id B908DE07E1 for ; Thu, 16 Feb 2017 06:53:44 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id EFE9B24140 for ; Thu, 16 Feb 2017 06:53:42 +0000 (UTC) Date: Thu, 16 Feb 2017 06:53:42 +0000 (UTC) From: "Ryan Zhang (JIRA)" To: dev@zookeeper.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (ZOOKEEPER-2684) Fix a crashing bug in the mixed workloads commit processor MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Thu, 16 Feb 2017 06:53:51 -0000 [ https://issues.apache.org/jira/browse/ZOOKEEPER-2684?page=3Dcom.atlas= sian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D= 15869349#comment-15869349 ]=20 Ryan Zhang commented on ZOOKEEPER-2684: --------------------------------------- so here is what actually happened On the server A, the request is processed right after the session connectio= n is closed and the request is forwarded to the lead investigate.log:2017-02-14 23:30:50,373 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:getData cxid:0x14 = zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1775503086 investigate.log:2017-02-14 23:30:54,327 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:getData cxid:0x15 = zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1775503083 investigate.log:2017-02-14 23:30:57,888 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:getData cxid:0x16 = zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1775503084 investigate.log:2017-02-14 23:31:01,583 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:getData cxid:0x17 = zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1775493180 investigate.log:2017-02-14 23:31:04,867 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:getData cxid:0x18 = zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1775493181 investigate.log:2017-02-14 23:31:08,150 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:getData cxid:0x19 = zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1775985079 investigate.log:2017-02-14 23:31:12,672 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:getChildren2 cxid:= 0x1a zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen investigate.log:2017-02-14 23:31:17,293 - WARN [NIOWorkerThread-16] - Excep= tion causing close of session 0x4006b1b17808b0c: Broken pipe investigate.log:2017-02-14 23:31:17,297 - INFO [FollowerRequestProcessor:4]= - Processing request:: sessionid:0x4006b1b17808b0c type:delete cxid:0x1b z= xid:0xfffffffffffffffe txntype:unknown reqpath:/loadgen/load_1776069644 investigate.log:2017-02-14 23:31:21,816 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:delete cxid:0x27 zxid:0x385012a1e94 txntype:2 re= qpath:n/a investigate.log:2017-02-14 23:31:21,816 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:create cxid:0x28 zxid:0x385012a1e95 txntype:1 re= qpath:n/a investigate.log:2017-02-14 23:31:21,816 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:delete cxid:0x29 zxid:0x385012a1e96 txntype:2 re= qpath:n/a investigate.log:2017-02-14 23:31:21,816 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:create cxid:0x2a zxid:0x385012a1e98 txntype:1 re= qpath:n/a investigate.log:2017-02-14 23:31:21,817 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:delete cxid:0x2b zxid:0x385012a1e9b txntype:2 re= qpath:n/a investigate.log:2017-02-14 23:31:21,817 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:create cxid:0x2c zxid:0x385012a1e9c txntype:1 re= qpath:n/a investigate.log:2017-02-14 23:31:21,818 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:delete cxid:0x2d zxid:0x385012a1ea1 txntype:2 re= qpath:n/a investigate.log:2017-02-14 23:31:21,822 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:create cxid:0x2e zxid:0x385012a1eb8 txntype:1 re= qpath:n/a investigate.log:2017-02-14 23:31:21,824 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:delete cxid:0x2f zxid:0x385012a1ec0 txntype:2 re= qpath:n/a investigate.log:2017-02-14 23:31:21,833 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:create cxid:0x30 zxid:0x385012a1ee9 txntype:1 re= qpath:n/a investigate.log:2017-02-14 23:31:22,048 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:error cxid:0x1b zxid:0x385012a2156 txntype:-1 re= qpath:n/a investigate.log:2017-02-14 23:31:22,690 - ERROR [CommitProcessor:4] - Got r= equest sessionid:0x4006b1b17808b0c type:delete cxid:0x27 zxid:0x385012a1e94= txntype:2 reqpath:n/a investigate.log: but we are expecting request sessionid:0x4006b1b17808b0c t= ype:delete cxid:0x1b zxid:0xfffffffffffffffe txntype:unknown reqpath:/loadg= en/load_1776069644 investigate.log:2017-02-14 23:32:39,172 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:create cxid:0x4c zxid:0x385012b34fa txntype:1 re= qpath:n/a investigate.log:2017-02-14 23:32:48,677 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: sessio= nid:0x4006b1b17808b0c type:delete cxid:0x4e zxid:0x385012b6c31 txntype:2 re= qpath:n/a investigate.log:2017-02-14 23:32:54,580 - INFO [QuorumPeer[myid=3D4](plain= =3D/0:0:0:0:0:0:0:0:2181)(secure=3Ddisabled)] - Committing request:: se while on the lead side, the requests are arrived out of order (in terms of = Cxid)=20 2017-02-14 23:31:21,822 - INFO [LearnerHandler-/10.45.111.116:53431] - Comm= itting request:: sessionid:0x4006b1b17808b0c type:create cxid:0x2e zxid:0x3= 85012a1eb8 txntype:1 reqpath:n/a 2017-02-14 23:31:21,824 - INFO [LearnerHandler-/10.45.111.116:53431] - Comm= it a proposal: sessionid:0x4006b1b17808b0c type:delete cxid:0x2f zxid:0x385= 012a1ec0 txntype:2 reqpath:n/a 2017-02-14 23:31:21,824 - INFO [LearnerHandler-/10.45.111.116:53431] - Comm= itting request:: sessionid:0x4006b1b17808b0c type:delete cxid:0x2f zxid:0x3= 85012a1ec0 txntype:2 reqpath:n/a 2017-02-14 23:31:21,833 - INFO [LearnerHandler-/10.45.111.116:53431] - Comm= it a proposal: sessionid:0x4006b1b17808b0c type:create cxid:0x30 zxid:0x385= 012a1ee9 txntype:1 reqpath:n/a 2017-02-14 23:31:21,833 - INFO [LearnerHandler-/10.45.111.116:53431] - Comm= itting request:: sessionid:0x4006b1b17808b0c type:create cxid:0x30 zxid:0x3= 85012a1ee9 txntype:1 reqpath:n/a 2017-02-14 23:31:21,999 - DEBUG [ProcessThread(sid:1 cport:-1):] - Got user= -level KeeperException when processing sessionid:0x4006b1b17808b0c type:del= ete cxid:0x1b zxid:0x385012a2156 txntype:-1 reqpath:/loadgen/load_177606964= 4 Error Path:null Error:KeeperErrorCode =3D Session moved investigate.log.1:2017-02-14 23:31:21,999 - INFO [ProcessThread(sid:1 cport= :-1):] - Processing request:: sessionid:0x4006b1b17808b0c type:delete cxid:= 0x1b zxid:0x385012a2156 txntype:-1 reqpath:/loadgen/load_1776069644 investigate.log.1:2017-02-14 23:31:21,999 - INFO [ProcessThread(sid:1 cport= :-1):] - Leader proposing: sessionid:0x4006b1b17808b0c type:delete cxid:0x1= b zxid:0x385012a2156 txntype:-1 reqpath:/loadgen/load_1776069644 investigate.log.1:2017-02-14 23:31:22,048 - INFO [LearnerHandler-/10.45.112= .127:53292] - Commit a proposal: sessionid:0x4006b1b17808b0c type:delete cx= id:0x1b zxid:0x385012a2156 txntype:-1 reqpath:/loadgen/load_1776069644 investigate.log.1:2017-02-14 23:31:22,048 - INFO [LearnerHandler-/10.45.112= .127:53292] - Committing request:: sessionid:0x4006b1b17808b0c type:delete = cxid:0x1b zxid:0x385012a2156 txntype:-1 reqpath:/loadgen/load_1776069644 2017-02-14 23:31:26,728 - INFO [ProcessThread(sid:1 cport:-1):] - Processin= g request:: sessionid:0x4006b1b17808b0c type:delete cxid:0x32 zxid:0x385012= a3bd0 txntype:2 reqpath:n/a 2017-02-14 23:31:26,728 - INFO [ProcessThread(sid:1 cport:-1):] - Leader pr= oposing: sessionid:0x4006b1b17808b0c type:delete cxid:0x32 zxid:0x385012a3b= d0 txntype:2 reqpath:n/a 2017-02-14 23:31:26,728 - INFO [ProcessThread(sid:1 cport:-1):] - Processin= g request:: sessionid:0x4006b1b17808b0c type:create cxid:0x33 zxid:0x385012= a3bd1 txntype:1 reqpath:n/a Ideally, I would like to check if the server still owns the session (has a = connection open) but it seems there is no easy way to check that. Any thoug= hts? The worst case is just be like the un-patched version to not check at = all... > 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 > Attachments: ZOOKEEPER-2684.patch > > > 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 [CommitPr= ocessor:2] -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitPr= ocessor.java:268) =E2=80=93 Got cxid 0x119fa expected 0x11fc5 for client se= ssion id 1009079ba470055 > atla-buh-05-sr1.prod.twttr.net: 2017-01-18 22:32:04,746 - ERROR [CommitPr= ocessor:2] -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitPr= ocessor.java:268) =E2=80=93 Got cxid 0x698 expected 0x928 for client sessio= n id 4002eeb3fd0009d > atla-buh-05-sr1.prod.twttr.net: 2017-01-18 22:34:46,648 - ERROR [CommitPr= ocessor:2] -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitPr= ocessor.java:268) =E2=80=93 Got cxid 0x8904 expected 0x8f34 for client sess= ion id 51b8905c90251 > atla-buh-05-sr1.prod.twttr.net: 2017-01-18 22:43:46,834 - ERROR [CommitPr= ocessor:2] -org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitPr= ocessor.java:268) =E2=80=93 Got cxid 0x3a8d expected 0x3ebc for client sess= ion id 2051af11af900cc > clearly something is not right in the new commit processor per session qu= eue implementation. -- This message was sent by Atlassian JIRA (v6.3.15#6346)