Uploaded image for project: 'MINA SSHD'
  1. MINA SSHD
  2. SSHD-557

MINA SSHD deadlocks upon multiple concurrent HTTP downloads over locally-forwarded ports

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Won't Fix
    • 0.14.0, 1.0.0
    • 1.1.0
    • Fedora 21, kernel 3.17.4-301, OpenJDK 1.8.0_51-b16

    Description

      SSHD-Core 1.0.0 deadlocks when multiple concurrent downloads are in progress over ChannelOutputStreams

      In both Mina-SSHD 0.14.0 and 1.0.0 the server will become deadlocked if multiple concurrent downloads are started over a locally-forwarded TCP socket. In this state the process is still alive and client connections stay open, but no data can be transmitted and new connections will not be accepted - when inspected via telnet, the SSH port will not even return a banner.

      Inspection of the hung process using the jstack tool shows that each NIO worker thread is in the following state: 

      "sshd-SshServer[36f6e879]-nio2-thread-4" #14 daemon prio=5 os_prio=0 tid=0x00007f219c009000 nid=0x34c6 in Object.wait() [0x00007f21c8439000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d799f9b0> (a org.apache.sshd.common.channel.Window)
        at java.lang.Object.wait(Object.java:502)
        at org.apache.sshd.common.channel.Window.waitForSpace(Window.java:175)
        - locked <0x00000000d799f9b0> (a org.apache.sshd.common.channel.Window)
        at org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:126)
        - locked <0x00000000d799fa68> (a org.apache.sshd.common.channel.ChannelOutputStream)
        at org.apache.sshd.server.forward.TcpipServerChannel$1.messageReceived(TcpipServerChannel.java:156)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:220)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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:276)
        at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297)
        at java.nio.channels.AsynchronousSocketChannel.read(AsynchronousSocketChannel.java:420)
        at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:247)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:224)
        at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:212)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:34)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:31)
        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)

      These are the steps to reproduce:

      1. Start up approximately 200 separate SSH sessions with one local forward to an HTTP server:
        ssh -N -LXXXXX:<HTTP_SERVER>:80 account@<MINA_SSHD_SERVER>
        1. To simplify this process, I modified org.apache.sshd.server.auth.AbstractUserAuth to always accept requests - this makes it possible to create the sessions on the same client (though I've also reproduced this on separate clients as well).
        2. This script will setup the client sessions as background processes
      2. With the above sessions alive and backgrounded, fetch large files concurrently from the HTTP server over multiple forwarded ports:
        wget http://localhost:XXXXX/hugefile
        1. This script will start wget downloads in the above manner.
      3. After a time, the wget downloads will stop progressing, and inspection of the SSH server process via jstack <PID> will show each of the nio2-thread-[0-9] threads in the deadlocked state.

      Note: I previously filed SSHD-539 on this, and have since reproduced it on vanilla MINA SSHD-Core without our proprietary modifications and running outside of Tomcat.

      The JAR files I used to reproduce are attached to this ticket as well.

      Attachments

        1. AbstractUserAuth.java
          2 kB
          Sam Gardner
        2. setup-tunnels.sh
          0.5 kB
          Sam Gardner
        3. ssh-load.sh
          0.1 kB
          Sam Gardner
        4. sshd-core-0.14.0-jar-with-dependencies.jar
          4.61 MB
          Sam Gardner
        5. sshd-core-1.0.0-jar-with-dependencies.jar
          5.15 MB
          Sam Gardner
        6. setup-tunnels-remote.sh
          0.5 kB
          Sam Gardner
        7. ssh-load-remote.sh
          0.2 kB
          Sam Gardner

        Issue Links

          is superceded by

          New Feature - A new feature of the product, which has yet to be developed. SSHD-1003 Use asynchronous streams when forwarding ports

          • Major - Major loss of function.
          • Resolved
          relates to

          Improvement - An improvement or enhancement to an existing feature or task. SSHD-565 Require a timeout value on Window's waitForSpace and waitAndConsume methods

          • Major - Major loss of function.
          • Resolved

          Activity

            People

              lgoldstein Lyor Goldstein
              sgardner Sam Gardner
              Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 20m
                  20m