[
https://issues.apache.org/jira/browse/ZOOKEEPER-3828?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17118301#comment-17118301
]
Aishwarya Soni commented on ZOOKEEPER-3828:
-------------------------------------------
This is what we see in the zookeeper CLI client logs (do not map the session ID
from the below snippet with the attached logs),
{noformat}
/opt/zookeeper # ./bin/zkCli.sh
Connecting to localhost:2181
2020-05-27 00:08:23,709 [myid:] - INFO [main:Environment@98] - Client
environment:zookeeper.version=3.6.1--104dcb3e3fb464b30c5186d229e00af9f332524b,
built on 04/21/2020 15:01 GMT
2020-05-27 00:08:23,712 [myid:] - INFO [main:Environment@98] - Client
environment:host.name=e8bf5996ce14
2020-05-27 00:08:23,712 [myid:] - INFO [main:Environment@98] - Client
environment:java.version=1.8.0_211
2020-05-27 00:08:23,713 [myid:] - INFO [main:Environment@98] - Client
environment:java.vendor=Oracle Corporation
2020-05-27 00:08:23,713 [myid:] - INFO [main:Environment@98] - Client
environment:java.home=/opt/jdk1.8.0_211/jre
2020-05-27 00:08:23,713 [myid:] - INFO [main:Environment@98] - Client
environment:java.class.path=/opt/zookeeper/bin/../zookeeper-server/target/classes:/opt/zookeeper/bin/../build/classes:/opt/zookeeper/bin/../zookeeper-server/target/lib/*.jar:/opt/zookeeper/bin/../build/lib/*.jar:/opt/zookeeper/bin/../lib/zookeeper-prometheus-metrics-3.6.1.jar:/opt/zookeeper/bin/../lib/zookeeper-jute-3.6.1.jar:/opt/zookeeper/bin/../lib/zookeeper-3.6.1.jar:/opt/zookeeper/bin/../lib/snappy-java-1.1.7.jar:/opt/zookeeper/bin/../lib/slf4j-log4j12-1.7.25.jar:/opt/zookeeper/bin/../lib/slf4j-api-1.7.25.jar:/opt/zookeeper/bin/../lib/simpleclient_servlet-0.6.0.jar:/opt/zookeeper/bin/../lib/simpleclient_hotspot-0.6.0.jar:/opt/zookeeper/bin/../lib/simpleclient_common-0.6.0.jar:/opt/zookeeper/bin/../lib/simpleclient-0.6.0.jar:/opt/zookeeper/bin/../lib/netty-transport-native-unix-common-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/netty-transport-native-epoll-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/netty-transport-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/netty-resolver-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/netty-handler-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/netty-common-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/netty-codec-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/netty-buffer-4.1.48.Final.jar:/opt/zookeeper/bin/../lib/metrics-core-3.2.5.jar:/opt/zookeeper/bin/../lib/log4j-1.2.17.jar:/opt/zookeeper/bin/../lib/json-simple-1.1.1.jar:/opt/zookeeper/bin/../lib/jline-2.11.jar:/opt/zookeeper/bin/../lib/jetty-util-9.4.24.v20191120.jar:/opt/zookeeper/bin/../lib/jetty-servlet-9.4.24.v20191120.jar:/opt/zookeeper/bin/../lib/jetty-server-9.4.24.v20191120.jar:/opt/zookeeper/bin/../lib/jetty-security-9.4.24.v20191120.jar:/opt/zookeeper/bin/../lib/jetty-io-9.4.24.v20191120.jar:/opt/zookeeper/bin/../lib/jetty-http-9.4.24.v20191120.jar:/opt/zookeeper/bin/../lib/javax.servlet-api-3.1.0.jar:/opt/zookeeper/bin/../lib/jackson-databind-2.10.3.jar:/opt/zookeeper/bin/../lib/jackson-core-2.10.3.jar:/opt/zookeeper/bin/../lib/jackson-annotations-2.10.3.jar:/opt/zookeeper/bin/../lib/commons-lang-2.6.jar:/opt/zookeeper/bin/../lib/commons-cli-1.2.jar:/opt/zookeeper/bin/../lib/audience-annotations-0.5.0.jar:/opt/zookeeper/bin/../zookeeper-*.jar:/opt/zookeeper/bin/../zookeeper-server/src/main/resources/lib/*.jar:/opt/zookeeper/bin/../conf:
2020-05-27 00:08:23,713 [myid:] - INFO [main:Environment@98] - Client
environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
2020-05-27 00:08:23,713 [myid:] - INFO [main:Environment@98] - Client
environment:java.io.tmpdir=/tmp
2020-05-27 00:08:23,713 [myid:] - INFO [main:Environment@98] - Client
environment:java.compiler=<NA>
2020-05-27 00:08:23,714 [myid:] - INFO [main:Environment@98] - Client
environment:os.name=Linux
2020-05-27 00:08:23,714 [myid:] - INFO [main:Environment@98] - Client
environment:os.arch=amd64
2020-05-27 00:08:23,714 [myid:] - INFO [main:Environment@98] - Client
environment:os.version=4.4.0-1106-aws
2020-05-27 00:08:23,714 [myid:] - INFO [main:Environment@98] - Client
environment:user.name=root
2020-05-27 00:08:23,714 [myid:] - INFO [main:Environment@98] - Client
environment:user.home=/root
2020-05-27 00:08:23,714 [myid:] - INFO [main:Environment@98] - Client
environment:user.dir=/opt/zookeeper
2020-05-27 00:08:23,714 [myid:] - INFO [main:Environment@98] - Client
environment:os.memory.free=56MB
2020-05-27 00:08:23,715 [myid:] - INFO [main:Environment@98] - Client
environment:os.memory.max=247MB
2020-05-27 00:08:23,715 [myid:] - INFO [main:Environment@98] - Client
environment:os.memory.total=61MB
2020-05-27 00:08:23,718 [myid:] - INFO [main:ZooKeeper@1005] - Initiating
client connection, connectString=localhost:2181 sessionTimeout=30000
watcher=org.apache.zookeeper.ZooKeeperMain$MyWatcher@3d012ddd
2020-05-27 00:08:23,721 [myid:] - INFO [main:X509Util@77] - Setting -D
jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS
renegotiation
2020-05-27 00:08:23,725 [myid:] - INFO [main:ClientCnxnSocket@239] -
jute.maxbuffer value is 1048575 Bytes
2020-05-27 00:08:23,731 [myid:] - INFO [main:ClientCnxn@1703] -
zookeeper.request.timeout value is 0. feature enabled=false
Welcome to ZooKeeper!
2020-05-27 00:08:23,734 [myid:localhost:2181] - DEBUG
[main-SendThread(localhost:2181):SaslServerPrincipal@86] - Canonicalized
address to localhost
2020-05-27 00:08:23,735 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1154] - Opening socket
connection to server localhost/127.0.0.1:2181.
2020-05-27 00:08:23,735 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1156] - SASL config
status: Will not attempt to authenticate using SASL (unknown error)
JLine support is enabled
2020-05-27 00:08:23,772 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@986] - Socket connection
established, initiating session, client: /127.0.0.1:59132, server:
localhost/127.0.0.1:2181
2020-05-27 00:08:23,773 [myid:localhost:2181] - DEBUG
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1076] - Session
establishment request sent on localhost/127.0.0.1:2181
[zk: localhost:2181(CONNECTING) 0] ls /
2020-05-27 00:08:34,272 [myid:] - DEBUG [main:ZooKeeperMain@407] - Processing ls
2020-05-27 00:08:53,787 [myid:localhost:2181] - WARN
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1229] - Client session
timed out, have not heard from server in 30016ms for session id 0x0
2020-05-27 00:08:53,788 [myid:localhost:2181] - WARN
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1272] - Session 0x0 for
sever localhost/127.0.0.1:2181, Closing socket connection. Attempting reconnect
except it is a SessionExpiredException.
org.apache.zookeeper.ClientCnxn$SessionTimeoutException: Client session timed
out, have not heard from server in 30016ms for session id 0x0
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1230)
KeeperErrorCode = ConnectionLoss for /
[zk: localhost:2181(CONNECTING) 1] 2020-05-27 00:08:55,230
[myid:localhost:2181] - DEBUG
[main-SendThread(localhost:2181):SaslServerPrincipal@86] - Canonicalized
address to localhost
2020-05-27 00:08:55,231 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1154] - Opening socket
connection to server localhost/127.0.0.1:2181.
2020-05-27 00:08:55,231 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1156] - SASL config
status: Will not attempt to authenticate using SASL (unknown error)
2020-05-27 00:08:55,231 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@986] - Socket connection
established, initiating session, client: /127.0.0.1:59496, server:
localhost/127.0.0.1:2181
2020-05-27 00:08:55,231 [myid:localhost:2181] - DEBUG
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1076] - Session
establishment request sent on localhost/127.0.0.1:2181
2020-05-27 00:09:25,232 [myid:localhost:2181] - WARN
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1229] - Client session
timed out, have not heard from server in 30000ms for session id 0x0
2020-05-27 00:09:25,232 [myid:localhost:2181] - WARN
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1272] - Session 0x0 for
sever localhost/127.0.0.1:2181, Closing socket connection. Attempting reconnect
except it is a SessionExpiredException.
org.apache.zookeeper.ClientCnxn$SessionTimeoutException: Client session timed
out, have not heard from server in 30000ms for session id 0x0
at
org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1230){noformat}
If a connection is established, we see,
{noformat}
2020-05-28 04:24:44,613 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@986] - Socket connection
established, initiating session, client: /127.0.0.1:41934, server:
localhost/127.0.0.1:2181
2020-05-28 04:24:44,615 [myid:localhost:2181] - DEBUG
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1076] - Session
establishment request sent on localhost/127.0.0.1:2181
2020-05-28 04:24:44,619 [myid:localhost:2181] - INFO
[main-SendThread(localhost:2181):ClientCnxn$SendThread@1420] - Session
establishment complete on server localhost/127.0.0.1:2181, session id =
0x2005f4df3da0001, negotiated timeout = 30000
WATCHER:: WatchedEvent state:SyncConnected type:None path:null [zk:
localhost:2181(CONNECTED) 0] 2020-05-28 04:24:54,621 [myid:localhost:2181] -
DEBUG [main-SendThread(localhost:2181):ClientCnxn$SendThread@872] - Got ping
response for session id: 0x2005f4df3da0001 after 2ms.
{noformat}
> zookeeper CLI client gets connection timeout when thee leader is restarted
> --------------------------------------------------------------------------
>
> Key: ZOOKEEPER-3828
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-3828
> Project: ZooKeeper
> Issue Type: Bug
> Components: java client
> Affects Versions: 3.6.1
> Reporter: Aishwarya Soni
> Priority: Minor
> Attachments: node1.txt, node2.txt, node3.txt, node4.txt, node4.txt,
> node5.txt, search-zookeeper-node-5-new.0
>
>
> I have configured 5 nodes zookeeper cluster using 3.6.1 version in a docker
> containerized environment. As a part of some destructive testing, I restarted
> zookeeper leader. Now, re-election happened and all 5 nodes (containers) are
> back in good state with new leader. But when I login to one of the container
> and go inside zk Cli (./zkCli.sh) and run the cmd *ls /* I see below error,
> {color:#000000} {color}
> *{color:#000000}[zk: localhost:2181(CONNECTING) 1]{color}*
> *{color:#000000}[zk: localhost:2181(CONNECTING) 1] ls /{color}*
> *{color:#000000}2020-05-14 23:48:26,556 [myid:localhost:2181] - WARN
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1229] - Client session
> timed out, have not heard from server in 30001ms for session id 0x0{color}*
> *{color:#000000}2020-05-14 23:48:26,556 [myid:localhost:2181] - WARN
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1272] - Session 0x0
> for sever localhost/127.0.0.1:2181, Closing socket connection. Attempting
> reconnect except it is a SessionExpiredException.{color}*
> *{color:#000000}org.apache.zookeeper.ClientCnxn$SessionTimeoutException:
> Client session timed out, have not heard from server in 30001ms for session
> id 0x0{color}*
> *{color:#000000}at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1230){color}*
> *{color:#000000}KeeperErrorCode = ConnectionLoss for /{color}*
> *{color:#000000}[zk: localhost:2181(CONNECTING) 2] 2020-05-14 23:48:28,089
> [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1154] - Opening socket
> connection to server localhost/127.0.0.1:2181.{color}*
> *{color:#000000}2020-05-14 23:48:28,089 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1156] - SASL config
> status: Will not attempt to authenticate using SASL (unknown error){color}*
> *{color:#000000}2020-05-14 23:48:28,090 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@986] - Socket
> connection established, initiating session, client: /127.0.0.1:60384, server:
> localhost/127.0.0.1:2181{color}*
> *{color:#000000}2020-05-14 23:48:58,119 [myid:localhost:2181] - WARN
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1229] - Client session
> timed out, have not heard from server in 30030ms for session id 0x0{color}*
> *{color:#000000}2020-05-14 23:48:58,120 [myid:localhost:2181] - WARN
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1272] - Session 0x0
> for sever localhost/127.0.0.1:2181, Closing socket connection. Attempting
> reconnect except it is a SessionExpiredException.{color}*
> *{color:#000000}org.apache.zookeeper.ClientCnxn$SessionTimeoutException:
> Client session timed out, have not heard from server in 30030ms for session
> id 0x0{color}*
> *{color:#000000}at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1230){color}*
> *{color:#000000}2020-05-14 23:49:00,003 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1154] - Opening socket
> connection to server localhost/127.0.0.1:2181.{color}*
> *{color:#000000}2020-05-14 23:49:00,004 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1156] - SASL config
> status: Will not attempt to authenticate using SASL (unknown error){color}*
> *{color:#000000}2020-05-14 23:49:00,004 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@986] - Socket
> connection established, initiating session, client: /127.0.0.1:32936, server:
> localhost/127.0.0.1:2181{color}*
> *{color:#000000}2020-05-14 23:49:30,032 [myid:localhost:2181] - WARN
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1229] - Client session
> timed out, have not heard from server in 30029ms for session id 0x0{color}*
> *{color:#000000}2020-05-14 23:49:30,033 [myid:localhost:2181] - WARN
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1272] - Session 0x0
> for sever localhost/127.0.0.1:2181, Closing socket connection. Attempting
> reconnect except it is a SessionExpiredException.{color}*
> *{color:#000000}org.apache.zookeeper.ClientCnxn$SessionTimeoutException:
> Client session timed out, have not heard from server in 30029ms for session
> id 0x0{color}*
> *{color:#000000}at
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1230){color}*
> *{color:#000000}2020-05-14 23:49:31,230 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1154] - Opening socket
> connection to server localhost/127.0.0.1:2181.{color}*
> *{color:#000000}2020-05-14 23:49:31,230 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@1156] - SASL config
> status: Will not attempt to authenticate using SASL (unknown error){color}*
> *{color:#000000}2020-05-14 23:49:31,230 [myid:localhost:2181] - INFO
> [main-SendThread(localhost:2181):ClientCnxn$SendThread@986] - Socket
> connection established, initiating session, client: /127.0.0.1:33766, server:
> localhost/127.0.0.1:2181{color}*
> {color:#000000}Does anyone know what could possibly be wrong? For reference:
> https://issues.apache.org/jira/browse/ZOOKEEPER-2164{color}
> This behavior is observed on all the nodes when the leader is restarted. All
> is good when a follower is restarted.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
