zookeeper-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Michael Han (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (ZOOKEEPER-2867) an expired ZK session can be re-established
Date Sat, 05 Aug 2017 23:28:02 GMT

    [ 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)

Mime
View raw message