[ https://issues.apache.org/jira/browse/ZOOKEEPER-344?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12694060#action_12694060 ]
bryan thompson commented on ZOOKEEPER-344: ------------------------------------------ Here are some more stack traces with DEBUG on the server and the client for this issue. The configuration, etc. is the same. Logs were written onto an NFS share but the machines are synched with ntpd. There are two distinct periods reported here. One leads to a warning on the server but not to an expired session while the other issues the same warning on the server and leads to an expired session. Here is a "ping" for sessionid 0x120597b6137000b shortly before the warning. DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:74) 2009-03-30 17:34:33,643 - Processing request:: sessionid:0x120597b6137000b type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:137) 2009-03-30 17:34:33,643 - sessionid:0x120597b6137000b type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a DEBUG [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.readResponse(ClientCnxn.java:548) 2009-03-30 17:34:33,643 - Got ping response for sessionid:0x120597b6137000b after 1ms Here is the "Exception causing close of session". WARN [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:898) 2009-03-30 17:34:48,120 - Exception closing session 0x120597b6137000b to sun.nio.ch.selectionkeyi...@7eb1cc87 java.io.IOException: TIMED OUT at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:837) WARN [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:417) 2009-03-30 17:34:48,166 - Exception causing close of session 0x120597b6137000b due to java.io.IOException: Read error DEBUG [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:420) 2009-03-30 17:34:48,166 - IOException stack trace java.io.IOException: Read error at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:295) at org.apache.zookeeper.server.NIOServerCnxn$Factory.run(NIOServerCnxn.java:162) INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.close(NIOServerCnxn.java:752) 2009-03-30 17:34:48,172 - closing session:0x120597b6137000b NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/192.168.6.21:2181 remote=/192.168.6.28:60720] And here is appears that the closed session was re-initialized? Perhaps closed != expired? INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.finishSessionInit(NIOServerCnxn.java:881) 2009-03-30 17:34:50,111 - Finished init of 0x120597b6137000b valid:true INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.readConnectRequest(NIOServerCnxn.java:531) 2009-03-30 17:34:50,111 - Renewing session 0x120597b6137000b DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:74) 2009-03-30 17:34:50,112 - Processing request:: sessionid:0x120597b6137000b type:setWatches cxid:0xfffffffffffffff8 zxid:0xfffffffffffffffe txntype:unknown DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:137) 2009-03-30 17:34:50,112 - sessionid:0x120597b6137000b type:setWatches cxid:0xfffffffffffffff8 zxid:0xfffffffffffffffe txntype:unknown DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:74) 2009-03-30 17:34:50,121 - Processing request:: sessionid:0x120597b6137000b type:create cxid:0x8 zxid:0xb95 txntype:-1 n/a DEBUG [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.readResponse(ClientCnxn.java:610) 2009-03-30 17:34:50,126 - Reading reply sessionid:0x120597b6137000b, packet:: path:null finished:false header:: -8,101 replyHeader:: -8,2964,0 request:: 2964,v{},v{'/benchmark/config/com.bigdata.service.jini.DataServer/logicalService0000000011/masterElection_INVALID},v{} response:: null ------------------------------------------------------------ Another trace that leads to an expired session: DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:74) 2009-03-30 18:35:39,478 - Processing request:: sessionid:0x120597b61370008 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:137) 2009-03-30 18:35:39,478 - sessionid:0x120597b61370008 type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffffffe txntype:unknown n/a DEBUG [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.readResponse(ClientCnxn.java:548) 2009-03-30 18:35:39,478 - Got ping response for sessionid:0x120597b61370008 after 1ms WARN [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:898) 2009-03-30 18:35:58,082 - Exception closing session 0x120597b61370008 to sun.nio.ch.selectionkeyi...@6e731a5b java.io.IOException: TIMED OUT at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:837) WARN [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:417) 2009-03-30 18:35:58,084 - Exception causing close of session 0x120597b61370008 due to java.io.IOException: Read error DEBUG [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:420) 2009-03-30 18:35:58,084 - IOException stack trace java.io.IOException: Read error at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:295) at org.apache.zookeeper.server.NIOServerCnxn$Factory.run(NIOServerCnxn.java:162) INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.close(NIOServerCnxn.java:752) 2009-03-30 18:35:58,085 - closing session:0x120597b61370008 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/192.168.6.21:2181 remote=/192.168.6.34:58347] INFO [SessionTracker] org.apache.zookeeper.server.SessionTrackerImpl.run(SessionTrackerImpl.java:132) 2009-03-30 18:36:00,000 - Expiring session 0x120597b61370008 INFO [SessionTracker] org.apache.zookeeper.server.ZooKeeperServer.expire(ZooKeeperServer.java:317) 2009-03-30 18:36:00,001 - Expiring session 0x120597b61370008 INFO [ProcessThread:-1] org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcessor.java:360) 2009-03-30 18:36:00,003 - Processed session termination request for id: 0x120597b61370008 DEBUG [SyncThread:0] org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:74) 2009-03-30 18:36:00,013 - Processing request:: sessionid:0x120597b61370008 type:closeSession cxid:0x0 zxid:0xbaf txntype:-11 n/a DEBUG [SyncThread:0] org.apache.zookeeper.server.DataTree.killSession(DataTree.java:743) 2009-03-30 18:36:00,014 - Deleting ephemeral node /benchmark/config/com.bigdata.service.jini.DataServer/logicalService0000000005/masterElection/lock0000000000 for session 0x120597b61370008 INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.readConnectRequest(NIOServerCnxn.java:503) 2009-03-30 18:36:00,072 - Connected to /192.168.6.34:45222 lastZxid 2984 INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.finishSessionInit(NIOServerCnxn.java:881) 2009-03-30 18:36:00,073 - Finished init of 0x120597b61370008 valid:false INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.readConnectRequest(NIOServerCnxn.java:531) 2009-03-30 18:36:00,073 - Renewing session 0x120597b61370008 WARN [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:417) 2009-03-30 18:36:00,074 - Exception causing close of session 0x120597b61370008 due to java.io.IOException: closing DEBUG [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:420) 2009-03-30 18:36:00,074 - IOException stack trace java.io.IOException: closing at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:373) at org.apache.zookeeper.server.NIOServerCnxn$Factory.run(NIOServerCnxn.java:162) INFO [NIOServerCxn.Factory:2181] org.apache.zookeeper.server.NIOServerCnxn.close(NIOServerCnxn.java:752) 2009-03-30 18:36:00,074 - closing session:0x120597b61370008 NIOServerCnxn: java.nio.channels.SocketChannel[connected local=/192.168.6.21:2181 remote=/192.168.6.34:4522\ 2] INFO [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:800) 2009-03-30 18:36:00,069 - Attempting connection to server blade2/192.168.6.21:2181 INFO [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.primeConnection(ClientCnxn.java:716) 2009-03-30 18:36:00,070 - Priming connection to java.nio.channels.SocketChannel[connected local=/192.168.6.34:45222 remote=blade2/192.168.6.21:2181] INFO [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:868) 2009-03-30 18:36:00,070 - Server connection successful WARN [main-SendThread] org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:898) 2009-03-30 18:36:00,073 - Exception closing session 0x120597b61370008 to sun.nio.ch.selectionkeyi...@3d38013d java.io.IOException: Session Expired at org.apache.zookeeper.ClientCnxn$SendThread.readConnectResult(ClientCnxn.java:527) at org.apache.zookeeper.ClientCnxn$SendThread.doIO(ClientCnxn.java:640) at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:876) WARN [main-EventThread] com.bigdata.service.jini.AbstractServer$1.process(AbstractServer.java:759) 2009-03-30 18:36:00,074 - Zookeeper session expired: cancelled master election task: com.bigdata.service.jini.abstractserve...@79b5334c ERROR [main-EventThread] com.bigdata.zookeeper.ZLockImpl$ZLockWatcher.process(ZLockImpl.java:400) 2009-03-30 18:36:00,074 - Session expired: WatchedEvent: Server state change. New state: Expired : zxid=120597b61370008, zpath=/benchmark/config/com.bigdata.service.jini.DataServer/logicalService0000000005/masterElection WARN [com.bigdata.service.jini.JiniFederation.executorService1] com.bigdata.zookeeper.ZLockImpl.unlock(ZLockImpl.java:1188) 2009-03-30 18:36:00,077 - Session expired: zpath=/benchmark/config/com.bigdata.service.jini.DataServer/logicalService0000000005/masterElection, child=lock0000000000 : org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired > doIO in NioServerCnxn: Exception causing close of session : cause is "read > error" > --------------------------------------------------------------------------------- > > Key: ZOOKEEPER-344 > URL: https://issues.apache.org/jira/browse/ZOOKEEPER-344 > Project: Zookeeper > Issue Type: Bug > Components: java client, server > Affects Versions: 3.1.0 > Environment: jdk1.6.0_07 > Linux blade2 2.6.27.7-134.fc10.x86_64 #1 SMP Mon Dec 1 22:21:35 EST 2008 > x86_64 x86_64 x86_64 GNU/Linux > Reporter: bryan thompson > Fix For: 3.2.0 > > > I have been having a problem with zookeeper 3.0.1 and now with 3.1.0 where I > see a lot of expired sessions. I am using a 16 node cluster which is all on > the same local network. There is a single zookeeper instance (these are > benchmarking runs). > The problem appears to be correlated with either run time or system load.\ > Personally I think that it is system load because I have session session > expired events under a Windows platform running zookeeper and the application > (i.e., everthing is local) when the application load suddenly spikes. To me > this suggests that the client is not able to renew (ping) the zookeeper > service in a timely manner and is expired. But the log messages below with > the "read error" suggest that maybe there is something else going on? > Zookeeper Configuration > #Wed Mar 18 12:41:05 GMT-05:00 2009 > clientPort=2181 > dataDir=/var/bigdata/benchmark/zookeeper/1 > syncLimit=2 > dataLogDir=/var/bigdata/benchmark/zookeeper/1 > tickTime=2000 > Some representative log messages are below. > Client side messages (from our app) > ERROR [main-EventThread] > com.bigdata.zookeeper.ZLockImpl$ZLockWatcher.process(ZLockImpl.java:400) > 2009-03-18 13:35:40,335 - Session expired: WatchedEvent: Server state change. > New state: Expired : > zpath=/benchmark/jobs/com.bigdata.service.jini.benchmark.ThroughputMaster/test_1/client1160/locknode > ERROR [main-EventThread] > com.bigdata.zookeeper.ZLockImpl$ZLockWatcher.process(ZLockImpl.java:400) > 2009-03-18 13:35:40,335 - Session expired: WatchedEvent: Server state change. > New state: Expired : > zpath=/benchmark/jobs/com.bigdata.service.jini.benchmark.ThroughputMaster/test_1/client1356/locknode > Server side messages: > WARN [NIOServerCxn.Factory:2181] > org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:417) > 2009-03-18 13:06:57,252 - Exception causing close of session > 0x1201aac14300022 due to java.io.IOException: Read error > WARN [NIOServerCxn.Factory:2181] > org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:417) > 2009-03-18 13:06:58,198 - Exception causing close of session > 0x1201aac1430000f due to java.io.IOException: Read error -- This message is automatically generated by JIRA. - You can reply to this email to add a comment to the issue online.