Re: [JSch-users] Problem with connections closing intermittently during use
Status: Alpha
Brought to you by:
ymnk
From: Antony R. <an...@ka...> - 2010-06-22 07:19:23
|
The first log you posted had this in it which is related to the issue I pointed you at: Jun 16 11:30:54 lightning sshd[2981]: Disconnecting: Received data for nonexistent channel 0. Poor synchronization in the last release of jsch sometimes causes data to be transmitted after a subchannel has been closed, and the server drops the connection. (Which is what invariably causes the above message from the ssh server). At a guess the second log looks like something in jsch closed a pipedinputstream (the log doesn't show what) whilst the server was still sending data to it, data arrived after it was closed and the internal error causes jsch to drop the whole connection. You could assume that it's most likely to be in the sftp subsystem in jsch, and add debug lines to all the calls to PipedInputStream.close() to work out which one and what called it (assuming that doesn't hide the bug). An alternative would be to modify ChannelSftp.java:181 to say: io.setInputStream(pis, true); which would probably solve the error you're seeing but maybe not the problems you're having. It looks like you've hit a completely difference lack of synchronization issue. If you like hitting things with hammers and singing 'la la la' you could bind the process with a single CPU thereby avoiding a lot of these issues. -Antony On Mon, Jun 21, 2010 at 7:53 PM, Bradley Wagner < bra...@ha...> wrote: > 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 < > bra...@ha...> 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 < >> 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 >> >> > > > -- > Hannon Hill - Put Us to the Test > bra...@ha... | http://www.hannonhill.com > > |