On Dec 21, 2007 10:21 PM, Jerome Lacoste <[EMAIL PROTECTED]> wrote: > Hei, > > we use jsch through commons-vfs. We've made some load tests to > investigate some issues. Our load test transfers 10 files > simultaneously (using so many threads), in an infinite loop.
[...] > we hope to be able to improve the error handling as well as reduce the > risks for this "too many open files" issue to occur. Hi again, Ive troubleshooted further using a Linux server (openssh 4.6p1, Ubunut 7.10). I can see using netstat that connections don't seem to be closed properly on the server side. Their number keep increasing (and stay as ESTABLISHED) until I close my program or until I reach a limit and the session is disconnected as explained in the mail before. It was my understanding that the ssh server should close those connections after receiving SSH_MSG_CHANNEL_CLOSE packet from jsch. The Channel#close() method is correctly closed on the client side and I see: Dec 24 12:43:05 expresso2 sshd[19315]: debug1: server_input_channel_open: ctype session rchan 54 win 1048576 max 16384 Dec 24 12:43:05 expresso2 sshd[19315]: debug1: input_session_request Dec 24 12:43:05 expresso2 sshd[19315]: debug1: channel 0: new [server-session] Dec 24 12:43:05 expresso2 sshd[19315]: debug1: session_new: session 0 Dec 24 12:43:05 expresso2 sshd[19315]: debug1: session_open: channel 0 Dec 24 12:43:05 expresso2 sshd[19315]: debug1: session_open: session 0: link with channel 0 Dec 24 12:43:05 expresso2 sshd[19315]: debug1: server_input_channel_open: confirm session Dec 24 12:43:05 expresso2 sshd[19315]: debug1: server_input_channel_req: channel 0 request subsystem reply 1 Dec 24 12:43:05 expresso2 sshd[19315]: debug1: session_by_channel: session 0 channel 0 Dec 24 12:43:05 expresso2 sshd[19315]: debug1: session_input_channel_req: session 0 req subsystem Dec 24 12:43:05 expresso2 sshd[19315]: subsystem request for sftp Dec 24 12:43:05 expresso2 sshd[19315]: debug1: subsystem: exec() /usr/lib/openssh/sftp-server Dec 24 12:43:05 expresso2 sshd[19387]: debug3: Normalising mapped IPv4 in IPv6 address Dec 24 12:43:05 expresso2 sshd[19387]: debug3: Copy environment: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11:/usr/games Dec 24 12:43:05 expresso2 sshd[19387]: debug3: Copy environment: LANG=en_US.UTF-8 Dec 24 12:43:05 expresso2 sshd[19387]: debug3: Copy environment: LANGUAGE=en_US:en Dec 24 12:43:05 expresso2 sshd[19387]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1 Dec 24 12:43:05 expresso2 sshd[19315]: debug2: fd 8 setting O_NONBLOCK Dec 24 12:43:05 expresso2 sshd[19315]: debug3: fd 8 is O_NONBLOCK Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: rcvd close Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: output open -> drain Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: close_read Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: input open -> closed Dec 24 12:43:06 expresso2 sshd[19315]: debug3: channel 0: will not send data after close Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: obuf empty Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: close_write Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: output drain -> closed Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: almost dead Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: gc: notify user Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_by_channel: session 0 channel 0 Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_close_by_channel: channel 0 child 19387 Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_close_by_channel: channel 0: has child Dec 24 12:43:06 expresso2 sshd[19315]: debug2: notify_done: reading Dec 24 12:43:06 expresso2 sshd[19315]: debug1: Received SIGCHLD. Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_by_pid: pid 19387 Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_exit_message: session 0 channel 0 pid 19387 Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: request exit-status confirm 0 Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_exit_message: release channel 0 Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: send close Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: is dead Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: gc: notify user Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_by_channel: session 0 channel 0 Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_close_by_channel: channel 0 child 0 Dec 24 12:43:06 expresso2 sshd[19315]: debug1: session_close: session 0 pid 0 Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: gc: user detached Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: is dead Dec 24 12:43:06 expresso2 sshd[19315]: debug2: channel 0: garbage collecting Dec 24 12:43:06 expresso2 sshd[19315]: debug1: channel 0: free: server-session, nchannels 1 Dec 24 12:43:06 expresso2 sshd[19315]: debug3: channel 0: status: The following connections are open:\r\n #0 server-session (t4 r54 i3/0 o3/0 fd 8/8 cfd -1)\r\n Dec 24 12:43:06 expresso2 sshd[19315]: debug3: channel 0: close_fds r 8 w 8 e -1 c -1 in the openssh server logs when transferring a single file. The line: channel 0: rcvd close makes me think that the close packet is correctly received. I've looked into how sftp (from Cygwin) works and it reproduces the same sshd logs on the server. It also produces an increased amount of connections. Is that an expected behavior ? Should I just close my session and forget about trying to reuse the same session while opening and closing channels ? Cheers, Jerome ------------------------------------------------------------------------- This SF.net email is sponsored by: Microsoft Defy all challenges. Microsoft(R) Visual Studio 2005. http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/ _______________________________________________ JSch-users mailing list JSch-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/jsch-users
