Renewed session times out getting data

[Jared Cantwell <ja...@gmail.com>]

We are seeing a problem quite frequently that I'm hoping someone might be
able to give me insight into.  I can't find an existing JIRA with these
symptoms.

We have a c zookeeper client instance whose sole purpose is to monitor a
connection to a specific database server.  This gives us some connectivity
information about each server individually.  We are seeing a problem where
occasionally we get into an endless loop where the client establishes a
renewed session with the server and gets a session connected event, but
then when it immediately tries to get a path it gets a timeout error after
our configured 10-15 second timeout.

Since we have tons of sessions that round robin between the ensemble
servers on reconnect and we only see this on the client that only has one
server in its server list, I strongly suspect it has something to do with
that, but I'm not sure how to proceed in confirming that theory.

The server logs repeat this over and over:

Jan 17 14:14:33.385322 zookeeper - WARN
 [NIOWorkerThread-19:NIOServerCnxn@361] - Unable to read additional data
from client sessionid 0x20000112e160031, likely client has closed socket
Jan 17 14:14:33.385603 zookeeper - INFO
 [NIOWorkerThread-19:NIOServerCnxn@999] - Closed socket connection for
client /10.170.243.7:58326 which had sessionid 0x20000112e160031
Jan 17 14:14:33.719075 zookeeper - INFO
 [NIOServerCxnFactory.AcceptThread:/10.170.243.5:2181
:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /
10.170.243.7:50123
Jan 17 14:14:33.719677 zookeeper - WARN
 [NIOWorkerThread-17:ZooKeeperServer@822] - Connection request from old
client /10.170.243.7:50123; will be dropped if server is in r-o mode
Jan 17 14:14:33.719818 zookeeper - INFO
 [NIOWorkerThread-17:ZooKeeperServer@869] - Client attempting to renew
session 0x20000112e160031 at /10.170.243.7:50123; client last zxid is
0x1000e5e53; server last zxid is 0x10030675c
Jan 17 14:14:33.719960 zookeeper - INFO  [NIOWorkerThread-17:Learner@115] -
Revalidating client: 0x20000112e160031
Jan 17 14:14:33.720708 zookeeper - INFO
 [QuorumPeer[myid=2]/10.170.243.5:2181:ZooKeeperServer@611] - Established
session 0x20000112e160031 with negotiated timeout 20000 for client /
10.170.243.7:50123

... client gets session connected event ...

... client times out the get data operation ...

*Jan 17 14:14:47*.054559 zookeeper - WARN
 [NIOWorkerThread-9:NIOServerCnxn@361] - Unable to read additional data
from client sessionid 0x20000112e160031, likely client has closed socket
Jan 17 14:14:47.054877 zookeeper - INFO
 [NIOWorkerThread-9:NIOServerCnxn@999] - Closed socket connection for
client /10.170.243.7:50123 which had sessionid 0x20000112e160031
Jan 17 14:14:47.388139 zookeeper - INFO
 [NIOServerCxnFactory.AcceptThread:/10.170.243.5:2181
:NIOServerCnxnFactory$AcceptThread@296] - Accepted socket connection from /
10.170.243.7:54094
Jan 17 14:14:47.388586 zookeeper - WARN
 [NIOWorkerThread-24:ZooKeeperServer@822] - Connection request from old
client /10.170.243.7:54094; will be dropped if server is in r-o mode
Jan 17 14:14:47.388747 zookeeper - INFO
 [NIOWorkerThread-24:ZooKeeperServer@869] - Client attempting to renew
session 0x20000112e160031 at /10.170.243.7:54094; client last zxid is
0x1000e5e53; server last zxid is 0x100306773
Jan 17 14:14:47.388924 zookeeper - INFO  [NIOWorkerThread-24:Learner@115] -
Revalidating client: 0x20000112e160031
Jan 17 14:14:47.389689 zookeeper - INFO
 [QuorumPeer[myid=2]/10.170.243.5:2181:ZooKeeperServer@611] - Established
session 0x20000112e160031 with negotiated timeout 20000 for client /
10.170.243.7:54094


Any help or suggestions would be much appreciated.  Thanks.

~Jared