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