zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stephen Green <eelstretch...@gmail.com>
Subject Ping and client session timeouts
Date Fri, 21 May 2010 16:31:12 GMT
I feel like I'm missing something fairly fundamental here.  I'm
building a clustered application that uses ZooKeeper (3.3.1) to store
its configuration information.  There are 33 nodes in the cluster
(Amazon EC2 instance, if that matters), and I'm currently using a
single ZooKeeper instance. When a node starts up, it makes a
connection to ZK, sets the data on a few paths and makes an ephemeral
node for itself. I keep the connection open while the node is running
so that I can use watches to find out if a node disappears, but after
the initial setup, the node usually won't write or read anything from
ZK.

My understanding (having had a quick look at the code) is that the
client connection will send a ping every sessionTimeout * 2/3 ms or so
to keep the session alive, but I keep seeing sessions dying.  On the
client side I'll see something like the following sequence of events:

[05/21/10 15:59:40.753] INFO Initiating client connection,
connectString=zookeeper:2200 sessionTimeout=30000
watcher=com.echonest.cluster.ZooContainer@1eb3319f
[05/21/10 15:59:40.767] INFO Socket connection established to
zookeeper/10.255.9.187:2200, initiating session
[05/21/10 15:59:40.787] INFO Session establishment complete on server
zookeeper/10.255.9.187:2200, sessionid = 0x128bb7b828d004c, negotiated
timeout = 30000
[05/21/10 16:13:03.729] INFO Client session timed out, have not heard
from server in 33766ms for sessionid 0x128bb7b828d004c, closing socket
connection and attempting reconnect
[05/21/10 16:13:19.268] INFO Initiating client connection,
connectString=zookeeper:2200 sessionTimeout=30000
watcher=com.echonest.cluster.ZooContainer@1eb3319f
[05/21/10 16:14:12.326] INFO Client session timed out, have not heard
from server in 53058ms for sessionid 0x128bb7b828d004c, closing socket
connection and attempting reconnect
[05/21/10 16:14:29.810] INFO Socket connection established to
zookeeper/10.255.9.187:2200, initiating session
[05/21/10 16:14:29.814] INFO Session establishment complete on server
zookeeper/10.255.9.187:2200, sessionid = 0x128bb7b828d004f, negotiated
timeout = 30000

While on the server side, I'll see something like:

2010-05-21 15:59:40,775 - INFO  [SyncThread:0:NIOServerCnxn@1579] -
Established session 0x128bb7b828d004c with negotiated timeout 30000
for client /10.198.98.3:50376
2010-05-21 15:59:40,799 - INFO
[ProcessThread:-1:PrepRequestProcessor@405] - Got user-level
KeeperException when processing sessionid:0x128bb7b828d004c
type:create cxid:0x1 zxid:0xfffffffffffffffe txntype:unknown
reqpath:n/a Error Path:/clusters Error:KeeperErrorCode = NodeExists
for /clusters
2010-05-21 15:59:40,825 - INFO
[ProcessThread:-1:PrepRequestProcessor@405] - Got user-level
KeeperException when processing sessionid:0x128bb7b828d004c
type:delete cxid:0xc zxid:0xfffffffffffffffe txntype:unknown
reqpath:n/a Error
Path:/clusters/echostore/groups/01222100-81db-439e-a3df-90e061166e44/master
Error:KeeperErrorCode = NoNode for
/clusters/echostore/groups/01222100-81db-439e-a3df-90e061166e44/master
2010-05-21 16:13:03,732 - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2200:NIOServerCnxn@633] -
EndOfStreamException: Unable to read additional data from client
sessionid 0x128bb7b828d004c, likely client has closed socket
2010-05-21 16:13:03,733 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2200:NIOServerCnxn@1434] -
Closed socket connection for client /10.198.98.3:50376 which had
sessionid 0x128bb7b828d004c
2010-05-21 16:13:20,012 - INFO  [SessionTracker:ZooKeeperServer@315] -
Expiring session 0x128bb7b828d004c, timeout of 30000ms exceeded
2010-05-21 16:13:20,013 - INFO
[ProcessThread:-1:PrepRequestProcessor@385] - Processed session
termination for sessionid: 0x128bb7b828d004c

If I'm reading this correctly, the connection gets set up and then the
server experiences an error trying to read from the client, so it
closes the connection.  It's not clear if this causes the session
timeout or vice-versa (these systems are both running ntp, but I doubt
that we can count on interleaving those log times correctly.)

I started out with a session timeout of 10,000ms, but as you can see,
I have the same problem at 30,000ms.

Do I have a fundamental misunderstanding? What else should I do to
figure out what's going on here?

Steve

Mime
View raw message