Re: [JSch-users] Problem with connections closing intermittently during use

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

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 <
bra...@ha...> 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 <an...@ka...>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 <
>> bra...@ha...> 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
>>> JSc...@li...
>>> 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
>> JSc...@li...
>> https://lists.sourceforge.net/lists/listinfo/jsch-users
>>
>>
>
>
> --
> Hannon Hill - Put Us to the Test
> bra...@ha... | http://www.hannonhill.com
>
>

-- 
Hannon Hill - Put Us to the Test
bra...@ha... | http://www.hannonhill.com