[
https://issues.apache.org/jira/browse/ZOOKEEPER-4921?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17946907#comment-17946907
]
Chuong Tran edited comment on ZOOKEEPER-4921 at 4/24/25 2:34 AM:
-----------------------------------------------------------------
[~kezhuw] This is the full log of 3.9.3:
{
"time" : "2025-04-23T18:51:35.611-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Session 0x100707c2dc261da for server XXX/YYYY:2181, Closing socket
connection. Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$ConnectionTimeoutException: Client connection
timed out, have not heard from server in 2667ms for session id 0x100707c2dc261da
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1259)
"
}
{
"time" : "2025-04-23T18:51:37.218-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "Opening socket connection to server XXX/YYYY:2181."
}
{
"time" : "2025-04-23T18:51:37.219-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "SASL config status: Will not attempt to authenticate using SASL
(unknown error)"
}
{
"time" : "2025-04-23T18:51:41.355-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Client session timed out, have not heard from server in 8393ms for
session id 0x100707c2dc261da"
}
{
"time" : "2025-04-23T18:51:41.360-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Session 0x100707c2dc261da for server XXX/YYYY:2181, Closing socket
connection. Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$SessionTimeoutException: Client session timed
out, have not heard from server in 8393ms for session id 0x100707c2dc261da
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1253)
"
}
Apr 23, 2025 6:51:41 PM com.twitter.finagle.common.zookeeper.ZooKeeperClient$3
process
INFO: Zookeeper session expired. Event: WatchedEvent state:Expired type:None
path:null zxid: -1
{
"time" : "2025-04-23T18:51:41.588-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-EventThread",
"level" : "INFO",
"message" : "EventThread shut down for session: 0x100707c2dc261da"
}
{
"time" : "2025-04-23T18:51:41.595-07:00",
"logger_name" : "org.apache.zookeeper.ZooKeeper",
"thread_name" : "ZookeeperClient-watcherProcessor",
"level" : "INFO",
"message" : "Initiating client connection, connectString=XXX:2181
sessionTimeout=4000
watcher=com.twitter.finagle.common.zookeeper.ZooKeeperClient$3@6ecbbfdf"
}
{
"time" : "2025-04-23T18:51:41.596-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxnSocket",
"thread_name" : "ZookeeperClient-watcherProcessor",
"level" : "INFO",
"message" : "jute.maxbuffer value is 1048575 Bytes"
}
{
"time" : "2025-04-23T18:51:41.597-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor",
"level" : "INFO",
"message" : "zookeeper.request.timeout value is 0. feature enabled=false"
}
{
"time" : "2025-04-23T18:51:41.600-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "Opening socket connection to server XXX/YYYY:2181."
}
{
"time" : "2025-04-23T18:51:41.601-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "SASL config status: Will not attempt to authenticate using SASL
(unknown error)"
}
{
"time" : "2025-04-23T18:51:45.613-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Session 0x0 for server XXX/YYYY:2181, Closing socket connection.
Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$ConnectionTimeoutException: Client connection
timed out, have not heard from server in 4005ms for session id 0x0
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1259)
"
}
{
"time" : "2025-04-23T18:51:46.730-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "Opening socket connection to server XXX/YYYY:2181."
}
{
"time" : "2025-04-23T18:51:46.730-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "SASL config status: Will not attempt to authenticate using SASL
(unknown error)"
}
{
"time" : "2025-04-23T18:51:50.732-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Client session timed out, have not heard from server in 9134ms for
session id 0x0"
}
{
"time" : "2025-04-23T18:51:50.732-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Session 0x0 for server XXX/YYYY:2181, Closing socket connection.
Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$SessionTimeoutException: Client session timed
out, have not heard from server in 9134ms for session id 0x0
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1253)
"
}
Apr 23, 2025 6:51:50 PM com.twitter.finagle.common.zookeeper.ZooKeeperClient$3
process
INFO: Zookeeper session expired. Event: WatchedEvent state:Expired type:None
path:null zxid: -1
was (Author: JIRAUSER309503):
[~kezhuw] This is the full log of 3.9.3:
{quote}{
"time" : "2025-04-23T18:51:35.611-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",{{"level" : "WARN",}}
"myid" : "XXX:2181",
"message" : "Session 0x100707c2dc261da for server XXX/YYYY:2181, Closing socket
connection. Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$ConnectionTimeoutException: Client connection
timed out, have not heard from server in 2667ms for session id 0x100707c2dc261da
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1259)
"
}
{
"time" : "2025-04-23T18:51:37.218-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "Opening socket connection to server XXX/YYYY:2181."
}
{
"time" : "2025-04-23T18:51:37.219-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "SASL config status: Will not attempt to authenticate using SASL
(unknown error)"
}
{
"time" : "2025-04-23T18:51:41.355-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Client session timed out, have not heard from server in 8393ms for
session id 0x100707c2dc261da"
}
{
"time" : "2025-04-23T18:51:41.360-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Session 0x100707c2dc261da for server XXX/YYYY:2181, Closing socket
connection. Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$SessionTimeoutException: Client session timed
out, have not heard from server in 8393ms for session id 0x100707c2dc261da
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1253)
"
}
Apr 23, 2025 6:51:41 PM com.twitter.finagle.common.zookeeper.ZooKeeperClient$3
process
INFO: Zookeeper session expired. Event: WatchedEvent state:Expired type:None
path:null zxid: -1
{
"time" : "2025-04-23T18:51:41.588-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZkAnnouncer Mutator-EventThread",
"level" : "INFO",
"message" : "EventThread shut down for session: 0x100707c2dc261da"
}
{
"time" : "2025-04-23T18:51:41.595-07:00",
"logger_name" : "org.apache.zookeeper.ZooKeeper",
"thread_name" : "ZookeeperClient-watcherProcessor",
"level" : "INFO",
"message" : "Initiating client connection, connectString=XXX:2181
sessionTimeout=4000
watcher=com.twitter.finagle.common.zookeeper.ZooKeeperClient$3@6ecbbfdf"
}
{
"time" : "2025-04-23T18:51:41.596-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxnSocket",
"thread_name" : "ZookeeperClient-watcherProcessor",
"level" : "INFO",
"message" : "jute.maxbuffer value is 1048575 Bytes"
}
{
"time" : "2025-04-23T18:51:41.597-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor",
"level" : "INFO",
"message" : "zookeeper.request.timeout value is 0. feature enabled=false"
}
{
"time" : "2025-04-23T18:51:41.600-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "Opening socket connection to server XXX/YYYY:2181."
}
{
"time" : "2025-04-23T18:51:41.601-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "SASL config status: Will not attempt to authenticate using SASL
(unknown error)"
}
{
"time" : "2025-04-23T18:51:45.613-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Session 0x0 for server XXX/YYYY:2181, Closing socket connection.
Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$ConnectionTimeoutException: Client connection
timed out, have not heard from server in 4005ms for session id 0x0
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1259)
"
}
{
"time" : "2025-04-23T18:51:46.730-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "Opening socket connection to server XXX/YYYY:2181."
}
{
"time" : "2025-04-23T18:51:46.730-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "INFO",
"myid" : "XXX:2181",
"message" : "SASL config status: Will not attempt to authenticate using SASL
(unknown error)"
}
{
"time" : "2025-04-23T18:51:50.732-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Client session timed out, have not heard from server in 9134ms for
session id 0x0"
}
{
"time" : "2025-04-23T18:51:50.732-07:00",
"logger_name" : "org.apache.zookeeper.ClientCnxn",
"thread_name" : "ZookeeperClient-watcherProcessor-SendThread(XXX:2181)",
"level" : "WARN",
"myid" : "XXX:2181",
"message" : "Session 0x0 for server XXX/YYYY:2181, Closing socket connection.
Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.",
"stackTrace" : "o.a.z.ClientCnxn$SessionTimeoutException: Client session timed
out, have not heard from server in 9134ms for session id 0x0
at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1253)
"
}
Apr 23, 2025 6:51:50 PM com.twitter.finagle.common.zookeeper.ZooKeeperClient$3
process
INFO: Zookeeper session expired. Event: WatchedEvent state:Expired type:None
path:null zxid: -1{quote}
> Zookeeper Client 3.9.3 Fails to Reconnect After Network Failures
> ----------------------------------------------------------------
>
> Key: ZOOKEEPER-4921
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-4921
> Project: ZooKeeper
> Issue Type: Bug
> Components: java client
> Affects Versions: 3.9.3
> Reporter: Chuong Tran
> Priority: Critical
>
> After upgrading the Java Zookeeper client to version 3.9.3, we observed that
> it is not resilient to brief network disruptions, such as a short VPN blip.
> In such cases, the client attempts to reconnect only once, and if
> unsuccessful, the session expires.
> {quote}Apr 23, 2025 10:19:23 AM
> com.twitter.finagle.common.zookeeper.ZooKeeperClient$3 process
> INFO: Zookeeper session expired. Event: WatchedEvent state:Expired type:None
> path:null zxid: -1
> {quote}
> In contrast, the previous version (3.9.2) would continuously retry until the
> network connection was restored, maintaining the session more reliably.
> I believe it's a new issue with this change:
> https://issues.apache.org/jira/browse/ZOOKEEPER-4508
>
> Step to repro:
> # Open VPN.
> # Start the application which connects to the Zookeeper server with the VPN.
> # Disable VPN for a couple of minutes.
> # Observe the application.
> # Enable the VPN again.
> {quote}3.9.3:
> "message" : "Session 0x0 for server XXX, Closing socket connection.
> Attempting reconnect except it is a SessionExpiredException or
> SessionTimeoutException.",
> "stackTrace" : "o.a.z.ClientCnxn$SessionTimeoutException: Client session
> timed out, have not heard from server in 5590ms for session id 0x0
> at o.a.z.ClientCnxn$SendThread.run(ClientCnxn.java:1253)
> {quote}
> 3.9.2: Application will be reconnected successfully.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
