Bug 179

Summary: sshd sends channel data after sending EOF
Product: Portable OpenSSH Reporter: denis bider <bugzilla-mindrot-org>
Component: sshdAssignee: Markus Friedl <markus>
Status: CLOSED FIXED    
Severity: normal    
Priority: P1    
Version: -current   
Hardware: All   
OS: All   
URL: http://www.denisbider.com
Attachments:
Description Flags
possible fix
none
another patch none

Description denis bider 2002-03-22 11:20:00 AEDT 
I think this problem has 'major' severity because it causes sshd to violate the 
SSH2 protocol specification in such a way that the connection will immediately 
be terminated by most clients.

There appears to be a semi-deterministic bug in sshd 3.1p1 (tested on SuSE 
Linux) which in certain conditions usually causes sshd to send data on a 
channel after it has already sent EOF, but before it has sent a channel close 
packet. The bug has been observed as follows:

(1) client connects and authenticates
(2) client sends exec request for a program that does not exist
(3) client sends EOF
(4) server sends EOF
(5) server sends extended data after EOF has already been sent

An sshd debug log from one such attempt is as follows:

Server listening on 0.0.0.0 port 22.
debug1: Server will not fork when running in debugging mode.
Connection from 10.1.1.2 port 2283
debug1: Client protocol version 2.0; client software version 1.22 sshlib: 
SshMultiExec 1.1
debug1: no match: 1.22 sshlib: SshMultiExec 1.1
Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_3.1p1
debug1: list_hostkey_types: ssh-rsa,ssh-dss
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-
group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-
cbc,arcfour,aes192-cbc,aes256-cbc
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-
cbc,arcfour,aes192-cbc,aes256-cbc
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-
ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-
ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: kex_parse_kexinit: diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-dss
debug2: kex_parse_kexinit: aes256-cbc,twofish-cbc,blowfish-cbc,3des-
cbc,arcfour,cast128-cbc
debug2: kex_parse_kexinit: aes256-cbc,twofish-cbc,blowfish-cbc,3des-
cbc,arcfour,cast128-cbc
debug2: kex_parse_kexinit: hmac-sha1,hmac-md5,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-sha1,hmac-md5,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: zlib,none
debug2: kex_parse_kexinit: zlib,none
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: mac_init: found hmac-sha1
debug1: kex: client->server aes256-cbc hmac-sha1 zlib
debug2: mac_init: found hmac-sha1
debug1: kex: server->client aes256-cbc hmac-sha1 zlib
debug1: dh_gen_key: priv key bits set: 253/512
debug1: bits set: 510/1024
debug1: expecting SSH2_MSG_KEXDH_INIT
debug1: bits set: 497/1024
debug1: kex_derive_keys
debug1: newkeys: mode 1
debug1: cipher_init: set keylen (16 -> 32)
debug1: Enabling compression at level 6.
debug1: SSH2_MSG_NEWKEYS sent
debug1: waiting for SSH2_MSG_NEWKEYS
debug1: newkeys: mode 0
debug1: cipher_init: set keylen (16 -> 32)
debug1: SSH2_MSG_NEWKEYS received
debug1: KEX done
debug1: userauth-request for user dbider service ssh-connection method password
debug1: attempt 0 failures 0
debug2: input_userauth_request: setting up authctxt for dbider
debug2: input_userauth_request: try method password
Accepted password for dbider from 10.1.1.2 port 2283 ssh2
debug1: Entering interactive session for SSH2.
debug1: fd 3 setting O_NONBLOCK
debug1: fd 7 setting O_NONBLOCK
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 20480 max 20480
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: server_input_channel_req: channel 0 request exec reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req exec
debug1: fd 9 setting O_NONBLOCK
debug2: fd 9 is O_NONBLOCK
debug1: fd 11 setting O_NONBLOCK
debug1: channel 0: rcvd eof
debug1: channel 0: output open -> drain
debug1: channel 0: obuf empty
debug1: channel 0: close_write
debug1: channel 0: output drain -> closed
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 25454
debug1: session_exit_message: session 0 channel 0 pid 25454
debug1: channel request 0: exit-status
debug1: session_exit_message: release channel 0
debug1: session_close: session 0 pid 25454
debug1: channel 0: read<=0 rfd 9 len 0
debug1: channel 0: read failed
debug1: channel 0: close_read
debug1: channel 0: input open -> drain
debug2: channel 0: read 296 from efd 11
debug1: channel 0: ibuf empty
debug1: channel 0: send eof
debug1: channel 0: input drain -> closed
debug2: channel 0: rwin 20480 elen 296 euse 1
debug2: channel 0: sent ext data 296
debug1: channel 0: send close
debug2: notify_done: reading
debug2: channel 0: read 0 from efd 11
debug2: channel 0: closing read-efd 11
debug3: channel 0: will not send data after close
debug3: channel 0: will not send data after close
Received disconnect from 10.1.1.2: 2: unexpected channel message 6
debug1: Calling cleanup 0x805c800(0x0)
debug1: channel_free: channel 0: server-session, nchannels 1
debug3: channel_free: status: The following connections are open:
  #0 server-session (t4 r0 i3/0 o3/0 fd 9/9)

debug3: channel_close_fds: channel 0: r 9 w 9 e -1
debug1: Calling cleanup 0x8067f40(0x0)
debug1: compress outgoing: raw data 393, compressed 283, factor 0.72
debug1: compress incoming: raw data 183, compressed 171, factor 0.93
Comment 1 Markus Friedl 2002-03-22 22:37:06 AEDT 
hm, sshd is not sending channel data after EOF, it's sending _extended_ channel
data. does EOF affect both channel data and extended channel data?

the draft says:


3.3 Closing a Channel

   When a party will no longer send more data to a channel, it SHOULD
   send SSH_MSG_CHANNEL_EOF.

     byte      SSH_MSG_CHANNEL_EOF
     uint32    recipient_channel
Comment 2 denis bider 2002-03-23 00:07:38 AEDT 
Much like a black man is still a man, and a brown cow is still a cow, I would 
think that extended data is still data - especially since data and extended 
data consume the same window. This should be no issue.

However, I think the draft should be more clear about how EOF relates to 
channel requests. It doesn't say anything about whether requests and responses 
can be sent after EOF has been sent. I'll follow up your message about that on 
the sex-age - I mean, secsh mailing list.
Comment 3 Markus Friedl 2002-03-23 01:05:54 AEDT 
extended data handling is an ad hoc hack and very broken. should fix it....
Comment 4 Markus Friedl 2002-03-23 05:46:05 AEDT 
Created attachment 52 [details]
possible fix
Comment 5 Markus Friedl 2002-03-24 02:57:10 AEDT 
Created attachment 53 [details]
another patch
Comment 6 Markus Friedl 2002-03-26 08:16:29 AEDT 
fixed in -current
Comment 7 Damien Miller 2004-04-14 12:24:18 AEST 
Mass change of RESOLVED bugs to CLOSED