[Question] Disconnecting: Received data for nonexistent channel 0.

[yeonkyung-cho]

Hello,

Although I have been used jsch-0.1.54 and I changed jsch-0.2.12 this time, I get this error very often.
Dec 26 17:02:29 linux sshd[1676]: channel_by_id: 0: bad id: channel free
Dec 26 17:02:29 linux sshd[1676]: Disconnecting: Received data for nonexistent channel 0.

and similar issues has been reported to JSCH already, but as you know they did not answer.
https://sourceforge.net/p/jsch/mailman/jsch-users/thread/201004230201.LAA12294@jcraft.com
https://sourceforge.net/p/jsch/bugs/16/
https://sourceforge.net/p/jsch/bugs/48/

Client
12-07 15:52:26.143 935 10580 E JSchUtil: JSchException : Connection refused
12-07 15:52:26.143 935 10580 D JSchUtil: session is down
12-07 15:52:26.143 935 10580 W System.err: com.jcraft.jsch.JSchException: session is down
12-07 15:52:26.144 935 10580 W System.err: at com.jcraft.jsch.Session.openChannel(Session.java:861)
12-07 15:52:26.144 935 10580 W System.err: at com.lge.robot.util.JSchUtil.openChannelSftp(JSchUtil.java:561)
12-07 15:52:26.145 935 10580 W System.err: at com.lge.robot.navigation.update.NavigationUpdater$5.run(NavigationUpdater.java:525)
12-07 15:52:26.145 935 10580 W System.err: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
12-07 15:52:26.145 935 10580 W System.err: at java.util.concurrent.FutureTask.run(FutureTask.java:266)
12-07 15:52:26.145 935 10580 W System.err: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
12-07 15:52:26.146 935 10580 W System.err: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
12-07 15:52:26.146 935 10580 W System.err: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
12-07 15:52:26.156 935 10580 W System.err: at java.lang.Thread.run(Thread.java:919)

Server
normal operation
Jan 2 16:07:12 linux sshd[16181]: Starting session: command on pts/1 for ***** from ... port ***** id 0
Jan 2 16:07:12 linux sshd[16181]: debug3: mm_request_send entering: type 113
Jan 2 16:07:12 linux sshd[16181]: debug2: fd 3 setting TCP_NODELAY
Jan 2 16:07:12 linux sshd[16181]: debug3: ssh_packet_set_tos: set IP_TOS 0x10
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: rfd 10 isatty
Jan 2 16:07:12 linux sshd[16181]: debug2: fd 10 setting O_NONBLOCK
Jan 2 16:07:12 linux sshd[16181]: debug3: fd 8 is O_NONBLOCK
Jan 2 16:07:12 linux sshd[16188]: debug1: Setting controlling tty using TIOCSCTTY.
Jan 2 16:07:12 linux sshd[16188]: debug3: Copy environment: XDG_SESSION_ID=c154
Jan 2 16:07:12 linux sshd[16188]: debug3: Copy environment: XDG_RUNTIME_DIR=/run/user/1000
Jan 2 16:07:12 linux sshd[16181]: debug3: receive packet: type 96
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: rcvd eof
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: output open -> drain
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: obuf empty
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: close_write
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: output drain -> closed
Jan 2 16:07:12 linux sshd[16181]: debug2: notify_done: reading
Jan 2 16:07:12 linux sshd[16181]: debug1: Received SIGCHLD.
Jan 2 16:07:12 linux sshd[16181]: debug1: session_by_pid: pid 16188
Jan 2 16:07:12 linux sshd[16181]: debug1: session_exit_message: session 0 channel 0 pid 16188
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: request exit-status confirm 0
Jan 2 16:07:12 linux sshd[16181]: debug3: send packet: type 98
Jan 2 16:07:12 linux sshd[16181]: debug1: session_exit_message: release channel 0
Jan 2 16:07:12 linux sshd[16181]: debug3: mm_request_send entering: type 30
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: read<=0 rfd 10 len -1
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: read failed
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: close_read
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: input open -> drain
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: ibuf empty
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: send eof
Jan 2 16:07:12 linux sshd[16181]: debug3: send packet: type 96
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: input drain -> closed
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: send close
Jan 2 16:07:12 linux sshd[16181]: debug3: send packet: type 97
Jan 2 16:07:12 linux sshd[16181]: debug3: channel 0: will not send data after close
Jan 2 16:07:12 linux sshd[16181]: debug3: receive packet: type 97
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: rcvd close
Jan 2 16:07:12 linux sshd[16181]: debug3: channel 0: will not send data after close
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: is dead
Jan 2 16:07:12 linux sshd[16181]: debug2: channel 0: gc: notify user
Jan 2 16:07:12 linux sshd[16181]: debug1: session_by_channel: session 0 channel 0
Jan 2 16:07:12 linux sshd[16181]: debug1: session_close_by_channel: channel 0 child 0
Jan 2 16:07:12 linux sshd[16181]: Close session: user ***** from ... port ***** id 0

issue time
Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: output open -> closed
Dec 26 17:02:29 linux sshd[1676]: debug3: mm_request_send entering: type 30

Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: send close
Dec 26 17:02:29 linux sshd[1676]: debug3: send packet: type 97
Dec 26 17:02:29 linux sshd[1676]: debug3: channel 0: will not send data after close
Dec 26 17:02:29 linux sshd[1676]: debug2: notify_done: reading
Dec 26 17:02:29 linux sshd[1676]: debug3: channel 0: will not send data after close
Dec 26 17:02:29 linux sshd[1676]: debug3: receive packet: type 97
Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: rcvd close
Dec 26 17:02:29 linux sshd[1676]: debug3: channel 0: will not send data after close
Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: is dead
Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: gc: notify user
Dec 26 17:02:29 linux sshd[1676]: debug1: session_by_channel: session 0 channel 0
Dec 26 17:02:29 linux sshd[1676]: debug1: session_close_by_channel: channel 0 child 0
Dec 26 17:02:29 linux sshd[1676]: Close session: user ***** from ... port ***** id 0
Dec 26 17:02:29 linux sshd[1676]: debug3: session_unused: session id 0 unused
Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: gc: user detached
Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: is dead
Dec 26 17:02:29 linux sshd[1676]: debug2: channel 0: garbage collecting
Dec 26 17:02:29 linux sshd[1676]: debug1: channel 0: free: server-session, nchannels 1
Dec 26 17:02:29 linux sshd[1676]: channel_by_id: 0: bad id: channel free
Dec 26 17:02:29 linux sshd[1676]: Disconnecting: Received data for nonexistent channel 0.
Dec 26 17:02:29 linux sshd[1676]: debug3: send packet: type 1
Dec 26 17:02:29 linux sshd[1676]: debug1: do_cleanup
Dec 26 17:02:29 linux sshd[1676]: debug3: PAM: sshpam_thread_cleanup entering

I think this issue can occur OutputStream.close() and ChannelExec.disconnect() are called within very short time.

It seems possibly,

1. OutputStream.close() called eof(), and it sends to openssh SSH_MSG_CHANNEL_EOF in Channel.java. and also channel is not disconnect yet.
2. ChannelExec.disconnect() is called, and sends to openssh SSH_MSG_CHANNEL_CLOSE in Channel.java and then close the channel.
3. SSH_MSG_CHANNEL_EOF is arrived to closed channel.

and once this exception is received, Session is always closed.

and my suggest is eof() and close() should be protected by synchorized().

Could you let me know if there is any kind of this issue reported and consider this issue?

This is very seriously issue to us, so any supports would be very appreciate,

Best regards.