[
https://issues.apache.org/jira/browse/ZOOKEEPER-2867?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jun Rao updated ZOOKEEPER-2867:
-------------------------------
Attachment: zk.2.08-02
zk.0.08-02
zk.1.08-02
[~hanm], I found some additional info on Jun. 27. I actually do see session
25cd1e82c110001 being closed in the commit log on 2 of the 3 ZK servers.
First, I saw the following on ZK server 1's log4j log. It appears that it first
expired session 25cd1e82c110001. Then there was some ZK leader election,
potentially due to a network issue. Finally, it allowed a client to renew
session 25cd1e82c110001.
{code:java}
ZK 1 :
June 27th 2017, 22:04:39.000 org.apache.zookeeper.server.ZooKeeperServer
Expiring session 0x25cd1e82c110001, timeout of 12000ms exceeded
June 27th 2017, 22:04:39.001
org.apache.zookeeper.server.quorum.CommitProcessor Processing request::
sessionid:0x25cd1e82c110008 type:closeSession cxid:0x0 zxid:0x200000fc5
txntype:-11 reqpath:n/a
June 27th 2017, 22:04:39.001
org.apache.zookeeper.server.quorum.CommitProcessor Processing request::
sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0 zxid:0x200000fc4
txntype:-11 reqpath:n/a
June 27th 2017, 22:04:39.001 org.apache.zookeeper.server.quorum.Leader
Proposing:: sessionid:0x25cd1e82c110001 type:closeSession cxid:0x0
zxid:0x200000fc4 txntype:-11 reqpath:n/a
June 27th 2017, 22:04:39.001 org.apache.zookeeper.server.quorum.Leader
Proposing:: sessionid:0x25cd1e82c110008 type:closeSession cxid:0x0
zxid:0x200000fc5 txntype:-11 reqpath:n/a
June 27th 2017, 22:04:39.001 org.apache.zookeeper.server.PrepRequestProcessor
Processed session termination for sessionid: 0x25cd1e82c110008
June 27th 2017, 22:04:39.001 org.apache.zookeeper.server.PrepRequestProcessor
Processed session termination for sessionid: 0x25cd1e82c110001
...
June 27th 2017, 22:04:42.064 org.apache.zookeeper.server.quorum.QuorumPeer
LOOKING
...
June 27th 2017, 22:04:45.824 org.apache.zookeeper.server.quorum.Learner
FOLLOWING - LEADER ELECTION TOOK - 3760
...
June 27th 2017, 22:05:20.324 org.apache.zookeeper.server.ZooKeeperServer
Client attempting to renew session 0x25cd1e82c110001 at /100.96.5.6:47618
June 27th 2017, 22:05:20.324 org.apache.zookeeper.server.quorum.Learner
Revalidating client: 0x25cd1e82c110001
June 27th 2017, 22:05:20.324 org.apache.zookeeper.server.ZooKeeperServer
Session establishment request from client /100.96.5.6:47618 client's lastZxid
is 0x2000003af
June 27th 2017, 22:05:20.325 org.apache.zookeeper.server.ZooKeeperServer
Established session 0x25cd1e82c110001 with negotiated timeout 12000 for client
/100.96.5.6:47618
{code}
In ZK server 1's commit log, I saw the following, which indicates that session
25cd1e82c110001 was closed.
{code:java}
6/27/17 22:04:39 session 0x25cd1e82c110001 cxid 0x0 zxid 0x200000fc4
closeSession null
{code}
I saw the same session close in ZK server 2's commit log.
{code:java}
6/27/17 22:04:39 session 0x25cd1e82c110001 cxid 0x0 zxid 0x200000fc4
closeSession null
{code}
However, I don't see the same session close in ZK server 0's commit log.
Also, in ZK server 2 and 0's log4j log, there was no logging for session
25cd1e82c110001 from 22:04:39.000 (when server 1 expired the session) to
22:05:20.325 (when server 1 renewed the session).
So, my questions are
(1) Does the presence of closeSession indicate that session 25cd1e82c110001 was
indeed expired on 6/27/17 22:04:39?
(2) Why the closeSession for 25cd1e82c110001 didn't show up in the commit log
of ZK server 0?
I am also attaching the log around that time in case you need them. 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.08-02, zk.0.08-02, zk.0.formatted, zk.1.08-02,
> zk.1.08-02, zk.1.formatted, zk.2.08-02, zk.2.08-02
>
>
> 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:0x200000fc4
> txntype:-11 reqpath:n/a
> June 27th 2017, 22:04:39.001 INFO
> org.apache.zookeeper.server.PrepRequestProcessor Processed 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:0x200000fc4
> 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 INFO org.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 WARN org.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 WARN org.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 INFO org.apache.zookeeper.ClientCnxn Opening
> socket connection to server 100.65.188.168/100.65.188.168:2181 0
> June 27th 2017, 22:05:20.324 INFO org.apache.zookeeper.ClientCnxn Socket
> connection established to 100.65.188.168/100.65.188.168:2181, initiating
> session 0
> June 27th 2017, 22:05:20.327 INFO org.apache.zookeeper.ClientCnxn Session
> establishment complete on server 100.65.188.168/100.65.188.168:2181,
> sessionid = 0x25cd1e82c110001, negotiated timeout = 12000 0
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
