Deadlock with SshClient.exec

[Oleg Aravin]

Hi Guys,

I have a problem during concurrent SSH execution on remote machine through SshClient. I have the following invocation:

org.jclouds.ssh.SshClient sshClient = ...

def execute = sshClient.exec("some command")

The method execute could be invoked from different threads, but sshClient will be the same. At the invocation of that method the threads periodically hangs. 

There are some threads from one program from java jstack thread dump when it hangs:

Thread 11272: (state = BLOCKED)

 - java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise)

 - java.io.PipedInputStream.read() @bci=142, line=327 (Compiled frame)

 - java.io.PipedInputStream.read(byte[], int, int) @bci=43, line=378 (Compiled frame)

 - java.io.InputStream.read(byte[]) @bci=5, line=101 (Interpreted frame)

 - com.google.common.io.ByteStreams.copy(java.io.InputStream, java.io.OutputStream) @bci=10, line=193 (Compiled frame)

 - com.google.common.io.ByteStreams.toByteArray(java.io.InputStream) @bci=10, line=236 (Interpreted frame)

 - org.jclouds.util.Strings2.toStringAndClose(java.io.InputStream) @bci=12, line=131 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create() @bci=32, line=428 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create() @bci=1, line=410 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient.acquire(org.jclouds.ssh.jsch.JschSshClient$Connection) @bci=64, line=207 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient.exec(java.lang.String) @bci=10, line=457 (Interpreted frame)

...

Thread 11268: (state = BLOCKED)

 - java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise)

 - java.io.PipedInputStream.read() @bci=142, line=327 (Compiled frame)

 - java.io.PipedInputStream.read(byte[], int, int) @bci=43, line=378 (Interpreted frame)

 - java.io.InputStream.read(byte[]) @bci=5, line=101 (Interpreted frame)

 - com.google.common.io.ByteStreams.copy(java.io.InputStream, java.io.OutputStream) @bci=10, line=193 (Interpreted frame)

 - com.google.common.io.ByteStreams.toByteArray(java.io.InputStream) @bci=10, line=236 (Interpreted frame)

 - org.jclouds.util.Strings2.toStringAndClose(java.io.InputStream) @bci=12, line=131 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create() @bci=32, line=428 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create() @bci=1, line=410 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient.acquire(org.jclouds.ssh.jsch.JschSshClient$Connection) @bci=64, line=207 (Interpreted frame)

 - org.jclouds.ssh.jsch.JschSshClient.exec(java.lang.String) @bci=10, line=457 (Interpreted frame)

...

I have this problem with jclouds versions 1.4.1, 1.5.0.beta.4 and I didn't test other. 

Does anybody faced with such problem or know how to solve it? 

[Aled Sage]

Hi,

No, I haven't seen this before. From the stacktrace, it has hung when reading the input stream from the ssh exec.

As a workaround, you could try using sshj instead of jsch (configuring it to use the module SshjSshClientModule).

Could you reproduce this with logging on debug for "jclouds.ssh", and send us the log please?

What sort of thing are your commands doing? Could they be producing a very large amount of stdout/stderr? How many commands are you executing concurrently? Is it possible to send us the commands so we can include them in a test case? What OS are you executing against?

Aled

--
You received this message because you are subscribed to the Google Groups "jclouds" group.
To post to this group, send email to jcl...@googlegroups.com.
To unsubscribe from this group, send email to jclouds+u...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/jclouds?hl=en.

[Oleg Aravin]

Hi Aled,

Thank you for the response. I'll try to use sshj as you suggested.

I'll send you the log as soon as I reproduce it in debug mode, but this difficult to reproduce. 

The command is quite simple, it's:

ps aux | grep 'some pid' 

We are using it to monitor the execution status of the process on the VM. It doesn't produce a lot of logs and executes very fast. This command does not have to be executed concurrently, but there is possible for few threads to execute it concurrently, so I'm not sure that the problem exactly in concurrency. I decided it based on the two hanging threads in the thread dump that hang on the same place.

[Andrew Phillips]

Is there any way this could be related to using the PipedInputStream
together with a PipedOutputStream on the same thread? From the
Javadocs [1]:

"Typically, data is read from a PipedInputStream object by one thread
and data is written to the corresponding PipedOutputStream by some
other thread. Attempting to use both objects from a single thread is
not recommended, as it may deadlock the thread"

ap

[1] http://docs.oracle.com/javase/6/docs/api/java/io/PipedInputStream.html

[Aled Sage]

I tried recreating this in a unit test (running 1.5.0-SNAPSHOT on Mac OS X), but haven't been able to reproduce yet.

I used JschSshClientLiveTest to create a JschSshClient, and then did hundreds of concurrent `ps aux | grep 1234`. The only strange behaviour I saw was the exception below. Because of the retry logic, the commands did subsequently succeed.

This makes me doubt whether JschSshClient is thread-safe for doing concurrent execs. I'll investigate this more tomorrow...

org.jclouds.ssh.SshException: error acquiring ChannelExec(): channel is not opened.
    at org.jclouds.ssh.jsch.JschSshClient.propagate(JschSshClient.java:324) [classes/:na]
    at org.jclouds.ssh.jsch.JschSshClient.acquire(JschSshClient.java:174) [classes/:na]
    at org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create(JschSshClient.java:387) ~[classes/:na]
    at org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create(JschSshClient.java:1) ~[classes/:na]
    at org.jclouds.ssh.jsch.JschSshClient.acquire(JschSshClient.java:167) [classes/:na]
    at org.jclouds.ssh.jsch.JschSshClient.exec(JschSshClient.java:417) [classes/:na]
    at org.jclouds.ssh.jsch.JschSshClientLiveTest$2.call(JschSshClientLiveTest.java:195) [test-classes/:na]
    at org.jclouds.ssh.jsch.JschSshClientLiveTest$2.call(JschSshClientLiveTest.java:1) [test-classes/:na]
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [na:1.6.0_33]
    at java.util.concurrent.FutureTask.run(FutureTask.java:138) [na:1.6.0_33]
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [na:1.6.0_33]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [na:1.6.0_33]
    at java.lang.Thread.run(Thread.java:680) [na:1.6.0_33]
Caused by: com.jcraft.jsch.JSchException: channel is not opened.
    at com.jcraft.jsch.Channel.sendChannelOpen(Channel.java:673) ~[jsch-0.1.48.jar:na]
    at com.jcraft.jsch.Channel.connect(Channel.java:151) ~[jsch-0.1.48.jar:na]
    at com.jcraft.jsch.Channel.connect(Channel.java:145) ~[jsch-0.1.48.jar:na]
    at org.jclouds.ssh.jsch.JschSshClient$3.create(JschSshClient.java:358) ~[classes/:na]
    at org.jclouds.ssh.jsch.JschSshClient$3.create(JschSshClient.java:1) ~[classes/:na]
    at org.jclouds.ssh.jsch.JschSshClient.acquire(JschSshClient.java:167) [classes/:na]
    ... 11 common frames omitted

---
The PipedInputStream/PipedOutputStream: could be a problem, but I think that writing to the PipedOutputStream is deep within com.jcraft.jsch code. I presume it will be a different thread, but maybe that's just wishful thinking! I'll investigate that as well tomorrow.

Aled

[Adrian Cole]

Great job, Aled.

Do you mind opening an issue and tracking there? Seems important for
those using jsch.

-A

[Oleg Aravin]

Guys, 

I reproduced this issue without concurrency and with 2 seconds timeout between invocations of method exec. 

There is a debug logs from "jclouds.ssh":

2012-07-11 11:34:41,790 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ExecResponse(command=[(echo "./exec-run.sh")|(sudo 'at' 'now')])

2012-07-11 11:34:41,791 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ChannelExec()

2012-07-11 11:34:41,792 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired com.jcraft.jsch.ChannelExec@10aab12f

2012-07-11 11:34:41,821 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired {output=job 3 at 2012-07-11 07:34

, error=, exitStatus=0}

2012-07-11 11:34:42,402 DEBUG [akka:event-driven:dispatcher:global-16] jclouds.ssh: >> (ubuntu:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@50.19.154.161:22) acquiring ExecResponse(command=[(ps 'aux')|(grep '9dc6595b-c886-4099-82c4-4b68e3d4bf58')])

2012-07-11 11:34:42,403 DEBUG [akka:event-driven:dispatcher:global-16] jclouds.ssh: >> (ubuntu:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@50.19.154.161:22) acquiring ChannelExec()

2012-07-11 11:34:42,405 DEBUG [akka:event-driven:dispatcher:global-16] jclouds.ssh: << (ubuntu:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@50.19.154.161:22) acquired com.jcraft.jsch.ChannelExec@77ab6495

2012-07-11 11:34:42,431 DEBUG [akka:event-driven:dispatcher:global-16] jclouds.ssh: << (ubuntu:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@50.19.154.161:22) acquired {output=root      3410  0.0  0.0  19168  1692 ?        SN   11:33   0:00 /bin/bash ./exec-run.sh 

root      3411  0.0  0.0  19168   904 ?        SN   11:33   0:00 /bin/bash ./exec-run.sh 

ubuntu   16325  0.0  0.0  10724  1456 pts/0    Ss+  11:34   0:00 bash -c (ps 'aux')|(grep '9dc6595b-c886-4099-82c4-4b68e3d4bf58')

ubuntu   16329  0.0  0.0   7628   936 pts/0    S+   11:34   0:00 grep 9dc6595b-c886-4099-82c4-4b68e3d4bf58

, error=, exitStatus=0}

…

2012-07-11 11:36:37,426 DEBUG [akka:event-driven:dispatcher:global-15] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ExecResponse(command=[(ps 'aux')|(grep '271bc997-34a3-4de7-b470-e7011239aef6')])

2012-07-11 11:36:37,427 DEBUG [akka:event-driven:dispatcher:global-15] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ChannelExec()

2012-07-11 11:36:37,430 DEBUG [akka:event-driven:dispatcher:global-15] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired com.jcraft.jsch.ChannelExec@75b6d432

2012-07-11 11:36:37,508 DEBUG [akka:event-driven:dispatcher:global-15] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired {output=root      2220  0.0  0.0   9196  1268 ?        SN   07:34   0:00 /bin/bash ./exec-run.sh 

root      2221  0.0  0.0   9192   736 ?        SN   07:34   0:00 /bin/bash ./exec-run.sh 

root     19703  0.0  0.0   9192  1368 pts/0    SNs+ 07:36   0:00 bash -c (ps 'aux')|(grep '271bc997-34a3-4de7-b470-e7011239aef6')

root     19710  0.0  0.0   6368   708 pts/0    SN+  07:36   0:00 grep 271bc997-34a3-4de7-b470-e7011239aef6

, error=, exitStatus=0}

2012-07-11 11:36:39,426 DEBUG [akka:event-driven:dispatcher:global-14] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ExecResponse(command=[(ps 'aux')|(grep '271bc997-34a3-4de7-b470-e7011239aef6')])

2012-07-11 11:36:39,427 DEBUG [akka:event-driven:dispatcher:global-14] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ChannelExec()

2012-07-11 11:36:39,429 DEBUG [akka:event-driven:dispatcher:global-14] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired com.jcraft.jsch.ChannelExec@18b612da

2012-07-11 11:36:39,455 DEBUG [akka:event-driven:dispatcher:global-14] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired {output=root      2220  0.0  0.0   9196  1268 ?        SN   07:34   0:00 /bin/bash ./exec-run.sh 

root      2221  0.0  0.0   9192   736 ?        SN   07:34   0:00 /bin/bash ./exec-run.sh

root     21236  0.0  0.0   9192  1360 pts/0    SNs+ 07:36   0:00 bash -c (ps 'aux')|(grep '271bc997-34a3-4de7-b470-e7011239aef6')

root     21240  0.0  0.0   6368   704 pts/0    SN+  07:36   0:00 grep 271bc997-34a3-4de7-b470-e7011239aef6

, error=, exitStatus=0}

2012-07-11 11:36:41,426 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ExecResponse(command=[(ps 'aux')|(grep '271bc997-34a3-4de7-b470-e7011239aef6')])

2012-07-11 11:36:41,427 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ChannelExec()

2012-07-11 11:36:41,429 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired com.jcraft.jsch.ChannelExec@6f343008

2012-07-11 11:36:41,454 DEBUG [akka:event-driven:dispatcher:global-4] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired {output=root      2220  0.0  0.0   9196  1268 ?        SN   07:34   0:00 /bin/bash ./exec-run.sh 

root      2221  0.0  0.0   9192   736 ?        SN   07:34   0:00 /bin/bash ./exec-run.sh 

root     21823  0.0  0.0   9192  1368 pts/0    SNs+ 07:36   0:00 bash -c (ps 'aux')|(grep '271bc997-34a3-4de7-b470-e7011239aef6')

root     21827  0.0  0.0   6368   704 pts/0    SN+  07:36   0:00 grep 271bc997-34a3-4de7-b470-e7011239aef6

, error=, exitStatus=0}

2012-07-11 11:36:43,426 DEBUG [akka:event-driven:dispatcher:global-7] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ExecResponse(command=[(ps 'aux')|(grep '271bc997-34a3-4de7-b470-e7011239aef6')])

2012-07-11 11:36:43,427 DEBUG [akka:event-driven:dispatcher:global-7] jclouds.ssh: >> (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquiring ChannelExec()

2012-07-11 11:36:43,439 DEBUG [akka:event-driven:dispatcher:global-7] jclouds.ssh: << (root:rsa[fingerprint(5d:87:fd:61:a7:05:44:86:a5:37:69:6c:6a:ac:96:f2),sha1(c6:fb:4c:50:4d:13:f0:28:e1:27:4e:42:67:a3:24:fe:57:c8:70:cc)]@67.202.3.136:22) acquired com.jcraft.jsch.ChannelExec@6fad3709

After that the thread akka:event-driven:dispatcher:global-7 hangs with the following trace:

Name: akka:event-driven:dispatcher:global-7

State: TIMED_WAITING on com.jcraft.jsch.Channel$MyPipedInputStream@45fc4149

Total blocked: 487  Total waited: 3,888

Stack trace: 

 java.lang.Object.wait(Native Method)

java.io.PipedInputStream.read(PipedInputStream.java:327)

java.io.PipedInputStream.read(PipedInputStream.java:378)

java.io.InputStream.read(InputStream.java:101)

com.google.common.io.ByteStreams.copy(ByteStreams.java:193)

com.google.common.io.ByteStreams.toByteArray(ByteStreams.java:236)

org.jclouds.util.Strings2.toStringAndClose(Strings2.java:131)

org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create(JschSshClient.java:428)

org.jclouds.ssh.jsch.JschSshClient$ExecConnection.create(JschSshClient.java:410)

org.jclouds.ssh.jsch.JschSshClient.acquire(JschSshClient.java:207)

org.jclouds.ssh.jsch.JschSshClient.exec(JschSshClient.java:457)

...

So, it seems that the problem occurs even without concurrency. My OS is Ubuntu 11.10, OS to which I'm trying to connect is CentOS Linux release 6.0 (Final). The jclouds version is 1.4.1.    

[Aled Sage]

Thanks.

I've created issue http://code.google.com/p/jclouds/issues/detail?id=1016, and submitted pull request https://github.com/jclouds/jclouds/pull/709.

Aled

On 11/07/2012 14:19, Oleg Aravin wrote:

Guys,�

I reproduced this issue without�concurrency�and with�2 seconds�timeout between invocations of�method�exec.�

[Oleg Aravin]

Great, BTW when do you think this will be available in the release version? 

On Wed, Jul 11, 2012 at 5:55 PM, Aled Sage <aled...@gmail.com> wrote:

Thanks.

I've created issue http://code.google.com/p/jclouds/issues/detail?id=1016, and submitted pull request https://github.com/jclouds/jclouds/pull/709.

Aled

On 11/07/2012 14:19, Oleg Aravin wrote:

Guys, 

I reproduced this issue without concurrency and with 2 seconds timeout between invocations of method exec. 

There is a debug logs from "jclouds.ssh":

--

[Adrian Cole]

Hi, Oleg.

We just cut 1.5.0-beta.6, so the next will be out either this weekend or Monday.  Changes haven't settled down enough for release candidate, yet. Probably end of the month.

-A

P.s. akka finds concurrency bugs :)

[Oleg Aravin]

Hi Adrian,

Thank you for the quick new version, I'll try it!

P.s. :)