From dev-return-67939-archive-asf-public=cust-asf.ponee.io@zookeeper.apache.org Fri Mar 2 15:09:06 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id A226F18062F for ; Fri, 2 Mar 2018 15:09:05 +0100 (CET) Received: (qmail 57927 invoked by uid 500); 2 Mar 2018 14:09:04 -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 57912 invoked by uid 99); 2 Mar 2018 14:09:04 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 02 Mar 2018 14:09:04 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 14A9F1A06B6 for ; Fri, 2 Mar 2018 14:09:04 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -101.511 X-Spam-Level: X-Spam-Status: No, score=-101.511 tagged_above=-999 required=6.31 tests=[KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, T_RP_MATCHES_RCVD=-0.01, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id mJbYVBZXZ_89 for ; Fri, 2 Mar 2018 14:09:01 +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 1539D5F39F for ; Fri, 2 Mar 2018 14:09:01 +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 7A947E0218 for ; Fri, 2 Mar 2018 14:09:00 +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 3262A2476C for ; Fri, 2 Mar 2018 14:09:00 +0000 (UTC) Date: Fri, 2 Mar 2018 14:09:00 +0000 (UTC) From: "Artyom Kravchenko (JIRA)" To: dev@zookeeper.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (ZOOKEEPER-2219) ZooKeeper server should better handle SessionMovedException. MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/ZOOKEEPER-2219?page=3Dcom.atlas= sian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D= 16383602#comment-16383602 ]=20 Artyom Kravchenko commented on ZOOKEEPER-2219: ---------------------------------------------- Hi=C2=A0 I have faced with similar issue. I use: server: Zookeeper server 3.4.11 (need to make cluster of solr instances), S= olr Server 7.2.1=C2=A0 client: CloudSolrClient (org.apache.solr:solr-solrj:7.1.0 and org.apache.zo= okeeper:zookeeper:3.4.10)=C2=A0 =C2=A0 After some time of work client=C2=A0falls off. Server logs: {code:java} 2018-02-28 15:04:04,131 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:ZooKeeperServer@942] - Client attempting to establish new session = at /10.100.53.1:52830 2018-02-28 15:04:04,133 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer= @687] - Established session 0x261c838af810485 with negotiated timeout 10000= for client /10.100.48.1:52827 2018-02-28 15:04:04,135 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer= @687] - Established session 0x261c838af810486 with negotiated timeout 10000= for client /10.100.80.1:52829 2018-02-28 15:04:04,136 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer= @687] - Established session 0x261c838af810487 with negotiated timeout 10000= for client /10.100.53.1:52830 2018-02-28 15:04:08,085 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxnFactory@192] - Accepted socket connection from /127.0= .0.1:52832 2018-02-28 15:04:08,085 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxn@883] - Processing ruok command from /127.0.0.1:52832 2018-02-28 15:04:08,086 [myid:2] - INFO [Thread-281185:NIOServerCnxn@1044]= - Closed socket connection for client /127.0.0.1:52832 (no session establi= shed for client) -- -- =09at java.lang.Thread.run(Thread.java:748) 2018-02-28 15:04:23,955 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxn@1044] - Closed socket connection for client /10.100.= 80.1:52829 which had sessionid 0x261c838af810486 2018-02-28 15:04:23,955 [myid:2] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxn@368] - caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid = 0x261c838af810487, likely client has closed socket =09at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239= ) =09at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFac= tory.java:203) =09at java.lang.Thread.run(Thread.java:748) -- -- =09at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239= ) =09at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFac= tory.java:203) =09at java.lang.Thread.run(Thread.java:748) 2018-02-28 15:04:23,956 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxn@1044] - Closed socket connection for client /10.100.= 53.1:52830 which had sessionid 0x261c838af810487 2018-02-28 15:04:23,956 [myid:2] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxn@368] - caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid = 0x261c838af810485, likely client has closed socket =09at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239= ) -- -- 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:ZooKeeperServer@942] - Client attempting to establish new session = at /10.100.48.1:52840 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxnFactory@192] - Accepted socket connection from /10.10= 0.80.1:52841 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxnFactory@192] - Accepted socket connection from /10.10= 0.53.1:52842 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:ZooKeeperServer@935] - Client attempting to renew session 0x261c83= 8af810487 at /10.100.80.1:52841 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:Learner@108] - Revalidating client: 0x261c838af810487 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:ZooKeeperServer@935] - Client attempting to renew session 0x261c83= 8af810486 at /10.100.53.1:52842 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:Learner@108] - Revalidating client: 0x261c838af810486 -- 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:ZooKeeperServer@935] - Client attempting to renew session 0x261c83= 8af810486 at /10.100.53.1:52842 2018-02-28 15:04:36,586 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:Learner@108] - Revalidating client: 0x261c838af810486 2018-02-28 15:04:36,587 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:2181:ZooKeeperServer@680] - Invalid session 0x261c838af810487 for clien= t /10.100.80.1:52841, probably expired 2018-02-28 15:04:36,587 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:2181:ZooKeeperServer@680] - Invalid session 0x261c838af810486 for clien= t /10.100.53.1:52842, probably expired -- 2018-02-28 15:04:36,587 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:2181:ZooKeeperServer@680] - Invalid session 0x261c838af810486 for clien= t /10.100.53.1:52842, probably expired 2018-02-28 15:04:36,592 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxn@1044] - Closed socket connection for client /10.100.= 80.1:52841 which had sessionid 0x261c838af810487 2018-02-28 15:04:36,592 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxn@1044] - Closed socket connection for client /10.100.= 53.1:52842 which had sessionid 0x261c838af810486 2018-02-28 15:04:36,595 [myid:2] - INFO [CommitProcessor:2:ZooKeeperServer= @687] - Established session 0x261c838af810488 with negotiated timeout 10000= for client /10.100.48.1:52840 2018-02-28 15:04:38,368 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:2181:NIOServerCnxnFactory@192] - Accepted socket connection from /127.0= .0.1:52844{code} =C2=A0 Client logs: {code:java} Unable to reconnect to ZooKeeper service, session 0x261c838af810487 has exp= ired {code} Could anybody provide some update about this issue =C2=A0 =C2=A0 > ZooKeeper server should better handle SessionMovedException. > ------------------------------------------------------------ > > Key: ZOOKEEPER-2219 > URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2219 > Project: ZooKeeper > Issue Type: Bug > Affects Versions: 3.4.5 > Reporter: zhihai xu > Priority: Major > > ZooKeeper server should better handle SessionMovedException. > We hit the SessionMovedException. the following is the reason for the Ses= sionMovedException we find: > 1. ZK client tried to connect to Leader L. Network was very slow, so befo= re leader processed the request, client disconnected. > 2. Client then re-connected to Follower F reusing the same session ID. It= was successful. > 3. The request in step 1 went into leader. Leader processed it and invali= dated the connection created in step 2. But client didn't know the connecti= on it used is invalidated. > 4. Client got SessionMovedException when it used the connection invalidat= ed by leader for any ZooKeeper operation. > The following are logs: c045dkh is the Leader, c470udy is the Follower an= d the sessionID is 0x14be28f50f4419d. > 1. ZK client try to initiate session to Leader at 015-03-16 10:59:40,735 = and timeout after 10/3 seconds. > logs from ZK client=20 > {code} > 2015-03-16 10:59:40,078 INFO org.apache.zookeeper.ClientCnxn: Client sess= ion timed out, have not heard from server in 6670ms for sessionid 0x14be28f= 50f4419d, closing socket connection and attempting reconnect > 015-03-16 10:59:40,735 INFO org.apache.zookeeper.ClientCnxn: Opening sock= et connection to server c045dkh/?.?.?.67:2181. Will not attempt to authenti= cate using SASL (unknown error) > 2015-03-16 10:59:40,735 INFO org.apache.zookeeper.ClientCnxn: Socket conn= ection established to c045dkh/?.?.?.67:2181, initiating session > 2015-03-16 10:59:44,071 INFO org.apache.zookeeper.ClientCnxn: Client sess= ion timed out, have not heard from server in 3336ms for sessionid 0x14be28f= 50f4419d, closing socket connection and attempting reconnect > {code} > 2. ZK client initiated session to Follower successfully at 2015-03-16 10:= 59:44,688 > logs from ZK client > {code} > 2015-03-16 10:59:44,673 INFO org.apache.zookeeper.ClientCnxn: Opening soc= ket connection to server c470udy/?.?.?.65:2181. Will not attempt to authent= icate using SASL (unknown error) > 2015-03-16 10:59:44,673 INFO org.apache.zookeeper.ClientCnxn: Socket conn= ection established to c470udy/?.?.?.65:2181, initiating session > 2015-03-16 10:59:44,688 INFO org.apache.zookeeper.ClientCnxn: Session est= ablishment complete on server c470udy/?.?.?.65:2181, sessionid =3D 0x14be28= f50f4419d, negotiated timeout =3D 10000 > {code} > logs from ZK Follower server > {code} > 2015-03-16 10:59:44,673 INFO org.apache.zookeeper.server.NIOServerCnxnFac= tory: Accepted socket connection from /?.?.?.65:42777 > 2015-03-16 10:59:44,674 INFO org.apache.zookeeper.server.ZooKeeperServer:= Client attempting to renew session 0x14be28f50f4419d at /?.?.?.65:42777 > 2015-03-16 10:59:44,674 INFO org.apache.zookeeper.server.quorum.Learner: = Revalidating client: 0x14be28f50f4419d > 2015-03-16 10:59:44,675 INFO org.apache.zookeeper.server.ZooKeeperServer:= Established session 0x14be28f50f4419d with negotiated timeout 10000 for cl= ient /?.?.?.65:42777 > {code} > 3. At 2015-03-16 10:59:45,668, Leader processed the delayed request which= is sent by Client at 2015-03-16 10:59:40,735, right after session was esta= blished, it close the socket connection/session because client was already = disconnected due to timeout. > logs from ZK Leader server > {code} > 2015-03-16 10:59:45,668 INFO org.apache.zookeeper.server.ZooKeeperServer:= Client attempting to renew session 0x14be28f50f4419d at /?.?.?.65:50271 > 2015-03-16 10:59:45,668 INFO org.apache.zookeeper.server.ZooKeeperServer:= Established session 0x14be28f50f4419d with negotiated timeout 10000 for cl= ient /?.?.?.65:50271 > 2015-03-16 10:59:45,670 WARN org.apache.zookeeper.server.NIOServerCnxn: E= xception causing close of session 0x14be28f50f4419d due to java.io.IOExcept= ion: Broken pipe > 2015-03-16 10:59:45,671 INFO org.apache.zookeeper.server.NIOServerCnxn: C= losed socket connection for client /?.?.?.65:50271 which had sessionid 0x14= be28f50f4419d > {code} > 4. Client got SessionMovedException at 2015-03-16 10:59:45,693 > logs from ZK Leader server > {code} > 2015-03-16 10:59:45,693 INFO org.apache.zookeeper.server.PrepRequestProce= ssor: Got user-level KeeperException when processing sessionid:0x14be28f50f= 4419d type:multi cxid:0x86e3 zxid:0x1c002a4e53 txntype:-1 reqpath:n/a abort= ing remaining multi ops. Error Path:null Error:KeeperErrorCode =3D Session = moved > 2015-03-16 10:59:45,695 INFO org.apache.zookeeper.server.PrepRequestProce= ssor: Got user-level KeeperException when processing sessionid:0x14be28f50f= 4419d type:multi cxid:0x86e5 zxid:0x1c002a4e56 txntype:-1 reqpath:n/a abort= ing remaining multi ops. Error Path:null Error:KeeperErrorCode =3D Session = moved > 2015-03-16 10:59:45,700 INFO org.apache.zookeeper.server.PrepRequestProce= ssor: Got user-level KeeperException when processing sessionid:0x14be28f50f= 4419d type:multi cxid:0x86e7 zxid:0x1c002a4e57 txntype:-1 reqpath:n/a abort= ing remaining multi ops. Error Path:null Error:KeeperErrorCode =3D Session = moved > {code} > 5. At 2015-03-16 10:59:45,710, we close the session 0x14be28f50f4419d but= the socket connection between ZK client and ZK Follower is closed at 2015-= 03-16 10:59:45,715 after session termination. > logs from ZK Leader server: > {code} > 2015-03-16 10:59:45,710 INFO org.apache.zookeeper.server.PrepRequestProce= ssor: Processed session termination for sessionid: 0x14be28f50f4419d > {code} > logs from ZK Follower server: > {code} > 2015-03-16 10:59:45,715 INFO org.apache.zookeeper.server.NIOServerCnxn: C= losed socket connection for client /?.?.?.65:42777 which had sessionid 0x14= be28f50f4419d > {code} > It looks like Zk client is out-of-sync with ZK server. > My question is how ZK client can recover from this error. It looks like t= he ZK Client won't be disconnected from Follower until session is closed an= d any ZooKeeper operation will fail with SessionMovedException before sessi= on is closed. > Also since ZK Leader already closed the socket connection/session to ZK C= lient at step 3, why it still reject the ZooKeeper operation from client wi= th SessionMovedException. Will it be better to endorse the session/connecti= on between ZK client and ZK Follower? This seems like a bug to me.=20 -- This message was sent by Atlassian JIRA (v7.6.3#76005)