You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Karol Gwaj <Ka...@skillpages.com> on 2011/11/30 15:49:27 UTC
java.nio.channels.CancelledKeyException in ZK 3.4
Hi,
Im getting error on the server every time I close session with zk (version 3.4)
Server debug logs for my connection:
2011-11-30 12:43:01,421 [myid:] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxnFactory@213][] - Accepted socket connection from /127.0.0.1:42298
2011-11-30 12:43:01,427 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:ZooKeeperServer@772][] - Session establishment request from client /127.0.0.1:42298 client's lastZxid is 0x0
2011-11-30 12:43:01,427 [myid:] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:ZooKeeperServer@784][] - Connection request from old client /127.0.0.1:42298; will be dropped if server is in r-o mode
2011-11-30 12:43:01,428 [myid:] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:ZooKeeperServer@830][] - Client attempting to establish new session at /127.0.0.1:42298
2011-11-30 12:43:01,430 [myid:] - INFO [SyncThread:0:FileTxnLog@200][] - Creating new log file: log.18761
2011-11-30 12:43:01,437 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@87][] - Processing request:: sessionid:0x133f47fd0d00000 type:createSession cxid:0x0 zxid:0x18761 txntype:-10 reqpath:n/a
2011-11-30 12:43:01,439 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@169][] - sessionid:0x133f47fd0d00000 type:createSession cxid:0x0 zxid:0x18761 txntype:-10 reqpath:n/a
2011-11-30 12:43:01,443 [myid:] - INFO [SyncThread:0:ZooKeeperServer@596][] - Established session 0x133f47fd0d00000 with negotiated timeout 30000 for client /127.0.0.1:42298
2011-11-30 12:43:04,564 [myid:] - INFO [ProcessThread(sid:0 cport:-1)::PrepRequestProcessor@466][] - Processed session termination for sessionid: 0x133f47fd0d00000
2011-11-30 12:43:04,565 [myid:] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxn@349][] - caught end of stream exception
EndOfStreamException: Unable to read additional data from client sessionid 0x133f47fd0d00000, likely client has closed socket
at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:224)
at java.lang.Thread.run(Thread.java:662)
2011-11-30 12:43:04,566 [myid:] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxn@1000][] - Closed socket connection for client /127.0.0.1:42298 which had sessionid 0x133f47fd0d00000
2011-11-30 12:43:04,567 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxn@1024][] - ignoring exception during input shutdown
java.net.SocketException: Transport endpoint is not connected
at sun.nio.ch.SocketChannelImpl.shutdown(Native Method)
at sun.nio.ch.SocketChannelImpl.shutdownInput(SocketChannelImpl.java:633)
at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:360)
at org.apache.zookeeper.server.NIOServerCnxn.closeSock(NIOServerCnxn.java:1020)
at org.apache.zookeeper.server.NIOServerCnxn.close(NIOServerCnxn.java:977)
at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:352)
at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:224)
at java.lang.Thread.run(Thread.java:662)
2011-11-30 12:43:04,568 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@87][] - Processing request:: sessionid:0x133f47fd0d00000 type:closeSession cxid:0x4ed624d6 zxid:0x18762 txntype:-11 reqpath:n/a
2011-11-30 12:43:04,569 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@169][] - sessionid:0x133f47fd0d00000 type:closeSession cxid:0x4ed624d6 zxid:0x18762 txntype:-11 reqpath:n/a
2011-11-30 12:43:04,570 [myid:] - ERROR [SyncThread:0:NIOServerCnxn@180][] - Unexpected Exception:
java.nio.channels.CancelledKeyException
at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1075)
at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:412)
at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:165)
at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:101)
Steps to reproduce:
1. Start c client: cli_mt localhost:2111
2. Execute quit from client console
Any idea if it is expected behaviour ?
Any help will be greatly appreciated
Thx,
Re: java.nio.channels.CancelledKeyException in ZK 3.4
Posted by Patrick Hunt <ph...@apache.org>.
I believe it's this: https://issues.apache.org/jira/browse/ZOOKEEPER-1237
Timing issue btw multiple threads (client closing and the server
writing). The problem is that the socket has been closed prior to the
server getting out the "close session response" to the client.
Patrick
On Wed, Nov 30, 2011 at 6:49 AM, Karol Gwaj <Ka...@skillpages.com> wrote:
> Hi,
>
> Im getting error on the server every time I close session with zk (version 3.4)
>
> Server debug logs for my connection:
> 2011-11-30 12:43:01,421 [myid:] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxnFactory@213][] - Accepted socket connection from /127.0.0.1:42298
> 2011-11-30 12:43:01,427 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:ZooKeeperServer@772][] - Session establishment request from client /127.0.0.1:42298 client's lastZxid is 0x0
> 2011-11-30 12:43:01,427 [myid:] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:ZooKeeperServer@784][] - Connection request from old client /127.0.0.1:42298; will be dropped if server is in r-o mode
> 2011-11-30 12:43:01,428 [myid:] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:ZooKeeperServer@830][] - Client attempting to establish new session at /127.0.0.1:42298
> 2011-11-30 12:43:01,430 [myid:] - INFO [SyncThread:0:FileTxnLog@200][] - Creating new log file: log.18761
> 2011-11-30 12:43:01,437 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@87][] - Processing request:: sessionid:0x133f47fd0d00000 type:createSession cxid:0x0 zxid:0x18761 txntype:-10 reqpath:n/a
> 2011-11-30 12:43:01,439 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@169][] - sessionid:0x133f47fd0d00000 type:createSession cxid:0x0 zxid:0x18761 txntype:-10 reqpath:n/a
> 2011-11-30 12:43:01,443 [myid:] - INFO [SyncThread:0:ZooKeeperServer@596][] - Established session 0x133f47fd0d00000 with negotiated timeout 30000 for client /127.0.0.1:42298
> 2011-11-30 12:43:04,564 [myid:] - INFO [ProcessThread(sid:0 cport:-1)::PrepRequestProcessor@466][] - Processed session termination for sessionid: 0x133f47fd0d00000
> 2011-11-30 12:43:04,565 [myid:] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxn@349][] - caught end of stream exception
> EndOfStreamException: Unable to read additional data from client sessionid 0x133f47fd0d00000, likely client has closed socket
> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:224)
> at java.lang.Thread.run(Thread.java:662)
> 2011-11-30 12:43:04,566 [myid:] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxn@1000][] - Closed socket connection for client /127.0.0.1:42298 which had sessionid 0x133f47fd0d00000
> 2011-11-30 12:43:04,567 [myid:] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2111:NIOServerCnxn@1024][] - ignoring exception during input shutdown
> java.net.SocketException: Transport endpoint is not connected
> at sun.nio.ch.SocketChannelImpl.shutdown(Native Method)
> at sun.nio.ch.SocketChannelImpl.shutdownInput(SocketChannelImpl.java:633)
> at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:360)
> at org.apache.zookeeper.server.NIOServerCnxn.closeSock(NIOServerCnxn.java:1020)
> at org.apache.zookeeper.server.NIOServerCnxn.close(NIOServerCnxn.java:977)
> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:352)
> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:224)
> at java.lang.Thread.run(Thread.java:662)
> 2011-11-30 12:43:04,568 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@87][] - Processing request:: sessionid:0x133f47fd0d00000 type:closeSession cxid:0x4ed624d6 zxid:0x18762 txntype:-11 reqpath:n/a
> 2011-11-30 12:43:04,569 [myid:] - DEBUG [SyncThread:0:FinalRequestProcessor@169][] - sessionid:0x133f47fd0d00000 type:closeSession cxid:0x4ed624d6 zxid:0x18762 txntype:-11 reqpath:n/a
> 2011-11-30 12:43:04,570 [myid:] - ERROR [SyncThread:0:NIOServerCnxn@180][] - Unexpected Exception:
> java.nio.channels.CancelledKeyException
> at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
> at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
> at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
> at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1075)
> at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:412)
> at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:165)
> at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:101)
>
>
> Steps to reproduce:
>
> 1. Start c client: cli_mt localhost:2111
>
> 2. Execute quit from client console
>
>
>
>
> Any idea if it is expected behaviour ?
>
> Any help will be greatly appreciated
>
> Thx,
>