It appears that the problem we're running into is not a problem connecting
to the SFTP server but rather a problem in the communication between the
Session thread and the thread invoking commands on the session. Basically,
we've tracked this down to an error PipedInputStream when the read end of
the Pipe (the thread invoking Jsch) is dead. Though, we're not sure how this
happened or how to avoid it. It appears to be somewhat machine specific
pointing to a either a JVM-specific issue with Jsch or well-time race
condition.

Any other reports of the piped streams between the Session thread and the
calling thread having these types of problems?

On Fri, Jun 18, 2010 at 5:43 PM, Bradley Wagner <
bradley.wag...@hannonhill.com> wrote:

> I've enabled SSH and SFTP subsystem server logging and added some
> additional logging to com.jcraft.jsch.Session.run() near line 1250 in the
> try/catch block that is calling channel.write() to actually print the
> exception I'm getting. Below I've included the SFTP logging, method calls,
> and except stacks in order after carefully debugging. What does "Read end
> dead" mean when the channel.write() errors out below?
>
> Jun 18 16:29:24 cascadetest sftp-server[28715]: debug3: request 11: stat
> Jun 18 16:29:24 cascadetest sftp-server[28715]: stat name
> "/var/www/cascade/sqlserver08test/pictures"
>  Jun 18 16:29:24 cascadetest sftp-server[28715]: debug1: request 11: sent
> attrib have 0xf
>
> *Exception thrown from channel.write() in Session.run() thread*
> Read end dead
> java.io.IOException: Read end dead
>  at java.io.PipedInputStream.checkStateForReceive(Unknown Source)
> at java.io.PipedInputStream.receive(Unknown Source)
>  at java.io.PipedOutputStream.write(Unknown Source)
> at com.jcraft.jsch.IO.put(IO.java:64)
>  at com.jcraft.jsch.Channel.write(Channel.java:394)
> at com.jcraft.jsch.Session.run(Session.java:1246)
>  at java.lang.Thread.run(Unknown Source)
>
> *Session.run() calls channel.disconnect*
>
> SSH/SFTP server closes the connection after the library calls disconnect:
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_by_channel:
> session 0 channel 0
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_close_by_channel:
> channel 0 child 28715
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_close_by_channel:
> channel 0: has child
> Jun 18 16:30:06 cascadetest sftp-server[28715]: debug1: read eof
> Jun 18 16:30:06 cascadetest sftp-server[28715]: session closed for local
> user hannonhill from [127.0.1.1]
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: Received SIGCHLD.
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_by_pid: pid 28715
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_exit_message:
> session 0 channel 0 pid 28715
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_exit_message:
> release channel 0
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_by_channel:
> session 0 channel 0
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_close_by_channel:
> channel 0 child 0
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: session_close: session 0
> pid 0
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: channel 0: free:
> server-session, nchannels 1
> Jun 18 16:30:06 cascadetest sshd[28713]: Connection closed by 127.0.1.1
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: do_cleanup
> Jun 18 16:30:06 cascadetest sshd[28713]: debug1: PAM: cleanup
> Jun 18 16:30:06 cascadetest sshd[28713]: pam_unix(sshd:session): session
> closed for user hannonhill
> Jun 18 16:30:06 cascadetest sshd[28713]: Closing connection to 127.0.1.1
>
> On Thu, Jun 17, 2010 at 11:33 AM, Bradley Wagner <
> bradley.wag...@hannonhill.com> wrote:
>
>> I tried the linked-to 0.1.43-rc1 build.
>>
>> I'm still having repeated Pipe Closed errors. I'm publishing to a
>> localhost SFTP server (Ubuntu - SSH-2.0-OpenSSH_4.7p1 Debian-8ubuntu1.2).
>>
>> What's weird is that I'm closing the connection after getting one of the
>> Pipe Closed errors, reopening it and finding that I'm still getting Pipe
>> Closed errors. Is it possible that the server is actually giving me the same
>> connection?
>>
>> On Thu, Jun 17, 2010 at 2:10 AM, Antony Riley <ant...@karmasphere.com>wrote:
>>
>>> It's come up before on the list, the last time I remember seeing it is:
>>>
>>>
>>> http://sourceforge.net/mailarchive/forum.php?thread_name=201004230201.LAA12294%40jcraft.com&forum_name=jsch-users
>>>
>>> -Antony
>>>
>>>
>>> On Wed, Jun 16, 2010 at 6:45 PM, Bradley Wagner <
>>> bradley.wag...@hannonhill.com> wrote:
>>>
>>>> I'm using the Jsch library to call a variety of SFTP commands: ls, put,
>>>> mkdir against an OpenSSH server (SSH-2.0-OpenSSH_5.2) on OS X.
>>>>
>>>> I keep a session open for a while and sometimes the session closes while
>>>> executing the "ls" command and I get the following stack trace:
>>>>
>>>> 2010-06-16 11:41:41,157 ERROR [SFTPShuttle] : Error occurred when
>>>> invoking 'ls' command, error code:
>>>>
>>>> 4:
>>>>
>>>> at com.jcraft.jsch.ChannelSftp._stat(ChannelSftp.java:1751)
>>>>
>>>> at com.jcraft.jsch.ChannelSftp._stat(ChannelSftp.java:1758)
>>>>
>>>> at com.jcraft.jsch.ChannelSftp.ls(ChannelSftp.java:1196)
>>>>
>>>> at
>>>> com.hannonhill.cascade.model.publish.transmit.SFTPShuttle.mkdirIfNecessary(
>>>> SFTPShuttle.java:345)
>>>>
>>>> at com.hannonhill.cascade.model.publish.transmit.SFTPShuttle.sendFile(
>>>> SFTPShuttle.java:96)
>>>>
>>>>         ....
>>>>
>>>> Caused by: java.io.IOException: inputstream is closed
>>>>
>>>> at com.jcraft.jsch.ChannelSftp.fill(ChannelSftp.java:2327)
>>>>
>>>> at com.jcraft.jsch.ChannelSftp.header(ChannelSftp.java:2351)
>>>>
>>>> at com.jcraft.jsch.ChannelSftp._stat(ChannelSftp.java:1732)
>>>>
>>>> ... 16 more
>>>>
>>>> 2010-06-16 11:42:49,439 ERROR [TransmitCallbackImpl] : Shuttle reported
>>>> error: Error occurred during SFTP transport: java.io.IOException: Pipe
>>>> closed
>>>>
>>>>
>>>> I've enabled DEBUG3 logging level in sshd and got the following logging
>>>> around the time of this error. Any idea what could be causing the 
>>>> connection
>>>> to close without me intentionally closing it? This happens intermittently.
>>>>
>>>>
>>>> Jun 16 11:30:44 lightning sshd[2981]: debug2: channel 0: window 1990643
>>>> sent adjust 106509
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: rcvd close
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: output open ->
>>>> drain
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: close_read
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: input open ->
>>>> closed
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug3: channel 0: will not send
>>>> data after close
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: obuf empty
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: close_write
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: output drain ->
>>>> closed
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: almost dead
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: gc: notify user
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_by_channel:
>>>> session 0 channel 0
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_close_by_channel:
>>>> channel 0 child 2982
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_close_by_channel:
>>>> channel 0: has child
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: notify_done: reading
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: Received SIGCHLD.
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_by_pid: pid 2982
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_exit_message:
>>>> session 0 channel 0 pid 2982
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: request
>>>> exit-status confirm 0
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_exit_message:
>>>> release channel 0
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: send close
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: is dead
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: gc: notify user
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_by_channel:
>>>> session 0 channel 0
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_close_by_channel:
>>>> channel 0 child 0
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: session_close: session 0
>>>> pid 0
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug3: session_unused: session id
>>>> 0 unused
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: gc: user
>>>> detached
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: is dead
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug2: channel 0: garbage
>>>> collecting
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: channel 0: free:
>>>> server-session, nchannels 1
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug3: channel 0: status: The
>>>> following connections are open:\r\n  #0 server-session (t4 r24 i3/0 o3/0 fd
>>>> -1/-1 cfd -1)\r\n
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug3: channel 0: close_fds r -1
>>>> w -1 e -1 c -1
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: channel_by_id: 0: bad id: channel
>>>> free
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: Disconnecting: Received data for
>>>> nonexistent channel 0.
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug1: do_cleanup
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2981]: debug3: PAM: sshpam_thread_cleanup
>>>> entering
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2977]: debug1: do_cleanup
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2977]: debug1: PAM: cleanup
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2977]: debug1: PAM: deleting credentials
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2977]: debug1: PAM: closing session
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2977]: debug3: PAM: sshpam_thread_cleanup
>>>> entering
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2977]: debug1: audit_event: unhandled
>>>> event 12
>>>>
>>>> Jun 16 11:30:54 lightning com.apple.SecurityServer[23]: Session 0x26f5a9
>>>> dead
>>>>
>>>> Jun 16 11:30:54 lightning com.apple.SecurityServer[23]: Killing auth
>>>> hosts
>>>>
>>>> Jun 16 11:30:54 lightning com.apple.SecurityServer[23]: Session 0x26f5a9
>>>> destroyed
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2996]: debug1: inetd sockets after
>>>> dupping: 3, 4
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2996]: debug3: BSM audit: connection from
>>>> 127.0.0.1 port 54659
>>>>
>>>> Jun 16 11:30:54 lightning sshd[2996]: debug3: BSM audit: iptype 4
>>>> machine ID 0100007f 00000000 00000000 00000000
>>>>
>>>>
>>>>
>>>> ------------------------------------------------------------------------------
>>>> ThinkGeek and WIRED's GeekDad team up for the Ultimate
>>>> GeekDad Father's Day Giveaway. ONE MASSIVE PRIZE to the
>>>> lucky parental unit.  See the prize list and enter to win:
>>>> http://p.sf.net/sfu/thinkgeek-promo
>>>> _______________________________________________
>>>> JSch-users mailing list
>>>> JSch-users@lists.sourceforge.net
>>>> https://lists.sourceforge.net/lists/listinfo/jsch-users
>>>>
>>>>
>>>
>>>
>>> ------------------------------------------------------------------------------
>>> ThinkGeek and WIRED's GeekDad team up for the Ultimate
>>> GeekDad Father's Day Giveaway. ONE MASSIVE PRIZE to the
>>> lucky parental unit.  See the prize list and enter to win:
>>> http://p.sf.net/sfu/thinkgeek-promo
>>> _______________________________________________
>>> JSch-users mailing list
>>> JSch-users@lists.sourceforge.net
>>> https://lists.sourceforge.net/lists/listinfo/jsch-users
>>>
>>>
>>
>>
>> --
>> Hannon Hill - Put Us to the Test
>> bradley.wag...@hannonhill.com | http://www.hannonhill.com
>>
>>
>
>
> --
> Hannon Hill - Put Us to the Test
> bradley.wag...@hannonhill.com | http://www.hannonhill.com
>
>


-- 
Hannon Hill - Put Us to the Test
bradley.wag...@hannonhill.com | http://www.hannonhill.com
------------------------------------------------------------------------------
ThinkGeek and WIRED's GeekDad team up for the Ultimate 
GeekDad Father's Day Giveaway. ONE MASSIVE PRIZE to the 
lucky parental unit.  See the prize list and enter to win: 
http://p.sf.net/sfu/thinkgeek-promo
_______________________________________________
JSch-users mailing list
JSch-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jsch-users

Reply via email to