SSH connection hanging on logout

[John Bowman]

> > Under linux there is no data corruption and the checksums match:
> > 
> > [wizard: ~] ssh localhost dd if=/bin/bash bs=65536 count=2 | ( sleep 10 ; md5sum )
> > 2+0 records in
> > 2+0 records out
> > 86d34e869a31df51922ad2bb9bd202bc  -
> > [wizard: ~] dd if=/bin/bash bs=65536 count=2 | ( sleep 10 ; md5sum )
> > 2+0 records in
> > 2+0 records out
> > 86d34e869a31df51922ad2bb9bd202bc  -
> 
> with my debugging patch,
> 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 )
...
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
debug2: channel 0: window 24545 sent adjust 28672 (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
debug2: channel 0: active efd: 6 len 31 type write
2+0 records in
2+0 records out
debug2: channel 0: written 31 to efd 6
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 6.1 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0
86d34e869a31df51922ad2bb9bd202bc  -


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




With 10 counts and a short sleep it looks like this:

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

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 28672 (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 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 4.5 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0
6c80ab2560a5f7b9b778b5498a93ece8  -

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


Looks ok to me.

-- John Bowman

University of Alberta
http://www.math.ualberta.ca/~bowman