Testing if this is making it to the list. I couldn't find my latest post in the list archives: http://www.mail-archive.com/[email protected]/
On Tue, Jun 22, 2010 at 10:34 AM, Bradley Wagner < [email protected]> wrote: > With regards to the second error: we agree that there is a synchronization > issue with the PipedInputStream but we don't think it's because the stream > is being explicitly closed as we're not seeing that method invoked. > > We have 2 threads using the same ChannelSFTP and sequentially issuing > commands. The first thread makes a few SFTP calls and becomes the "reader" > end of the associated PipedInputStream used to communicate the response from > the Session to the Channel. At this point, the first thread dies, but the > second thread still has a reference to the same ChannelSFTP/Session. When > the second thread sends an "ls" command to the server, if the Session thread > gets a response from the server and starts writing to the PipedOutputStream > before the second thread starts blocking on a read call to the > PipedInputStream (ChannelSFTP._stat() calls header() line 1732) where it > sets itself as the read end of the PipedInputStream, then the last reader > thread of the PipedInputStream is the first thread which is now dead in turn > causing the "read end dead" exception. > > This happens much more frequently when the SFTP server and application > (which is managing the threads) are running on the same machine likely due > to the fact that the SFTP commands receive a response from the server more > quickly. The error happens rarely when the SFTP server is not on the same > machine as the application probably due to network latency. > > So, my question is, should we be shutting down the SFTP client between > thread executions? or is there some way to prevent this scenario from > happening without having to incur the overhead cost of reinitializing the > client for every thread that wants to use it? > > We think the fix is to have the thread with the Channel in it set itself as > the reader of the PipedInputStream *before* it calls sendSTAT(path) > (ChannelSFTP._stat() line 1729) to guarantee that there is no race condition > in which the sendSTAT command will result in the Session writing the > response to the OutputStream (Session.run() line 1246) before the > ChannelSFTP has had a chance to block in line 1732. > > Thanks, > Bradley > > On Tue, Jun 22, 2010 at 2:55 AM, Antony Riley <[email protected]>wrote: > >> 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 < >> [email protected]> 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 < >>> [email protected]> 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 < >>>> [email protected]> 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 >>>>> <[email protected]>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 < >>>>>> [email protected]> 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 >>>>>>> >>>>>>
------------------------------------------------------------------------------ This SF.net email is sponsored by Make an app they can't live without Enter the BlackBerry Developer Challenge http://p.sf.net/sfu/RIM-dev2dev
_______________________________________________ JSch-users mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/jsch-users
