ZK causing EndOfStreamException and CancelledKeyExceptions?

[hsanjuan]

While using ZK in the following way:

ZK.new(...) do |zk|
zk.with_lock(...) do

end
end

my logs get filled with:

2013-05-06 15:41:21,341 - INFO [CommitProcessor:1:ZooKeeperServer@595] - Established session 0x13e6ea9db2c0034 with negotiated timeout 20001 for client /10.218.xxx.xxx:33402 2013-05-06 15:42:25,734 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@349] - caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13e6ea9db2c0034, likely client has closed socket at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220) at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208) at java.lang.Thread.run(Thread.java:722) 2013-05-06 15:42:25,735 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed socket connection for client /10.218.xxx.xxx:33402 which had sessionid 0x13e6ea9db2c0034 2013-05-06 15:42:26,145 - ERROR [CommitProcessor:1:NIOServerCnxn@180] - Unexpected Exception: java.nio.channels.CancelledKeyException at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73) at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77) at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153) at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1076) at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:404) at org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:74)

Code works as expected, but I wonder if this is a ZK problem (dropping the connection before reading all that is to be read) or maybe the way i am using it is not correct?

[slyphon]

I'm not sure why this happens (it's always happened as far as I've been
maintaining the project), but it seems to be harmless. It occurs when a
connection is closed on the client side. I spent some time a while back
trying to track it down, but I had to spend too much time digging in the
server code and it didn't seem to have any negative effects.

On Mon, May 6, 2013 at 8:47 AM, Hector Sanjuan [email protected]:

While using ZK in the following way:

ZK.new(...) do |zk|
zk.with_lock(...) do

end
end

my logs get filled with:

2013-05-06 15:41:21,341 - INFO [CommitProcessor:1:ZooKeeperServer@595] -
Established session 0x13e6ea9db2c0034 with negotiated timeout 20001 for
client /10.218.xxx.xxx:33402
2013-05-06 15:42:25,734 - WARN [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxn@349] - caught end of stream exception
EndOfStreamException: Unable to read additional data from client sessionid
0x13e6ea9db2c0034, likely client has closed socket
at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
at
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
at java.lang.Thread.run(Thread.java:722)
2013-05-06 15:42:25,735 - INFO [NIOServerCxn.Factory:
0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed socket connection for
client /10.218.xxx.xxx:33402 which had sessionid 0x13e6ea9db2c0034
2013-05-06 15:42:26,145 - ERROR [CommitProcessor:1:NIOServerCnxn@180] -
Unexpected Exception:
java.nio.channels.CancelledKeyException
at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
at
org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
at
org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1076)
at
org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:404)
at
org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:74)

Code works as expected, but I wonder if this is a ZK problem (dropping the
connection before reading all that is to be read) or maybe the way i am
using it is not correct?

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/67
.

[hsanjuan]

hmm... I have not gone deep in the zookeeper gem client code, but is there a chance the socket is closed before all that needs to be read from it has been read? Googling for these exceptions suggest such causes...

[csfrancis]

FYI, I have an open PR to fix this: zk-ruby/zookeeper#54.