[ https://issues.apache.org/jira/browse/SSHD-966?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17054487#comment-17054487 ] 

Lyor Goldstein commented on SSHD-966:
-------------------------------------

I see the problem, but will have to think some more about a solution....

> Deadlock on disconnection at the end of key-exchange
> ----------------------------------------------------
>
>                 Key: SSHD-966
>                 URL: https://issues.apache.org/jira/browse/SSHD-966
>             Project: MINA SSHD
>          Issue Type: Bug
>    Affects Versions: 2.0.0
>            Reporter: Francois Ferrand
>            Assignee: Lyor Goldstein
>            Priority: Major
>
> We are using git-repo to download projects from Gerrit server, using SSH.
> Gerrit is in version 2.16.16. which uses SSHD 2.0.0 and Mina 2.0.17 with NIO2 backend.
> One particularity of this setup is that git-repo creates a single control master channel, and then downloads *lots* of Git repositories (500 repositories, some of them relatively large), with some degree of parallelism. This takes a long time, lots of data, and the multiplexed connections are handled by gerrit in multiple threads.
> In some cases, we experience a deadlock when an error happens at the end of the key exchange, while sending pending packets:
> {noformat}
> Warning, the following threads are deadlocked : SSH git-upload-pack /project1 (myuser), sshd-SshServer[df5f657]-nio2-thread-3
> "SSH git-upload-pack /project1 (myuser)" prio=1 BLOCKED
> 	org.apache.sshd.common.session.helpers.AbstractSession.writePacket(AbstractSession.java:1107)
> 	org.apache.sshd.common.channel.AbstractChannel.writePacket(AbstractChannel.java:798)
> 	org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:227)
> 	org.apache.sshd.common.channel.ChannelOutputStream.write(ChannelOutputStream.java:127)
> 	org.eclipse.jgit.transport.UploadPack$ResponseBufferedOutputStream.write(UploadPack.java:2183)
> 	org.eclipse.jgit.transport.SideBandOutputStream.writeBuffer(SideBandOutputStream.java:174)
> 	org.eclipse.jgit.transport.SideBandOutputStream.write(SideBandOutputStream.java:153)
> 	org.eclipse.jgit.internal.storage.pack.PackOutputStream.write(PackOutputStream.java:132)
> 	org.eclipse.jgit.internal.storage.file.PackFile.copyAsIs2(PackFile.java:614)
> 	org.eclipse.jgit.internal.storage.file.PackFile.copyAsIs(PackFile.java:433)
> 	org.eclipse.jgit.internal.storage.file.WindowCursor.copyObjectAsIs(WindowCursor.java:221)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObjectImpl(PackWriter.java:1644)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObject(PackWriter.java:1621)
> 	org.eclipse.jgit.internal.storage.pack.PackOutputStream.writeObject(PackOutputStream.java:171)
> 	org.eclipse.jgit.internal.storage.file.WindowCursor.writeObjects(WindowCursor.java:229)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObjects(PackWriter.java:1609)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObjects(PackWriter.java:1597)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writePack(PackWriter.java:1154)
> 	org.eclipse.jgit.transport.UploadPack.sendPack(UploadPack.java:2133)
> 	org.eclipse.jgit.transport.UploadPack.sendPack(UploadPack.java:1947)
> 	org.eclipse.jgit.transport.UploadPack.service(UploadPack.java:971)
> 	org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:776)
> 	com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:77)
> 	com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:98)
> 	com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:31)
> 	com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:63)
> 	com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:467)
> 	com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:83)
> 	java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> 	java.util.concurrent.FutureTask.run(FutureTask.java:266)
> 	java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
> 	java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> 	com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:646)
> 	java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> 	java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> 	java.lang.Thread.run(Thread.java:748)
> "sshd-SshServer[df5f657]-nio2-thread-3" daemon prio=5 BLOCKED
> 	org.apache.sshd.common.channel.ChannelOutputStream.close(ChannelOutputStream.java:249)
> 	org.apache.sshd.common.util.io.IoUtils.closeQuietly(IoUtils.java:151)
> 	org.apache.sshd.server.channel.ChannelSession.doCloseImmediately(ChannelSession.java:205)
> 	org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:83)
> 	org.apache.sshd.common.channel.AbstractChannel.close(AbstractChannel.java:576)
> 	org.apache.sshd.common.util.closeable.ParallelCloseable.doClose(ParallelCloseable.java:65)
> 	org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
> 	org.apache.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:46)
> 	org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:83)
> 	org.apache.sshd.common.util.closeable.ParallelCloseable.doClose(ParallelCloseable.java:65)
> 	org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
> 	org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56)
> 	org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45)
> 	org.apache.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69)
> 	org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
> 	org.apache.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:46)
> 	org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:83)
> 	org.apache.sshd.common.session.helpers.AbstractSession.exceptionCaught(AbstractSession.java:973)
> 	org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.exceptionCaught(AbstractSessionIoHandler.java:53)
> 	org.apache.sshd.common.io.nio2.Nio2Session.exceptionCaught(Nio2Session.java:186)
> 	org.apache.sshd.common.io.nio2.Nio2Session.handleWriteCycleFailure(Nio2Session.java:460)
> 	org.apache.sshd.common.io.nio2.Nio2Session$2.onFailed(Nio2Session.java:415)
> 	org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$failed$1(Nio2CompletionHandler.java:46)
> 	org.apache.sshd.common.io.nio2.Nio2CompletionHandler$$Lambda$627/1874891543.run(Unknown Source)
> 	java.security.AccessController.doPrivileged(Native Method)
> 	org.apache.sshd.common.io.nio2.Nio2CompletionHandler.failed(Nio2CompletionHandler.java:45)
> 	sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128)
> 	sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
> 	sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:736)
> 	sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382)
> 	sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:399)
> 	org.apache.sshd.common.io.nio2.Nio2Session.doWriteCycle(Nio2Session.java:401)
> 	org.apache.sshd.common.io.nio2.Nio2Session.startWriting(Nio2Session.java:386)
> 	org.apache.sshd.common.io.nio2.Nio2Session.writePacket(Nio2Session.java:169)
> 	org.apache.sshd.common.session.helpers.AbstractSession.doWritePacket(AbstractSession.java:1181)
> 	org.apache.sshd.common.session.helpers.AbstractSession.sendPendingPackets(AbstractSession.java:910)
> 	org.apache.sshd.common.session.helpers.AbstractSession.handleNewKeys(AbstractSession.java:875)
> 	org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(AbstractSession.java:606)
> 	org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(AbstractSession.java:555)
> 	org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1527)
> 	org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:516)
> 	org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:63)
> 	org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:339)
> 	org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:318)
> 	org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:315)
> 	org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
> 	org.apache.sshd.common.io.nio2.Nio2CompletionHandler$$Lambda$349/1690110070.run(Unknown Source)
> 	java.security.AccessController.doPrivileged(Native Method)
> 	org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
> 	sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
> 	sun.nio.ch.Invoker$2.run(Invoker.java:218)
> 	sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
> 	java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> 	java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> 	java.lang.Thread.run(Thread.java:748)
> "SSH git-upload-pack /project2 (myuser)" prio=1 BLOCKED
> 	org.apache.sshd.common.session.helpers.AbstractSession.writePacket(AbstractSession.java:1107)
> 	org.apache.sshd.common.channel.AbstractChannel.writePacket(AbstractChannel.java:798)
> 	org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:227)
> 	org.apache.sshd.common.channel.ChannelOutputStream.write(ChannelOutputStream.java:127)
> 	org.eclipse.jgit.transport.UploadPack$ResponseBufferedOutputStream.write(UploadPack.java:2183)
> 	org.eclipse.jgit.transport.SideBandOutputStream.writeBuffer(SideBandOutputStream.java:174)
> 	org.eclipse.jgit.transport.SideBandOutputStream.write(SideBandOutputStream.java:153)
> 	org.eclipse.jgit.internal.storage.pack.PackOutputStream.write(PackOutputStream.java:132)
> 	org.eclipse.jgit.internal.storage.file.PackFile.copyAsIs2(PackFile.java:614)
> 	org.eclipse.jgit.internal.storage.file.PackFile.copyAsIs(PackFile.java:433)
> 	org.eclipse.jgit.internal.storage.file.WindowCursor.copyObjectAsIs(WindowCursor.java:221)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObjectImpl(PackWriter.java:1644)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObject(PackWriter.java:1621)
> 	org.eclipse.jgit.internal.storage.pack.PackOutputStream.writeObject(PackOutputStream.java:171)
> 	org.eclipse.jgit.internal.storage.file.WindowCursor.writeObjects(WindowCursor.java:229)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObjects(PackWriter.java:1609)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writeObjects(PackWriter.java:1597)
> 	org.eclipse.jgit.internal.storage.pack.PackWriter.writePack(PackWriter.java:1154)
> 	org.eclipse.jgit.transport.UploadPack.sendPack(UploadPack.java:2133)
> 	org.eclipse.jgit.transport.UploadPack.sendPack(UploadPack.java:1947)
> 	org.eclipse.jgit.transport.UploadPack.service(UploadPack.java:971)
> 	org.eclipse.jgit.transport.UploadPack.upload(UploadPack.java:776)
> 	com.google.gerrit.sshd.commands.Upload.runImpl(Upload.java:77)
> 	com.google.gerrit.sshd.AbstractGitCommand.service(AbstractGitCommand.java:98)
> 	com.google.gerrit.sshd.AbstractGitCommand.access$000(AbstractGitCommand.java:31)
> 	com.google.gerrit.sshd.AbstractGitCommand$1.run(AbstractGitCommand.java:63)
> 	com.google.gerrit.sshd.BaseCommand$TaskThunk.run(BaseCommand.java:467)
> 	com.google.gerrit.server.logging.LoggingContextAwareRunnable.run(LoggingContextAwareRunnable.java:83)
> 	java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> 	java.util.concurrent.FutureTask.run(FutureTask.java:266)
> 	java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
> 	java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> 	com.google.gerrit.server.git.WorkQueue$Task.run(WorkQueue.java:646)
> 	java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> 	java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> 	java.lang.Thread.run(Thread.java:748)
> {noformat}
> In AbstractSession.handleNewKeys(), there is a lock on {{pendingEvents}}, while trying to send these packets; when sending the packets fails, an exception is generated, which causes the channel to get closed by calling ChannelOutputStream.close(), which is a synchronized method.
> At the same time, some other threads are trying to write data to the session: it calls ChannelOutputStream.write(), which is also a synchronized method, which calls AbstractSession.writePacket() which attempts to lock {{pendingPackets}} to queue the packets.
> *NOTE*: in our setup, we can reproduce this quite easily by increasing the parallelism in git-repo, reducing the values of waitTimeout (WAIT_FOR_SPACE_TIMEOUT), rekeyBytesLimit (REKEY_TIME_LIMIT) and rekeyTimeLimit (REKEY_TIME_LIMIT) configuration options.



--
This message was sent by Atlassian Jira
(v8.3.4#803005)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org