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
