Thread: [JSch-users] Bug: ChannelDirectTCPIP fails if remote side sends EOF quickly
Status: Alpha
Brought to you by:
ymnk
|
From: Paul E. <Pau...@gm...> - 2011-05-20 01:24:36
|
Hello Atsuhiko (and other interested parties), I tried to open a direct-tcpip channel to some TCP server which replies with a message and immediately closes the connection. (See [0] for background.) When trying this with the StreamForwarding example, it shows the output and then throws an JSchException (in `.connect()`). When modifying the example to use `getInputStream()` instead of `setOutputStream()`, it only throws the exception and I don't get to read from the stream because of the exception. I added quite some debugging commands to Session.run [1] to localize the problem. At the end [2] is the output when adding the logger from the Logger example. The same problem occurs if I use socket-forwarding (PortForwardingL), but the PortWatcher's run() loop silently discards the exception. I added a logging call in the catch block, see below [3] for example output (last line shows the exception, without stack trace). As we can see, the remote host sends an SSH_MSG_CHANNEL_EOF before our channel's connect() method had the chance to even see that the connection is open, and thus it throws an exception instead of simply returning. Solution idea: We should in the Session's packet read loop somehow treat SSH_MSG_CHANNEL_OPEN_FAILURE differently than SSH_MSG_CHANNEL_EOF. Now, both are calling channel.remote_eof(), and this is used by the ChannelDirectTCPIP to tell wether the connection was successful. Maybe the ChannelDirectTCPIP could use the exit code, or another additional status variable instead of remote_eof for this decision. Paŭlo [0] Background: I wanted to create a general SocketImpl based on JSch's ChannelDirectTCPIP, so I can implement a SocketFactory or similar things for other libraries (like RMI or Webservice calls). I searched a bit for a simple enough server to test this, and finally used a server I'm working with on my current project (the same one that got me to JSch, and where I'm using the ProxySSH I posted some weeks ago). Normally this is used with "telnet localhost 2006". I think another example with similar behaviour would be the standard Daytime service as defined in RFC 861. When my TunnelSocketImpl not worked (same exception as described), I tried with the official examples. [1] I commited the latest changes to the better-examples branch of my github repository. You can view the source here: <https://github.com/ePaul/jsch-documentation/blob/better-examples/src/com/jcraft/jsch/Session.java#L1300> (I think I will move this to the master branch later.) [2] Log output from StreamForwarding example with added logger. The lines starting with 10.5. are on stdout, what the remote host sent. The rest is logging output on stderr. INFO: Connecting to 141.20.23.223 port 22 INFO: Connection established INFO: Remote version string: SSH-2.0-dropbear_0.52 INFO: Local version string: SSH-2.0-JSCH-0.1.44 INFO: CheckCiphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-ctr,arcfour,arcfour128,arcfour256 INFO: SSH_MSG_KEXINIT sent INFO: SSH_MSG_KEXINIT received INFO: kex: server->client aes128-ctr hmac-md5 none INFO: kex: client->server aes128-ctr hmac-md5 none INFO: SSH_MSG_KEXDH_INIT sent INFO: expecting SSH_MSG_KEXDH_REPLY INFO: ssh_rsa_verify: signature true WARN: Permanently added '141.20.23.223' (RSA) to the list of known hosts. INFO: SSH_MSG_NEWKEYS sent INFO: SSH_MSG_NEWKEYS received INFO: SSH_MSG_SERVICE_REQUEST sent INFO: SSH_MSG_SERVICE_ACCEPT received INFO: Authentications that can continue: publickey,keyboard-interactive,password INFO: Next authentication method: publickey INFO: Authentications that can continue: password INFO: Next authentication method: password INFO: Authentication succeeded (password). System.{in,out} will be forwarded to localhost:2006. DEBUG: waiting for channel reply ... DEBUG: packet received, type: 91 INFO: SSH_MSG_CHANNEL_OPEN_CONFIRMATION received, channel: 0 DEBUG: packet received, type: 94 INFO: SSH_MSG_CHANNEL_DATA received, channel: 0, len: 772 10.7.205.149,1353052,5242911,37,2,0 10.5.59.109,1353031,5242920,1000,1,0 10.5.58.253,1353072,5242964,36,2,0 10.7.205.151,1353009,5243308,51,2,0 10.5.59.93,1353008,5242896,86,2,0 10.7.205.153,1353333,5243057,60,2,0 10.5.59.150,1353085,5242948,74,2,0 10.5.70.9,1352998,5243159,55,2,0 10.5.59.159,1353108,5242965,55,2,0 10.5.70.16,1353094,5242978,52,2,0 10.5.70.8,1353145,5243099,51,2,0 10.5.59.151,1353205,5242922,86,2,0 10.5.59.142,1352973,5242900,58,2,0 10.5.59.147,1353018,5242996,41,2,0 10.5.70.54,1353130,5242946,33,2,0 10.5.59.161,1353426,5243212,59,2,0 10.5.70.12,1353128,5242955,71,2,0 10.5.59.117,1353091,5242902,103,2,0 10.5.59.111,1353086,5242954,14,2,0 10.5.59.153,1353032,5242921,56,2,0 10.7.205.14,1353035,5242951,1000,1,0 10.5.58.251,1353129,5242940,1000,1,0 DEBUG: packet received, type: 96 INFO: SSH_MSG_CHANNEL_EOF received, channel: 0 DEBUG: packet received, type: 97 INFO: SSH_MSG_CHANNEL_CLOSE received, channel: 0 DEBUG: ... finished waiting for channel reply Exception in thread "main" com.jcraft.jsch.JSchException: channel is not opened: remote EOF at com.jcraft.jsch.ChannelDirectTCPIP.connect(ChannelDirectTCPIP.java:127) at StreamForwarding.main(StreamForwarding.java:60) ----------- [3] Logging output from PortForwardingL example with added logger. INFO: Connecting to 141.20.23.223 port 22 INFO: Connection established INFO: Remote version string: SSH-2.0-dropbear_0.52 INFO: Local version string: SSH-2.0-JSCH-0.1.44 INFO: CheckCiphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-ctr,arcfour,arcfour128,arcfour256 INFO: SSH_MSG_KEXINIT sent INFO: SSH_MSG_KEXINIT received INFO: kex: server->client aes128-ctr hmac-md5 none INFO: kex: client->server aes128-ctr hmac-md5 none INFO: SSH_MSG_KEXDH_INIT sent INFO: expecting SSH_MSG_KEXDH_REPLY INFO: ssh_rsa_verify: signature true WARN: Permanently added '141.20.23.223' (RSA) to the list of known hosts. INFO: SSH_MSG_NEWKEYS sent INFO: SSH_MSG_NEWKEYS received INFO: SSH_MSG_SERVICE_REQUEST sent INFO: SSH_MSG_SERVICE_ACCEPT received INFO: Authentications that can continue: publickey,keyboard-interactive,password INFO: Next authentication method: publickey INFO: Authentications that can continue: password INFO: Next authentication method: password INFO: Authentication succeeded (password). localhost:2007 -> localhost:2006 DEBUG: waiting for channel reply ... DEBUG: packet received, type: 91 INFO: SSH_MSG_CHANNEL_OPEN_CONFIRMATION received, channel: 0 DEBUG: packet received, type: 94 INFO: SSH_MSG_CHANNEL_DATA received, channel: 0, len: 774 DEBUG: packet received, type: 96 INFO: SSH_MSG_CHANNEL_EOF received, channel: 0 DEBUG: packet received, type: 97 INFO: SSH_MSG_CHANNEL_CLOSE received, channel: 0 DEBUG: ... finished waiting for channel reply WARN: com.jcraft.jsch.JSchException: channel is not opened: remote EOF |
|
From: <ym...@jc...> - 2011-05-24 08:32:34
|
Hi, Sorry for my delay of reply, +-From: Paul Ebermann <Pau...@gm...> -- |_Date: Fri, 20 May 2011 03:24:27 +0200 _______ | |I tried to open a direct-tcpip channel to some TCP server which replies |with a message and immediately closes the connection. (See [0] for background.) ... |As we can see, the remote host sends an SSH_MSG_CHANNEL_EOF before our channel's |connect() method had the chance to even see that the connection is open, and thus |it throws an exception instead of simply returning. You are right. It must be a bug. Could you try the following? http://www.jcraft.com/jsch/jsch-0.1.45-rc3.zip Sincerely, -- Atsuhiko Yamanaka JCraft,Inc. 1-14-20 HONCHO AOBA-KU, SENDAI, MIYAGI 980-0014 Japan. Tel +81-22-723-2150 +1-415-578-3454 Skype callto://jcraft/ Twitter: http://twitter.com/ymnk Facebook: http://facebook.com/aymnk |
|
From: Paul E. <Pau...@gm...> - 2011-05-24 13:56:34
|
Atsuhiko Yamanaka schrieb: > Hi, > > Sorry for my delay of reply, No problem, I have enough other things to do in the meantime. (And also, Axis seems to not provide any way to set a specific SocketFactory object, only a SocketFactory class name, thus I'll have to use normal port forwarding for my project.) > +-From: Paul Ebermann <Pau...@gm...> -- > |_Date: Fri, 20 May 2011 03:24:27 +0200 _______ > | > |I tried to open a direct-tcpip channel to some TCP server which replies > |with a message and immediately closes the connection. (See [0] for background.) > ... > |As we can see, the remote host sends an SSH_MSG_CHANNEL_EOF before our channel's > |connect() method had the chance to even see that the connection is open, and thus > |it throws an exception instead of simply returning. > > You are right. It must be a bug. Could you try the following? > http://www.jcraft.com/jsch/jsch-0.1.45-rc3.zip Now the StreamForwarding example doesn't do anything after connecting (independently of whether the server sends something, ends the stream or not). Applying my debugging patches on it results in this (I added "timeout" or "failure" to the two Exception messages in ChannelDirectTCPIP.connect(), corresponding to the comment there): INFO: Connecting to 141.20.23.223 port 22 INFO: Connection established INFO: Remote version string: SSH-2.0-dropbear_0.52 INFO: Local version string: SSH-2.0-JSCH-0.1.45 INFO: CheckCiphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-ctr,arcfour,arcfour128,arcfour256 INFO: CheckKexes: diffie-hellman-group14-sha1 INFO: SSH_MSG_KEXINIT sent INFO: SSH_MSG_KEXINIT received INFO: kex: server->client aes128-ctr hmac-md5 none INFO: kex: client->server aes128-ctr hmac-md5 none INFO: SSH_MSG_KEXDH_INIT sent INFO: expecting SSH_MSG_KEXDH_REPLY INFO: ssh_rsa_verify: signature true WARN: Permanently added '141.20.23.223' (RSA) to the list of known hosts. INFO: SSH_MSG_NEWKEYS sent INFO: SSH_MSG_NEWKEYS received INFO: SSH_MSG_SERVICE_REQUEST sent INFO: SSH_MSG_SERVICE_ACCEPT received INFO: Authentications that can continue: publickey,keyboard-interactive,password INFO: Next authentication method: publickey INFO: Authentications that can continue: password INFO: Next authentication method: password INFO: Authentication succeeded (password). System.{in,out} will be forwarded to localhost:2006. DEBUG: waiting 5000 ms for channel reply ... DEBUG: packet received, type: 91 INFO: SSH_MSG_CHANNEL_OPEN_CONFIRMATION received, channel: 0 DEBUG: ... finished waiting for channel reply Exception in thread "main" com.jcraft.jsch.JSchException: channel is not opened (failure). at com.jcraft.jsch.ChannelDirectTCPIP.connect(ChannelDirectTCPIP.java:141) at StreamForwarding.main(Unknown Source) DEBUG: packet received, type: 94 INFO: SSH_MSG_CHANNEL_DATA received, channel: 0, len: 804 DEBUG: packet received, type: 96 INFO: SSH_MSG_CHANNEL_EOF received, channel: 0 DEBUG: packet received, type: 97 INFO: SSH_MSG_CHANNEL_CLOSE received, channel: 0 It creates the channel (and receives packets), but still throws an Exception here. (The packets don't appear on stdout, here.) Paŭlo |
|
From: Paul E. <Pau...@gm...> - 2011-05-24 18:50:43
|
(Atsuiko: Sorry for double sending, I first used the wrong sender address.) Paul Ebermann schrieb: > Atsuhiko Yamanaka schrieb: >> Hi, >> >> Sorry for my delay of reply, > > No problem, I have enough other things to do in the meantime. > > (And also, Axis seems to not provide any way to set a specific > SocketFactory object, only a SocketFactory class name, thus I'll > have to use normal port forwarding for my project.) > >> +-From: Paul Ebermann <Pau...@gm...> -- >> |_Date: Fri, 20 May 2011 03:24:27 +0200 _______ >> | >> |I tried to open a direct-tcpip channel to some TCP server which replies >> |with a message and immediately closes the connection. (See [0] for background.) >> ... >> |As we can see, the remote host sends an SSH_MSG_CHANNEL_EOF before our channel's >> |connect() method had the chance to even see that the connection is open, and thus >> |it throws an exception instead of simply returning. >> >> You are right. It must be a bug. Could you try the following? >> http://www.jcraft.com/jsch/jsch-0.1.45-rc3.zip > > Now the StreamForwarding example doesn't do anything after connecting > (independently of whether the server sends something, ends the stream > or not). An addition: The only output is this line: System.{in,out} will be forwarded to localhost:2006. Now I have even more strange results. Your plain sources compiled and executed with java version "1.4.2_04" Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2_04-b05) Java HotSpot(TM) Client VM (build 1.4.2_04-b05, mixed mode) work without any problems, while the same class files running with java version "1.6.0_20" OpenJDK Runtime Environment (IcedTea6 1.9.7) (suse-1.2.1-x86_64) OpenJDK 64-Bit Server VM (build 19.0-b09, mixed mode) give the hanging described above. (The main thread finishes, but there is no output at all.) The "Connect thread 141.20.23.223 session" stays in java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:146) at com.jcraft.jsch.IO.getByte(IO.java:82) at com.jcraft.jsch.Session.read(Session.java:837) at com.jcraft.jsch.Session.run(Session.java:1259) at java.lang.Thread.run(Thread.java:636) On the server the TCP connection to 2006 is already closed, nothing to see there (but the SSH connection is still open, of course). The same occurs with this runtime: java version "1.5.0_01" Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_01-b08) Java HotSpot(TM) Client VM (build 1.5.0_01-b08, mixed mode) Now, with my current master branch (just pushed to github), it works even on 1.6.0_20, with activated logging. The differences (apart from lots of addes (documentation) comments) are only logging output in ChannelDirectTCPIP and Session (I'm just looking at the diff). Then, using the `better-examples` branch, I sometimes get the output, but still the exception, while at other times I'll get no output (only the exception (like the log in the last message) - just now in two successing runs of the same program. (Both with activated logging.) If I port only the logging changes to your RC version (see branch directtcpip-bug), the output shows nothing without logging, and with logging sometimes the data, sometimes not. It never shows the exception. (The difference on showing the output or not is whether the SSH_MSG_CHANNEL_DATA comes before "finished waiting" (it shows the output) or after it (it doesn't show).) Could it be that there is a timing problem (i.e. some race condition)? I didn't yet look thouroughly at your new implementation of ChannelDirectTCPIP.connect, only superficialy to add my logging again. Paŭlo |
|
From: <ym...@jc...> - 2011-05-25 06:32:45
|
Hi, +-From: Paul Ebermann <Pau...@gm...> -- |_Date: Tue, 24 May 2011 15:56:17 +0200 _______ | |Now the StreamForwarding example doesn't do anything after connecting |(independently of whether the server sends something, ends the stream |or not). ... |DEBUG: packet received, type: 91 |INFO: SSH_MSG_CHANNEL_OPEN_CONFIRMATION received, channel: 0 |DEBUG: ... finished waiting for channel reply |Exception in thread "main" com.jcraft.jsch.JSchException: channel is not opened (failure). | at com.jcraft.jsch.ChannelDirectTCPIP.connect(ChannelDirectTCPIP.java:141) | at StreamForwarding.main(Unknown Source) That is my fault. Could you try the following? http://www.jcraft.com/jsch/jsch-0.1.45-rc4.zip Sincerely, -- Atsuhiko Yamanaka JCraft,Inc. 1-14-20 HONCHO AOBA-KU, SENDAI, MIYAGI 980-0014 Japan. Tel +81-22-723-2150 +1-415-578-3454 Skype callto://jcraft/ Twitter: http://twitter.com/ymnk Facebook: http://facebook.com/aymnk |
|
From: Paul E. <Pau...@gm...> - 2011-05-25 12:58:59
|
Atsuhiko Yamanaka skribis: > http://www.jcraft.com/jsch/jsch-0.1.45-rc4.zip It seems to work now, thanks. Below an example log with the debugging-enabled version. Paŭlo --- INFO: Connecting to 141.20.23.223 port 22 INFO: Connection established INFO: Remote version string: SSH-2.0-dropbear_0.52 INFO: Local version string: SSH-2.0-JSCH-0.1.45 INFO: CheckCiphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-ctr,arcfour,arcfour128,arcfour256 INFO: CheckKexes: diffie-hellman-group14-sha1 INFO: SSH_MSG_KEXINIT sent INFO: SSH_MSG_KEXINIT received INFO: kex: server->client aes128-ctr hmac-md5 none INFO: kex: client->server aes128-ctr hmac-md5 none INFO: SSH_MSG_KEXDH_INIT sent INFO: expecting SSH_MSG_KEXDH_REPLY INFO: ssh_rsa_verify: signature true WARN: Permanently added '141.20.23.223' (RSA) to the list of known hosts. INFO: SSH_MSG_NEWKEYS sent INFO: SSH_MSG_NEWKEYS received INFO: SSH_MSG_SERVICE_REQUEST sent INFO: SSH_MSG_SERVICE_ACCEPT received INFO: Authentications that can continue: publickey,keyboard-interactive,password INFO: Next authentication method: publickey INFO: Authentications that can continue: password INFO: Next authentication method: password INFO: Authentication succeeded (password). System.{in,out} will be forwarded to localhost:2006. DEBUG: waiting max. 5000 ms for channel reply ... DEBUG: packet received, type: 91 INFO: SSH_MSG_CHANNEL_OPEN_CONFIRMATION received, channel: 0 DEBUG: ... finished waiting for channel reply DEBUG: packet received, type: 94 INFO: SSH_MSG_CHANNEL_DATA received, channel: 0, len: 806 10.5.59.109,1353031,5242920,1000,1,0 10.5.58.253,1353098,5242951,68,2,0 10.7.205.153,1353337,5243052,52,2,0 10.7.205.151,1353009,5243307,48,2,0 10.5.59.150,1353089,5242959,64,2,0 10.7.205.149,1353051,5242914,41,2,0 10.5.59.93,1352996,5242923,18,2,0 10.5.59.159,1353106,5242965,54,2,0 10.5.70.8,1353149,5243096,49,2,0 10.5.70.54,1353164,5242965,52,2,0 10.5.59.151,1353092,5242969,36,2,0 10.5.70.9,1353033,5243145,56,2,0 10.5.58.251,1353129,5242940,1000,1,0 10.5.59.142,1352984,5242904,57,2,0 10.5.70.16,1353093,5242975,52,2,0 10.5.59.161,1353433,5243214,63,2,0 10.5.70.12,1353092,5242991,11,2,0 10.5.59.117,1353160,5242876,56,2,0 10.5.59.147,1353023,5242981,70,2,0 10.5.59.153,1353025,5242913,36,2,0 10.5.59.111,1353063,5242971,40,2,0 10.7.205.14,1353035,5242951,1000,1,0 10.5.59.163,1352742,5242930,31,2,0 DEBUG: packet received, type: 96 INFO: SSH_MSG_CHANNEL_EOF received, channel: 0 DEBUG: packet received, type: 97 INFO: SSH_MSG_CHANNEL_CLOSE received, channel: 0 |