[ 
https://issues.apache.org/jira/browse/ZOOKEEPER-2867?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16122353#comment-16122353
 ] 

Jun Rao commented on ZOOKEEPER-2867:
------------------------------------

[~hanm], that broker stopped logging around Aug 2, 23:16:11, which matches the 
time when the ping from that session stopped showing in ZK log. If the pinging 
stops, ZK server should expire that session after the session timeout, right?

I also grepped for all references to /cp15/brokers/ids/0 in the log. After 
"Deleting ephemeral node", the node was recreated later, but for a different 
session (which is when that broker was restarted). So, there is no indication 
that session 0x25cd1e82c110001 was restored.

{code:java}
ZK server 2:
August 2nd 2017, 23:41:29.019   DEBUG   org.apache.zookeeper.server.DataTree    
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x5cc2b607d10002
August 2nd 2017, 23:41:29.149   DEBUG   org.apache.zookeeper.server.DataTree    
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
August 2nd 2017, 23:42:12.105   DEBUG   
org.apache.zookeeper.server.FinalRequestProcessor       Processing request:: 
sessionid:0x25ceb96455e0000 type:getData cxid:0x4c4 zxid:0xfffffffffffffffe 
txntype:unknown reqpath:/cp15/brokers/ids/0
August 2nd 2017, 23:42:12.105   DEBUG   
org.apache.zookeeper.server.quorum.CommitProcessor      Processing request:: 
sessionid:0x25ceb96455e0000 type:getData cxid:0x4c4 zxid:0xfffffffffffffffe 
txntype:unknown reqpath:/cp15/brokers/ids/0
August 2nd 2017, 23:42:12.105   DEBUG   
org.apache.zookeeper.server.FinalRequestProcessor       
sessionid:0x25ceb96455e0000 type:getData cxid:0x4c4 zxid:0xfffffffffffffffe 
txntype:unknown reqpath:/cp15/brokers/ids/0
August 2nd 2017, 23:42:21.982   DEBUG   
org.apache.zookeeper.server.FinalRequestProcessor       
sessionid:0x25ceb96455e0000 type:getData cxid:0x4c8 zxid:0xfffffffffffffffe 
txntype:unknown reqpath:/cp15/brokers/ids/0
August 2nd 2017, 23:42:21.982   DEBUG   
org.apache.zookeeper.server.FinalRequestProcessor       Processing request:: 
sessionid:0x25ceb96455e0000 type:getData cxid:0x4c8 zxid:0xfffffffffffffffe 
txntype:unknown reqpath:/cp15/brokers/ids/0
August 2nd 2017, 23:42:21.982   DEBUG   
org.apache.zookeeper.server.quorum.CommitProcessor      Processing request:: 
sessionid:0x25ceb96455e0000 type:getData cxid:0x4c8 zxid:0xfffffffffffffffe 
txntype:unknown reqpath:/cp15/brokers/ids/0

ZK server 1:
August 2nd 2017, 23:41:54.966   DEBUG   org.apache.zookeeper.server.DataTree    
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x5cc2b607d10002
August 2nd 2017, 23:41:55.076   DEBUG   org.apache.zookeeper.server.DataTree    
Deleting ephemeral node /cp15/brokers/ids/0 for session 0x25cd1e82c110001
August 2nd 2017, 23:42:12.045   DEBUG   
org.apache.zookeeper.server.quorum.CommitProcessor      Processing request:: 
sessionid:0x15da553c7ec0000 type:create cxid:0x26 zxid:0xfffffffffffffffe 
txntype:unknown reqpath:/cp15/brokers/ids/0
August 2nd 2017, 23:42:12.095   DEBUG   
org.apache.zookeeper.server.FinalRequestProcessor       Processing request:: 
sessionid:0x15da553c7ec0000 type:create cxid:0x26 zxid:0x40000004d txntype:1 
reqpath:/cp15/brokers/ids/0
August 2nd 2017, 23:42:12.095   DEBUG   
org.apache.zookeeper.server.FinalRequestProcessor

ZK server 0:
August 2nd 2017, 23:42:12.107   DEBUG   org.apache.zookeeper.server.DataTree    
Failed: 98416546127020032,38,17179869261,1501717332053,1
:'/cp15/brokers/ids/0,#7b226c697374656e65725f73656375726974795f70726f746f636f6c5f6d6170223a7b22494e5445524e414c223a22504c41494e54455854222c225245504c49434154494f4e223a22504c41494e54455854222c2245585445524e414c223a225341534c5f504c41494e54455854227d2c22656e64706f696e7473223a5b22494e5445524e414c3a2f2f62726f6b65722d696e7465726e616c2d302e637031352e7376632e636c75737465722e6c6f63616c3a39303731222c225245504c49434154494f4e3a2f2f62726f6b65722d696e7465726e616c2d302e637031352e7376632e636c75737465722e6c6f63616c3a39303732222c2245585445524e414c3a2f2f72302e6b61666b612e676f73706f74636865636b2e6177732e636f6e666c75656e742e636c6f75643a39303932225d2c227261636b223a227230222c226a6d785f706f7274223a373230332c22686f7374223a2262726f6b65722d696e7465726e616c2d302e637031352e7376632e636c75737465722e6c6f63616c222c2274696d657374616d70223a2231353031373137333332303337222c22706f7274223a393037312c2276657273696f6e223a347d,v{s{31,s{'world,'anyone}}},T,9
August 2nd 2017, 23:42:12.108   DEBUG   org.apache.zookeeper.server.DataTree    
Adjusting parent cversion for Txn: 1 path:/cp15/brokers/ids/0 err: -110
{code}

So, what do you think happened there? Did the session 0x25cd1e82c110001 ever 
get closed? Could this be a ZK bug?

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

Reply via email to