[jira] [Comment Edited] (ZOOKEEPER-2867) an expired ZK session can be re-established
[
https://issues.apache.org/jira/browse/ZOOKEEPER-2867?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16119048#comment-16119048
]
Jun Rao edited comment on ZOOKEEPER-2867 at 8/8/17 9:16 PM:
[~hanm], thanks for the explanation. The client on session 25cd1e82c110001
actually died around Aug 2, 23:16:11. From ZK server's log, the last ping from
that session was around that time. Then ZK server was restarted around 23:41:28.
{code:java}
August 2nd 2017, 23:16:11.086 DEBUG
org.apache.zookeeper.server.FinalRequestProcessor
sessionid:0x25cd1e82c110001 type:ping cxid:0xfffe
zxid:0xfffe txntype:unknown reqpath:n/a
August 2nd 2017, 23:16:11.086 DEBUG
org.apache.zookeeper.server.quorum.CommitProcessor Processing request::
sessionid:0x25cd1e82c110001 type:ping cxid:0xfffe
zxid:0xfffe txntype:unknown reqpath:n/a
August 2nd 2017, 23:41:28.699 INFO
org.apache.zookeeper.server.NIOServerCnxnFactorybinding to port
0.0.0.0/0.0.0.0:2181
August 2nd 2017, 23:41:29.149 DEBUG org.apache.zookeeper.server.DataTree
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
{code}
However, I couldn't find any entry about the closing of that session in ZK
commit log around that time. So, it's not clear to me if ZK server ever closed
that session. Should every closed session be in the ZK commit log?
was (Author: junrao):
[~hanm], thanks for the explanation. The client on session 25cd1e82c110001
actually died around Aug 2, 23:16:11. From ZK server's log, the last ping from
that session was around that time. Then ZK server was restarted around 23:41:28.
{code:java}
August 2nd 2017, 23:16:11.086 DEBUG
org.apache.zookeeper.server.FinalRequestProcessor
sessionid:0x25cd1e82c110001 type:ping cxid:0xfffe
zxid:0xfffe txntype:unknown reqpath:n/a
August 2nd 2017, 23:16:11.086 DEBUG
org.apache.zookeeper.server.quorum.CommitProcessor Processing request::
sessionid:0x25cd1e82c110001 type:ping cxid:0xfffe
zxid:0xfffe txntype:unknown reqpath:n/a
August 2nd 2017, 23:41:28.699 INFO
org.apache.zookeeper.server.NIOServerCnxnFactorybinding to port
0.0.0.0/0.0.0.0:2181
August 2nd 2017, 23:41:29.149 DEBUG org.apache.zookeeper.server.DataTree
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
{code}
However, I could find any entry about the closing of that session in ZK commit
log around that time. So, it's not clear to me if ZK server ever closed that
session. Should every closed session be in the ZK commit log?
> an expired ZK session can be re-established
> ---
>
> Key: ZOOKEEPER-2867
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2867
> Project: ZooKeeper
> Issue Type: Bug
>Affects Versions: 3.4.10
>Reporter: Jun Rao
> Attachments: zk.0.formatted, zk.1.formatted
>
>
> Not sure if this is a real bug, but I found an instance when a ZK client
> seems to be able to renew a session already expired by the ZK server.
> From ZK server log, session 25cd1e82c110001 was expired at 22:04:39.
> {code:java}
> June 27th 2017, 22:04:39.000 INFO
> org.apache.zookeeper.server.ZooKeeperServer Expiring session
> 0x25cd1e82c110001, timeout of 12000ms exceeded
> June 27th 2017, 22:04:39.001 DEBUG
> org.apache.zookeeper.server.quorum.Leader Proposing::
> sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0 zxid:0x20fc4
> txntype:-11 reqpath:n/a
> June 27th 2017, 22:04:39.001 INFO
> org.apache.zookeeper.server.PrepRequestProcessorProcessed session
> termination for sessionid: 0x25cd1e82c110001
> June 27th 2017, 22:04:39.001 DEBUG
> org.apache.zookeeper.server.quorum.CommitProcessor Processing request::
> sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0 zxid:0x20fc4
> txntype:-11 reqpath:n/a
> June 27th 2017, 22:05:20.324 INFO
> org.apache.zookeeper.server.quorum.Learner Revalidating client:
> 0x25cd1e82c110001
> June 27th 2017, 22:05:20.324 INFO
> org.apache.zookeeper.server.ZooKeeperServer Client attempting to renew
> session 0x25cd1e82c110001 at /100.96.5.6:47618
> June 27th 2017, 22:05:20.325 INFO
> org.apache.zookeeper.server.ZooKeeperServer Established session
> 0x25cd1e82c110001 with negotiated timeout 12000 for client /100.96.5.6:47618
> {code}
> From ZK client's log, it was able to renew the expired session on 22:05:20.
> {code:java}
> June 27th 2017, 22:05:18.590 INFOorg.apache.zookeeper.ClientCnxn Client
> session timed out, have not heard from server in 4485ms for sessionid
> 0x25cd1e82c110001, closing socket connection and attempting reconnect 0
> June 27th 2017, 22:05:18.590 WARNorg
[jira] [Comment Edited] (ZOOKEEPER-2867) an expired ZK session can be re-established
[
https://issues.apache.org/jira/browse/ZOOKEEPER-2867?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16117570#comment-16117570
]
Jun Rao edited comment on ZOOKEEPER-2867 at 8/7/17 11:51 PM:
-
[~hanm], thanks for the reply. I am attaching the log of 2 of the 3 ZK servers
around that time. During that window, there was some potential network issue
that may prevent ZK servers from talking to each other. The network issue seems
to be gone after 22:05:20, when the ZK cluster stabilized again.
Assuming that session 25cd1e82c110001 didn't really get expired at that point,
I got a followup question. A month later, the whole ZK cluster was down and was
restarted. On restarting, I saw the following logging in ZK server about
deleting an ephemeral in that session.
{code:java}
August 2nd 2017, 23:41:55.076 DEBUG org.apache.zookeeper.server.DataTree
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
{code}
I assume that's because ZK server thinks that session is expired? However, in
ZK server's commit log, I didn't find any entry about closing that session. Is
that normal? Thanks,
was (Author: junrao):
[~hanm], thanks for the reply. I am attaching the log of 2 of the 3 ZK servers
around that time. During that window, there was some potential network issue
that may prevent ZK servers from talking to each other. The network issue seems
to be gone after 22:05:20, when the ZK cluster stabilized again.
Assuming that session 25cd1e82c110001 didn't really get expired at that point,
I got a followup question. A month later, the whole ZK cluster was done and was
restarted. On restarting, I saw the following logging in ZK server about
deleting an ephemeral in that session.
{code:java}
August 2nd 2017, 23:41:55.076 DEBUG org.apache.zookeeper.server.DataTree
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
{code}
I assume that's because ZK server thinks that session is expired? However, in
ZK server's commit log, I didn't find any entry about closing that session. Is
that normal? Thanks,
> an expired ZK session can be re-established
> ---
>
> Key: ZOOKEEPER-2867
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2867
> Project: ZooKeeper
> Issue Type: Bug
>Affects Versions: 3.4.10
>Reporter: Jun Rao
> Attachments: zk.0.formatted, zk.1.formatted
>
>
> Not sure if this is a real bug, but I found an instance when a ZK client
> seems to be able to renew a session already expired by the ZK server.
> From ZK server log, session 25cd1e82c110001 was expired at 22:04:39.
> {code:java}
> June 27th 2017, 22:04:39.000 INFO
> org.apache.zookeeper.server.ZooKeeperServer Expiring session
> 0x25cd1e82c110001, timeout of 12000ms exceeded
> June 27th 2017, 22:04:39.001 DEBUG
> org.apache.zookeeper.server.quorum.Leader Proposing::
> sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0 zxid:0x20fc4
> txntype:-11 reqpath:n/a
> June 27th 2017, 22:04:39.001 INFO
> org.apache.zookeeper.server.PrepRequestProcessorProcessed session
> termination for sessionid: 0x25cd1e82c110001
> June 27th 2017, 22:04:39.001 DEBUG
> org.apache.zookeeper.server.quorum.CommitProcessor Processing request::
> sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0 zxid:0x20fc4
> txntype:-11 reqpath:n/a
> June 27th 2017, 22:05:20.324 INFO
> org.apache.zookeeper.server.quorum.Learner Revalidating client:
> 0x25cd1e82c110001
> June 27th 2017, 22:05:20.324 INFO
> org.apache.zookeeper.server.ZooKeeperServer Client attempting to renew
> session 0x25cd1e82c110001 at /100.96.5.6:47618
> June 27th 2017, 22:05:20.325 INFO
> org.apache.zookeeper.server.ZooKeeperServer Established session
> 0x25cd1e82c110001 with negotiated timeout 12000 for client /100.96.5.6:47618
> {code}
> From ZK client's log, it was able to renew the expired session on 22:05:20.
> {code:java}
> June 27th 2017, 22:05:18.590 INFOorg.apache.zookeeper.ClientCnxn Client
> session timed out, have not heard from server in 4485ms for sessionid
> 0x25cd1e82c110001, closing socket connection and attempting reconnect 0
> June 27th 2017, 22:05:18.590 WARNorg.apache.zookeeper.ClientCnxn Client
> session timed out, have not heard from server in 4485ms for sessionid
> 0x25cd1e82c110001 0
> June 27th 2017, 22:05:19.325 WARNorg.apache.zookeeper.ClientCnxn SASL
> configuration failed: javax.security.auth.login.LoginException: No JAAS
> configuration section named 'Client' was found in specified JAAS
> configuration file: '/opt/confluent/etc/kafka/server_jaas.conf'. Will
> continue connection to Zookeeper server without SASL authentication, if
> Zookeeper server allows it. 0
> June 27th 2017, 22:05
[jira] [Comment Edited] (ZOOKEEPER-2867) an expired ZK session can be re-established
[
https://issues.apache.org/jira/browse/ZOOKEEPER-2867?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16117570#comment-16117570
]
Jun Rao edited comment on ZOOKEEPER-2867 at 8/7/17 11:50 PM:
-
[~hanm], thanks for the reply. I am attaching the log of 2 of the 3 ZK servers
around that time. During that window, there was some potential network issue
that may prevent ZK servers from talking to each other. The network issue seems
to be gone after 22:05:20, when the ZK cluster stabilized again.
Assuming that session 25cd1e82c110001 didn't really get expired at that point,
I got a followup question. A month later, the whole ZK cluster was done and was
restarted. On restarting, I saw the following logging in ZK server about
deleting an ephemeral in that session.
{code:java}
August 2nd 2017, 23:41:55.076 DEBUG org.apache.zookeeper.server.DataTree
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
{code}
I assume that's because ZK server thinks that session is expired? However, in
ZK server's commit log, I didn't find any entry about closing that session. Is
that normal? Thanks,
was (Author: junrao):
[~hanm], thanks for the reply. I am attaching the log of 2 of the 3 ZK servers
around that time. During that window, there was some potential network issue
that may prevent ZK servers from talking to each other. The network issue seems
to be gone after 22:05:20, when the ZK cluster stabilized again.
Assuming that session 25cd1e82c110001 didn't really get expired at that point,
I got a followup question. A month later, the whole ZK cluster was done and was
restarted. On restarting, I saw the following logging in ZK server about
deleting an ephemeral in that session.
August 2nd 2017, 23:41:55.076 DEBUG org.apache.zookeeper.server.DataTree
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
I assume that's because ZK server thinks that session is expired? However, in
ZK server's commit log, I didn't find any entry about closing that session. Is
that normal? Thanks,
> an expired ZK session can be re-established
> ---
>
> Key: ZOOKEEPER-2867
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2867
> Project: ZooKeeper
> Issue Type: Bug
>Affects Versions: 3.4.10
>Reporter: Jun Rao
> Attachments: zk.0.formatted, zk.1.formatted
>
>
> Not sure if this is a real bug, but I found an instance when a ZK client
> seems to be able to renew a session already expired by the ZK server.
> From ZK server log, session 25cd1e82c110001 was expired at 22:04:39.
> {code:java}
> June 27th 2017, 22:04:39.000 INFO
> org.apache.zookeeper.server.ZooKeeperServer Expiring session
> 0x25cd1e82c110001, timeout of 12000ms exceeded
> June 27th 2017, 22:04:39.001 DEBUG
> org.apache.zookeeper.server.quorum.Leader Proposing::
> sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0 zxid:0x20fc4
> txntype:-11 reqpath:n/a
> June 27th 2017, 22:04:39.001 INFO
> org.apache.zookeeper.server.PrepRequestProcessorProcessed session
> termination for sessionid: 0x25cd1e82c110001
> June 27th 2017, 22:04:39.001 DEBUG
> org.apache.zookeeper.server.quorum.CommitProcessor Processing request::
> sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0 zxid:0x20fc4
> txntype:-11 reqpath:n/a
> June 27th 2017, 22:05:20.324 INFO
> org.apache.zookeeper.server.quorum.Learner Revalidating client:
> 0x25cd1e82c110001
> June 27th 2017, 22:05:20.324 INFO
> org.apache.zookeeper.server.ZooKeeperServer Client attempting to renew
> session 0x25cd1e82c110001 at /100.96.5.6:47618
> June 27th 2017, 22:05:20.325 INFO
> org.apache.zookeeper.server.ZooKeeperServer Established session
> 0x25cd1e82c110001 with negotiated timeout 12000 for client /100.96.5.6:47618
> {code}
> From ZK client's log, it was able to renew the expired session on 22:05:20.
> {code:java}
> June 27th 2017, 22:05:18.590 INFOorg.apache.zookeeper.ClientCnxn Client
> session timed out, have not heard from server in 4485ms for sessionid
> 0x25cd1e82c110001, closing socket connection and attempting reconnect 0
> June 27th 2017, 22:05:18.590 WARNorg.apache.zookeeper.ClientCnxn Client
> session timed out, have not heard from server in 4485ms for sessionid
> 0x25cd1e82c110001 0
> June 27th 2017, 22:05:19.325 WARNorg.apache.zookeeper.ClientCnxn SASL
> configuration failed: javax.security.auth.login.LoginException: No JAAS
> configuration section named 'Client' was found in specified JAAS
> configuration file: '/opt/confluent/etc/kafka/server_jaas.conf'. Will
> continue connection to Zookeeper server without SASL authentication, if
> Zookeeper server allows it. 0
> June 27th 2017, 22:05:19.326 INFOorg
