You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Sam Gardner (JIRA)" <ji...@apache.org> on 2015/07/14 22:19:05 UTC
[jira] [Commented] (SSHD-348) Some SSH threads get blocked in
Object.wait() method forever
[ 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)