[
https://issues.apache.org/jira/browse/ZOOKEEPER-2867?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16115545#comment-16115545
]
Michael Han commented on ZOOKEEPER-2867:
----------------------------------------
Is this the full server log? Does anything happen between 22:04:39 and
22:05:20? Session expiration requires consensus over the quorum so to perform a
session expiration operation, a proposal has to be sent out by leader to the
quorum and wait until leader receives ACKs from a quorum of servers. If during
this process leader election happens, then client might be able to renew the
session at the same (or a different server), which is what the client log shows
here.
For the available server log posted here, in particular:
* {{ org.apache.zookeeper.server.PrepRequestProcessor Processed session
termination for sessionid }} does not mean session is expired. It only implies
that the request passed one of the processor stage.
* Similarly, {{ org.apache.zookeeper.server.quorum.CommitProcessor
Processing request:: sessionid:0x25cd1e82c110001 type:closeSession }} does not
mean session close is performed. At this stage the commit processor only queued
the closing request which will be processed later once the leader receives
enough ACKs from a quorum. So if leader dies, then this will not be committed.
It should be easy to find hard evidence regarding whether or not the session
close transaction was finally committed by quorum or not. When DEBUG is
enabled, there should be lots of information related to what proposals got
committed in different servers. That is also the reason I was asking if the
server log is completed or not.
It will be a bug however if we find out that the close session was committed
across quorum yet client was still able to renew the session.
> 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
>
> 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)
