[
https://issues.apache.org/jira/browse/SSHD-348?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14626984#comment-14626984
]
Sam Gardner commented on SSHD-348:
----------------------------------
I'm seeing a similar issue with MINA 0.14.0: {noformat}
"sshd-SshServer[7b5477d5]-nio2-thread-5" prio=5 tid=0x00007fa4d6854800
nid=0x380b in Object.wait() [0x000000011e55a000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000706a428e0> (a
org.apache.sshd.common.channel.Window)
at java.lang.Object.wait(Object.java:503)
at org.apache.sshd.common.channel.Window.waitForSpace(Window.java:152)
- locked <0x0000000706a428e0> (a org.apache.sshd.common.channel.Window)
at
org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:116)
- locked <0x0000000706a422e8> (a
org.apache.sshd.common.channel.ChannelOutputStream)
at
org.apache.sshd.common.forward.TcpipServerChannel$1.messageReceived(TcpipServerChannel.java:121)
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:1)
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.invokeDirect(Invoker.java:157)
at
sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:275)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:296)
at
java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:407)
at
org.apache.sshd.common.io.nio2.Nio2Session.startReading(Nio2Session.java:170)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:186)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:1)
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.invokeDirect(Invoker.java:157)
at
sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:275)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:296)
at
java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:407)
at
org.apache.sshd.common.io.nio2.Nio2Session.startReading(Nio2Session.java:170)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:186)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:1)
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.invokeDirect(Invoker.java:157)
at
sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:275)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:296)
at
java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:407)
at
org.apache.sshd.common.io.nio2.Nio2Session.startReading(Nio2Session.java:170)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:186)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:1)
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:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
{noformat}
This does not implicate my code directly, but a similarly-hung thread _does_
(note the CustomServerSession trace): {noformat}
"sshd-SshServer[7b5477d5]-nio2-thread-4" prio=5 tid=0x00007fa4d6301800
nid=0x3b07 runnable [0x000000011e457000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.FileDispatcherImpl.close0(Native Method)
at sun.nio.ch.SocketDispatcher.close(SocketDispatcher.java:55)
at
sun.nio.ch.UnixAsynchronousSocketChannelImpl.implClose(UnixAsynchronousSocketChannelImpl.java:222)
at
sun.nio.ch.AsynchronousSocketChannelImpl.close(AsynchronousSocketChannelImpl.java:143)
at
org.apache.sshd.common.io.nio2.Nio2Session.doCloseImmediately(Nio2Session.java:150)
at
org.apache.sshd.common.util.CloseableUtils$AbstractCloseable.close(CloseableUtils.java:276)
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:1)
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:1)
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.doCloseImmediately(CloseableUtils.java:356)
at
org.apache.sshd.common.session.AbstractSession.doCloseImmediately(AbstractSession.java:481)
at
org.apache.sshd.common.util.CloseableUtils$AbstractCloseable.close(CloseableUtils.java:276)
at
com.proprietary.relay.sshd.server.session.CustomServerSession.doClose(CustomServerSession.java:378)
at
com.proprietary.relay.sshd.server.session.CustomServerSession.close(CustomServerSession.java:316)
at
org.apache.sshd.common.session.AbstractSession.exceptionCaught(AbstractSession.java:468)
at
org.apache.sshd.common.AbstractSessionIoHandler.exceptionCaught(AbstractSessionIoHandler.java:47)
at
org.apache.sshd.common.io.nio2.Nio2Session.exceptionCaught(Nio2Session.java:125)
at
org.apache.sshd.common.io.nio2.Nio2Session.access$3(Nio2Session.java:118)
at
org.apache.sshd.common.io.nio2.Nio2Session$2.onFailed(Nio2Session.java:227)
at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler$2.run(Nio2CompletionHandler.java:41)
at java.security.AccessController.doPrivileged(Native Method)
at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.failed(Nio2CompletionHandler.java:39)
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128)
at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
at
sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:736)
at
sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:381)
at
sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:398)
at
java.nio.channels.AsynchronousSocketChannel.write(AsynchronousSocketChannel.java:560)
at
org.apache.sshd.common.io.nio2.Nio2Session.startWriting(Nio2Session.java:209)
at
org.apache.sshd.common.io.nio2.Nio2Session.write(Nio2Session.java:114)
at
org.apache.sshd.common.session.AbstractSession.doWritePacket(AbstractSession.java:557)
- locked <0x00000007051e3a38> (a java.lang.Object)
at
com.proprietary.relay.sshd.server.session.CustomServerSession.doWritePacket(CustomServerSession.java:306)
at
com.proprietary.relay.sshd.server.session.CustomServerSession.writePacket(CustomServerSession.java:297)
at
org.apache.sshd.common.channel.AbstractChannel.writePacket(AbstractChannel.java:218)
at
org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:132)
- locked <0x0000000706651618> (a
org.apache.sshd.common.channel.ChannelOutputStream)
at
org.apache.sshd.common.forward.TcpipServerChannel$1.messageReceived(TcpipServerChannel.java:121)
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:1)
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.invokeDirect(Invoker.java:157)
at
sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:275)
at
sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:296)
at
java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:407)
at
org.apache.sshd.common.io.nio2.Nio2Session.startReading(Nio2Session.java:170)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:186)
at
org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:1)
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:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
{noformat}
> Some SSH threads get blocked in Object.wait() method forever
> ------------------------------------------------------------
>
> Key: SSHD-348
> URL: https://issues.apache.org/jira/browse/SSHD-348
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 0.10.0, 0.10.1, 0.11.0, 0.12.0, 0.13.0
> Environment: Gerrit Code Review 2.9.1 (SSHD 0.12.0)
> Gerrit Code Review 2.9.2 (SSHD 0.13.0)
> Gerrit Code Review 2.9.3 (Downgraded to SSHD 0.9)
> Reporter: David Ostrovsky
> Assignee: Guillaume Nodet
> Priority: Blocker
> Fix For: 0.14.0
>
> Attachments: 0001-Prepare-release-sshd-0.13.0-72f868e26.patch,
> debugLogs.txt, diff, threaddump.txt
>
>
> This seems to be a regression started from 0.10.1.
> In Gerrit we have SSH commamds that returns immediately and so called
> stream-events command which keeps connection open until clients disconnect.
> Basically for days or weeks. This is used for example to inform CI system
> (jenkins) about events in gerrit, like new patch set upload etc.
> In Gerrit we have configurable "SSH-Stream-Worker" thread pool which is
> dedicated to the mentioned stream-events SSH command. The observed behaviour
> on latest SSHD release is that after some time all threads are stuck. They
> aren't stuck at the same time, but one after another untill at some time all
> threads are stuck and Gerrit must be restarted. Usually after one week. The
> stack dump of all such stuck thread are the same, see below. If we had a
> patch we could apply it to our production Gerrit instance and try if this
> helps.
> {code}
> "SSH-Stream-Worker-10" cpu=95400.00 [reset 95400.00] ms elapsed=146444.30
> [reset 146444.30] s allocated=5526700000 B (5.15 GB) [reset 5526700000 B
> (5.15 GB)] defined_classes=0
> io= file i/o: 15622752/0 B, net i/o: 0/0 B, files opened:0, socks opened:0
> [reset file i/o: 15622752/0 B, net i/o: 0/0 B, files opened:0, socks opened:0
> ]
> prio=10 tid=0x00007f54514df800 nid=0x1c71 / 7281 pthread-id=139999281374976
> in Object.wait() [_thread_blocked (_at_safepoint),
> stack(0x00007f541f5f6000,0x00007f541f6f7000)] [0x00007f541f6f5000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(J)V(Native Method)
> - waiting on <0x00007f553aa530d0> (a
> org.apache.sshd.common.channel.Window)
> at java.lang.Object.wait()V(Object.java:503)
> at
> org.apache.sshd.common.channel.Window.waitForSpace()I(Window.java:148)
> - locked <0x00007f553aa530d0> (a org.apache.sshd.common.channel.Window)
> at
> org.apache.sshd.common.channel.ChannelOutputStream.flush()V(ChannelOutputStream.java:116)
> - locked <0x00007f553aa55060> (a
> org.apache.sshd.common.channel.ChannelOutputStream)
> at
> org.apache.sshd.common.channel.ChannelOutputStream.write([BII)V(ChannelOutputStream.java:84)
> - locked <0x00007f553aa55060> (a
> org.apache.sshd.common.channel.ChannelOutputStream)
> at sun.nio.cs.StreamEncoder.writeBytes()V(StreamEncoder.java:221)
> at sun.nio.cs.StreamEncoder.implFlushBuffer()V(StreamEncoder.java:291)
> at sun.nio.cs.StreamEncoder.implFlush()V(StreamEncoder.java:295)
> at sun.nio.cs.StreamEncoder.flush()V(StreamEncoder.java:141)
> - locked <0x00007f553aa7e258> (a java.io.OutputStreamWriter)
> at java.io.OutputStreamWriter.flush()V(OutputStreamWriter.java:229)
> at java.io.BufferedWriter.flush()V(BufferedWriter.java:254)
> - locked <0x00007f553aa7e258> (a java.io.OutputStreamWriter)
> at java.io.PrintWriter.flush()V(PrintWriter.java:320)
> - locked <0x00007f553aa7e210> (a java.io.BufferedWriter)
> at java.io.PrintWriter.checkError()Z(PrintWriter.java:357)
> at
> com.google.gerrit.sshd.commands.StreamEvents.writeEvents()V(StreamEvents.java:186)
> at
> com.google.gerrit.sshd.commands.StreamEvents.access$100(Lcom/google/gerrit/sshd/commands/StreamEvents;)V(StreamEvents.java:43)
> at
> com.google.gerrit.sshd.commands.StreamEvents$3.run()V(StreamEvents.java:82)
> at
> java.util.concurrent.Executors$RunnableAdapter.call()Ljava/lang/Object;(Executors.java:471)
> at java.util.concurrent.FutureTask.run()V(FutureTask.java:262)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Ljava/util/concurrent/ScheduledThreadPoolExecutor$ScheduledFutureTask;)V(ScheduledThreadPoolExecutor.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run()V(ScheduledThreadPoolExecutor.java:292)
> at
> com.google.gerrit.server.git.WorkQueue$Task.run()V(WorkQueue.java:364)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run()V(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run()V(Thread.java:812)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
