We met a deadlock recently between AsyncSshHandler and AsyncSshHandlerReader:
Deadlock happend as the following path:
ReadException happend
operationComplete
|
Something failed happend -> close -> SH -> disconnect -> SHR -> close
| |
| <------------ invokeDisconnect
(SH stands for lock instance of AsyncSshHandler and SHR stands for lock instance of AsyncSshHandlerReader)
Found one Java-level deadlock:
=============================
"sshd-SshClient[4b240240]-nio2-thread-6":
waiting to lock monitor 0x00007f68c405bc48 (object 0x0000000096086638, a org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler),
which is held by "nioEventLoopGroupCloseable-3-1"
"nioEventLoopGroupCloseable-3-1":
waiting to lock monitor 0x00007f68e9387308 (object 0x0000000096217a90, a org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerReader),
which is held by "sshd-SshClient[4b240240]-nio2-thread-6"
Java stack information for the threads listed above:
===================================================
"sshd-SshClient[4b240240]-nio2-thread-6":
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler.disconnect(AsyncSshHandler.java:256)
- waiting to lock <0x0000000096086638> (a org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler)
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler$5.close(AsyncSshHandler.java:197)
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerReader.invokeDisconnect(AsyncSshHandlerReader.java:82)
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerReader.operationComplete(AsyncSshHandlerReader.java:62)
- locked <0x0000000096217a90> (a org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerReader)
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerReader.operationComplete(AsyncSshHandlerReader.java:24)
at org.apache.sshd.common.future.DefaultSshFuture.notifyListener(DefaultSshFuture.java:269)
at org.apache.sshd.common.future.DefaultSshFuture.notifyListeners(DefaultSshFuture.java:254)
at org.apache.sshd.common.future.DefaultSshFuture.setValue(DefaultSshFuture.java:173)
at org.apache.sshd.common.channel.ChannelAsyncInputStream.preClose(ChannelAsyncInputStream.java:73)
- locked <0x0000000096217930> (a org.apache.sshd.common.util.Buffer)
at org.apache.sshd.common.util.CloseableUtils$AbstractCloseable.close(CloseableUtils.java:284)
at org.apache.sshd.common.util.CloseableUtils$ParallelCloseable.doClose(CloseableUtils.java:182)
at org.apache.sshd.common.util.CloseableUtils$SimpleCloseable.close(CloseableUtils.java:151)
at org.apache.sshd.common.util.CloseableUtils$SequentialCloseable$1.operationComplete(CloseableUtils.java:205)
at org.apache.sshd.common.util.CloseableUtils$SequentialCloseable$1.operationComplete(CloseableUtils.java:200)
at org.apache.sshd.common.future.DefaultSshFuture.notifyListener(DefaultSshFuture.java:269)
at org.apache.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:214)
at org.apache.sshd.common.util.CloseableUtils$SequentialCloseable$1.operationComplete(CloseableUtils.java:206)
at org.apache.sshd.common.util.CloseableUtils$SequentialCloseable$1.operationComplete(CloseableUtils.java:200)
at org.apache.sshd.common.future.DefaultSshFuture.notifyListener(DefaultSshFuture.java:269)
at org.apache.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:214)
at org.apache.sshd.common.util.CloseableUtils$SequentialCloseable$1.operationComplete(CloseableUtils.java:206)
at org.apache.sshd.common.util.CloseableUtils$SequentialCloseable$1.operationComplete(CloseableUtils.java:200)
at org.apache.sshd.common.util.CloseableUtils$SequentialCloseable.doClose(CloseableUtils.java:215)
at org.apache.sshd.common.util.CloseableUtils$SimpleCloseable.close(CloseableUtils.java:151)
at org.apache.sshd.common.util.CloseableUtils$AbstractInnerCloseable.doCloseGracefully(CloseableUtils.java:351)
at org.apache.sshd.common.util.CloseableUtils$AbstractCloseable.close(CloseableUtils.java:285)
at org.apache.sshd.common.channel.AbstractChannel.handleClose(AbstractChannel.java:148)
at org.apache.sshd.common.session.AbstractConnectionService.channelClose(AbstractConnectionService.java:263)
at org.apache.sshd.common.session.AbstractConnectionService.process(AbstractConnectionService.java:171)
at org.apache.sshd.common.session.AbstractSession.doHandleMessage(AbstractSession.java:431)
at org.apache.sshd.common.session.AbstractSession.handleMessage(AbstractSession.java:326)
- locked <0x00000000960868b8> (a java.lang.Object)
at org.apache.sshd.client.session.ClientSessionImpl.handleMessage(ClientSessionImpl.java:306)
- locked <0x00000000960868b8> (a java.lang.Object)
at org.apache.sshd.common.session.AbstractSession.decode(AbstractSession.java:780)
at org.apache.sshd.common.session.AbstractSession.messageReceived(AbstractSession.java:308)
- locked <0x000000009608a3b8> (a java.lang.Object)
at org.apache.sshd.common.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:54)
at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:184)
at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:170)
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:32)
at java.security.AccessController.doPrivileged(Native Method)
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:30)
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
at sun.nio.ch.Invoker$2.run(Invoker.java:218)
at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"nioEventLoopGroupCloseable-3-1":
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerReader.close(AsyncSshHandlerReader.java:92)
- waiting to lock <0x0000000096217a90> (a org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerReader)
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler.disconnect(AsyncSshHandler.java:268)
- locked <0x0000000096086638> (a org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler)
at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler.close(AsyncSshHandler.java:251)
at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:604)
at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:588)
at io.netty.channel.ChannelOutboundHandlerAdapter.close(ChannelOutboundHandlerAdapter.java:71)
at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:604)
at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:588)
at io.netty.channel.ChannelOutboundHandlerAdapter.close(ChannelOutboundHandlerAdapter.java:71)
at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:604)
at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:588)
at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:445)
at io.netty.channel.DefaultChannelPipeline.close(DefaultChannelPipeline.java:928)
at io.netty.channel.AbstractChannel.close(AbstractChannel.java:187)
at org.opendaylight.protocol.framework.AbstractSessionNegotiator.negotiationFailed(AbstractSessionNegotiator.java:53)
at org.opendaylight.protocol.framework.AbstractSessionNegotiator$1.operationComplete(AbstractSessionNegotiator.java:70)
at org.opendaylight.protocol.framework.AbstractSessionNegotiator$1.operationComplete(AbstractSessionNegotiator.java:65)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:518)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:492)
at io.netty.util.concurrent.DefaultPromise.notifyListenersWithStackOverFlowProtection(DefaultPromise.java:431)
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
at io.netty.util.concurrent.DefaultPromise.addListener(DefaultPromise.java:167)
at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:93)
at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:28)
at org.opendaylight.protocol.framework.AbstractSessionNegotiator.sendMessage(AbstractSessionNegotiator.java:64)
at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.start(AbstractNetconfSessionNegotiator.java:112)
at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.startNegotiation(AbstractNetconfSessionNegotiator.java:93)
at org.opendaylight.protocol.framework.AbstractSessionNegotiator.channelActive(AbstractSessionNegotiator.java:82)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:201)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:187)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:180)
at io.netty.channel.ChannelInboundHandlerAdapter.channelActive(ChannelInboundHandlerAdapter.java:64)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:201)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:187)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:180)
at io.netty.channel.ChannelInboundHandlerAdapter.channelActive(ChannelInboundHandlerAdapter.java:64)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:201)
at io.netty.channel.AbstractChannelHandlerContext.access$200(AbstractChannelHandlerContext.java:33)
at io.netty.channel.AbstractChannelHandlerContext$3.run(AbstractChannelHandlerContext.java:192)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:394)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)
at java.lang.Thread.run(Thread.java:745)