[NETCONF-495] Deadlock between AsyncSshHandler and AsyncSshHandlerReader Created: 02/Jan/18  Updated: 22/Jul/20  Resolved: 22/Jul/20

Status: Resolved
Project: netconf
Component/s: netconf
Affects Version/s: None
Fix Version/s: Sodium

Type: Bug Priority: High
Reporter: fenggang xiao Assignee: Oleksii Mozghovyi
Resolution: Done Votes: 0
Labels: pt
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu 16.04

openjdk version "1.8.0_151"

 



 Description   

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)



 Comments   
Comment by Robert Varga [ 11/Aug/18 ]

JMorvay can you triage this?

Comment by Oleksii Mozghovyi [ 14/Jul/20 ]

Hi, springasa,

Looks like this issue was fixed with the following patch: https://git.opendaylight.org/gerrit/c/netconf/+/81714 , but this Jira issue wasn't updated.

Comment by Oleksii Mozghovyi [ 22/Jul/20 ]

The issue was fixed with the following commits:

https://git.opendaylight.org/gerrit/c/netconf/+/81714

https://git.opendaylight.org/gerrit/c/netconf/+/81924

https://git.opendaylight.org/gerrit/c/netconf/+/81925

 

Generated at Wed Feb 07 20:15:10 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.