SSH connection hanging on logout

[John Bowman]

> Date: Thu, 17 May 2001 23:38:23 +0200
> From: Markus Friedl <markus.friedl at informatik.uni-erlangen.de>
> Cc: openssh-unix-dev at mindrot.org
> Content-Type: text/plain; charset=us-ascii
> Content-Disposition: inline
> User-Agent: Mutt/1.2.5i
> 
> On Thu, May 17, 2001 at 03:35:18PM -0000, John Bowman wrote:
> > > you should see something like this on the sshd side:
> > > 
> > > 	debug3: channel 0: channel data: 16384
> > > 	debug3: channel 0: read rfd 10 len 16384
> > > 	debug3: channel 0: channel data: 15907
> > > 	debug2: channel 0: rcvd adjust 16861
> > > 	debug3: channel 0: channel data: 477
> > > 	debug3: channel 0: read rfd 10 len 16384
> > > 	debug3: channel 0: channel data: 16384
> > > 	debug2: channel 0: rcvd adjust 65536
> > > 	debug3: channel 0: read rfd 10 len 16384
> > > 	debug3: channel 0: channel data: 16384
> > > 	debug3: channel 0: read rfd 10 len 16384
> > > 	debug3: channel 0: channel data: 16384
> > > 	debug1: Received SIGCHLD.
> > > ^^ shell dies
> > > 	debug1: session_by_pid: pid 29873
> > > 	debug1: session_exit_message: session 0 channel 0 pid 29873
> > > 	debug1: session_exit_message: release channel 0
> > > 	debug1: channel 0: write failed
> > > 	debug1: channel 0: output open -> closed
> > > 	debug1: channel 0: close_write
> > > 	debug1: session_free: session 0 pid 29873
> > > 	debug3: channel 0: read rfd 10 len 16384
> > > ^^ more reads from the shell.
> > > 
> > > if you shutdown at the SIGCHLD, you can no longer read
> > > at this point!
> > > 
> > > 	debug2: channel 0: read 84 from efd 12
> > > 	debug3: channel 0: channel data: 16384
> > > 	debug2: channel 0: rwin 16384 elen 84 euse 1
> > > 	debug2: channel 0: sent ext data 84
> > > 	debug1: channel 0: read<=0 rfd 10 len 0
> > > 	debug1: channel 0: read failed
> > > 	debug1: channel 0: input open -> drain
> > > 	debug1: channel 0: close_read
> > > 	debug1: channel 0: input: no drain shortcut
> > > 	debug1: channel 0: ibuf empty
> > > 	debug1: channel 0: input drain -> closed
> > > 	debug1: channel 0: send eof
> > > 
> > 
> > Here is what I get with the latest patch and your debug patch
> > installed. There is a SIGCHLD, but only after the very beginning:
> > 
> > ssh -v -v -v localhost dd if=/bin/bash bs=65536 count=2 | ( sleep 10 ; md5sum )
> 
> i need the server side LOG message!
> 
Sorry, I realized after sending it that I forgot to include the server side
output and I didn't get a chance to get back to it until now.

Here is the debugging output, with my latest patch (which fixes the -N
problem you pointed out today) and your debug patch applied to 2.9p1:


ssh -v -v -v localhost dd if=/bin/bash bs=65536 count=2 | ( sleep 10 ; md5sum )

SSH:
debug2: channel 0: written 477 to efd 6
debug2: channel 0: rcvd ext data 27
debug1: Received SIGCHLD.
debug2: channel 0: written 27 to efd 6
debug2: channel 0: window 32264 sent adjust 4600 (obuf 28672)
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug2: channel 0: window 0 sent adjust 4096 (obuf 61440)
debug2: channel 0: window 4096 sent adjust 4096 (obuf 57344)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 16384 sent adjust 4096 (obuf 45056)
debug2: channel 0: window 20480 sent adjust 4096 (obuf 40960)
debug2: channel 0: window 24576 sent adjust 4096 (obuf 36864)
debug2: channel 0: window 28672 sent adjust 4096 (obuf 32768)
debug2: channel 0: window 20480 sent adjust 36864 (obuf 8192)
debug2: channel 0: rcvd ext data 31
2+0 records in
2+0 records out
debug2: channel 0: written 31 to efd 6
debug2: channel 0: window 24545 sent adjust 28703 (obuf 12288)
debug1: channel 0: rcvd eof
debug1: channel 0: output open -> drain
debug1: channel 0: rcvd close
debug1: channel 0: input open -> closed
debug1: channel 0: close_read
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug1: channel 0: obuf empty
debug1: channel 0: output drain -> closed
debug1: channel 0: close_write
debug1: channel 0: send close
debug1: channel 0: is dead
debug1: channel_free: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i8/0 o128/0 fd -1/-1)

debug1: channel_free: channel 0: dettaching channel user
debug1: Transferred: stdin 0, stdout 0, stderr 0 bytes in 7.3 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0
86d34e869a31df51922ad2bb9bd202bc  -

dd if=/bin/bash bs=65536 count=2 | ( sleep 10 ; md5sum )
2+0 records in
2+0 records out
86d34e869a31df51922ad2bb9bd202bc  -

SSHD:
debug1: Entering interactive session for SSH2.
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 65536 max 32768
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: init
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 channel 0 request x11-req reply 0
debug1: Received request for X11 forwarding with auth spoofing.
debug1: x11_create_display_inet: Socket family 10 not supported
debug1: fd 3 setting O_NONBLOCK
debug1: fd 3 IS O_NONBLOCK
debug1: channel 1: new [X11 inet listener]
debug1: temporarily_use_uid: 9062/2501 (e=0)
debug1: restore_uid
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 channel 0 request exec reply 0
debug1: fd 8 setting O_NONBLOCK
debug1: fd 8 IS O_NONBLOCK
debug1: fd 10 setting O_NONBLOCK
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 9448
debug1: session_exit_message: session 0 channel 0 pid 9448
debug1: session_exit_message: release channel 0
debug1: channel 0: write failed
debug1: channel 0: output open -> closed
debug1: channel 0: close_write
debug1: channel 0: close_read
debug1: session_free: session 0 pid 9448
debug1: channel 0: read<=0 rfd 8 len 0
debug1: channel 0: read failed
debug1: channel 0: input open -> drain
debug1: channel 0: close_read
debug1: channel 0: input: no drain shortcut
debug1: channel 0: ibuf empty
debug1: channel 0: input drain -> closed
debug1: channel 0: send eof
debug1: channel 0: send close
debug1: channel 0: rcvd close
debug1: channel 0: is dead
debug1: channel_free: channel 0: status: The following connections are open:
  #0 server-session (t4 r0 i8/0 o128/0 fd 8/8)

Connection closed by remote host.
debug1: channel_free: channel 1: status: The following connections are open:

debug1: xauthfile_cleanup_proc called
Closing connection to 127.0.0.1

==============================================================================

ssh -v -v -v localhost dd if=/bin/bash bs=65536 count=10 | ( sleep 5 ; md5sum )

SSH:
debug2: channel 0: written 477 to efd 6
debug2: channel 0: rcvd ext data 27
debug1: Received SIGCHLD.
debug2: channel 0: written 27 to efd 6
debug2: channel 0: window 32264 sent adjust 4600 (obuf 28672)
debug2: channel 0: window 0 sent adjust 4096 (obuf 61440)
debug2: channel 0: window 4096 sent adjust 4096 (obuf 57344)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 16384 sent adjust 4096 (obuf 45056)
debug2: channel 0: window 20480 sent adjust 4096 (obuf 40960)
debug2: channel 0: window 24576 sent adjust 4096 (obuf 36864)
debug2: channel 0: window 28672 sent adjust 4096 (obuf 32768)
debug2: channel 0: window 20480 sent adjust 36864 (obuf 8192)
debug2: channel 0: window 24576 sent adjust 20480 (obuf 20480)
debug2: channel 0: window 28672 sent adjust 8192 (obuf 28672)
debug2: channel 0: window 20480 sent adjust 32768 (obuf 12288)
debug2: channel 0: window 20480 sent adjust 32768 (obuf 12288)
debug2: channel 0: window 20480 sent adjust 32768 (obuf 12288)
debug2: channel 0: window 20480 sent adjust 32768 (obuf 12288)
debug2: channel 0: window 20480 sent adjust 32768 (obuf 12288)
debug2: channel 0: window 21136 sent adjust 32768 (obuf 11632)
debug2: channel 0: rcvd ext data 15
4+1 records in
debug2: channel 0: written 15 to efd 6
debug2: channel 0: rcvd ext data 16
4+1 records out
debug2: channel 0: written 16 to efd 6
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: channel 0: rcvd eof
debug1: channel 0: output open -> drain
debug1: channel 0: rcvd close
debug1: channel 0: input open -> closed
debug1: channel 0: close_read
debug2: channel 0: no data after CLOSE
debug1: channel 0: obuf empty
debug1: channel 0: output drain -> closed
debug1: channel 0: close_write
debug1: channel 0: send close
debug1: channel 0: is dead
debug1: channel_free: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i8/0 o128/0 fd -1/-1)

debug1: channel_free: channel 0: dettaching channel user
debug1: Transferred: stdin 0, stdout 0, stderr 0 bytes in 2.8 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0
6c80ab2560a5f7b9b778b5498a93ece8  -

dd if=/bin/bash bs=65536 count=10 | ( sleep 5 ; md5sum )
4+1 records in
4+1 records out
6c80ab2560a5f7b9b778b5498a93ece8  -

SSHD:
debug1: Entering interactive session for SSH2.
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 65536 max 32768
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: init
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 channel 0 request x11-req reply 0
debug1: Received request for X11 forwarding with auth spoofing.
debug1: x11_create_display_inet: Socket family 10 not supported
debug1: fd 3 setting O_NONBLOCK
debug1: fd 3 IS O_NONBLOCK
debug1: channel 1: new [X11 inet listener]
debug1: temporarily_use_uid: 9062/2501 (e=0)
debug1: restore_uid
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 channel 0 request exec reply 0
debug1: fd 8 setting O_NONBLOCK
debug1: fd 8 IS O_NONBLOCK
debug1: fd 10 setting O_NONBLOCK
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 9462
debug1: session_exit_message: session 0 channel 0 pid 9462
debug1: session_exit_message: release channel 0
debug1: channel 0: write failed
debug1: channel 0: output open -> closed
debug1: channel 0: close_write
debug1: channel 0: close_read
debug1: session_free: session 0 pid 9462
debug1: channel 0: read<=0 rfd 8 len 0
debug1: channel 0: read failed
debug1: channel 0: input open -> drain
debug1: channel 0: close_read
debug1: channel 0: input: no drain shortcut
debug1: channel 0: ibuf empty
debug1: channel 0: input drain -> closed
debug1: channel 0: send eof
debug1: channel 0: send close
debug1: channel 0: rcvd close
debug1: channel 0: is dead
debug1: channel_free: channel 0: status: The following connections are open:
  #0 server-session (t4 r0 i8/0 o128/0 fd 8/8)

Connection closed by remote host.
debug1: channel_free: channel 1: status: The following connections are open:

debug1: xauthfile_cleanup_proc called
Closing connection to 127.0.0.1

==============================================================================

ssh -v -v -v localhost dd if=/bin/bash bs=655360 count=2 | ( sleep 10 ; md5sum )

SSH:
debug2: channel 0: written 477 to efd 6
debug2: channel 0: rcvd ext data 27
debug1: Received SIGCHLD.
debug2: channel 0: written 27 to efd 6
debug2: channel 0: window 32264 sent adjust 4600 (obuf 28672)
debug2: channel 0: window 0 sent adjust 4096 (obuf 61440)
debug2: channel 0: window 4096 sent adjust 4096 (obuf 57344)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 16384 sent adjust 4096 (obuf 45056)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 16384 sent adjust 4096 (obuf 45056)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 16384 sent adjust 4096 (obuf 45056)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49152)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53248)
debug2: channel 0: rcvd ext data 31
debug2: channel 0: window 8161 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49121)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug2: channel 0: window 8161 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49121)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug2: channel 0: window 8161 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49121)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug2: channel 0: window 8161 sent adjust 4096 (obuf 53248)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug2: channel 0: window 12288 sent adjust 4096 (obuf 49121)
debug2: channel 0: window 8192 sent adjust 4096 (obuf 53217)
debug1: channel 0: rcvd eof
debug1: channel 0: output open -> drain
debug1: channel 0: rcvd close
debug1: channel 0: input open -> closed
debug1: channel 0: close_read
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
0+1 records in
0+1 records out
debug2: channel 0: written 31 to efd 6
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug2: channel 0: no data after CLOSE
debug1: channel 0: obuf empty
debug1: channel 0: output drain -> closed
debug1: channel 0: close_write
debug1: channel 0: send close
debug1: channel 0: is dead
debug1: channel_free: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i8/0 o128/0 fd -1/-1)

debug1: channel_free: channel 0: dettaching channel user
debug1: Transferred: stdin 0, stdout 0, stderr 0 bytes in 8.3 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0
6c80ab2560a5f7b9b778b5498a93ece8  -

dd if=/bin/bash bs=655360 count=2 | ( sleep 10 ; md5sum )
0+1 records in
0+1 records out
6c80ab2560a5f7b9b778b5498a93ece8  -

SSHD:
debug1: Entering interactive session for SSH2.
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 65536 max 32768
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: init
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 channel 0 request x11-req reply 0
debug1: Received request for X11 forwarding with auth spoofing.
debug1: x11_create_display_inet: Socket family 10 not supported
debug1: fd 3 setting O_NONBLOCK
debug1: fd 3 IS O_NONBLOCK
debug1: channel 1: new [X11 inet listener]
debug1: temporarily_use_uid: 9062/2501 (e=0)
debug1: restore_uid
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 channel 0 request exec reply 0
debug1: fd 8 setting O_NONBLOCK
debug1: fd 8 IS O_NONBLOCK
debug1: fd 10 setting O_NONBLOCK
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 9496
debug1: session_exit_message: session 0 channel 0 pid 9496
debug1: session_exit_message: release channel 0
debug1: channel 0: write failed
debug1: channel 0: output open -> closed
debug1: channel 0: close_write
debug1: channel 0: close_read
debug1: session_free: session 0 pid 9496
debug1: channel 0: read<=0 rfd 8 len 0
debug1: channel 0: read failed
debug1: channel 0: input open -> drain
debug1: channel 0: close_read
debug1: channel 0: input: no drain shortcut
debug1: channel 0: ibuf empty
debug1: channel 0: input drain -> closed
debug1: channel 0: send eof
debug1: channel 0: send close
debug1: channel 0: rcvd close
debug1: channel 0: is dead
debug1: channel_free: channel 0: status: The following connections are open:
  #0 server-session (t4 r0 i8/0 o128/0 fd 8/8)

Connection closed by remote host.
debug1: channel_free: channel 1: status: The following connections are open:

debug1: xauthfile_cleanup_proc called
Closing connection to 127.0.0.1