When using sftp to transfer a file from a Solaris 8 server to a Windows PC, the transfer fails and the following message is appended to the system log: fred sshd[29075]: [ID 800047 auth.crit] fatal: buffer_append_space: alloc 10517901 not supported. This kills the users ssh session, but sshd continues to run. The version of OpenSSH running is 4.2pl: OpenSSH_4.2p1, OpenSSL 0.9.8 05 Jul 2005 This problem is reproducible.
Is the Solaris box is the server or client? Are you using OpenSSH at both ends, or is the client something different?
Also, which version of zlib and openssl did you build OpenSSH with?
OpenSSH is being used on the server side. The client is SSH.com's Tectia 4.1.1 client, which utilizes a convenient drag & drop feature to sftp files. The zlib version is 1.2.3 (SMCzlib from sunfreeware.com) and openssl version is 0.9.8 (SMCossl098 from sunfreeware.com).
It sounds like either the client is sending a 10MB(!) packet, or there's some bug some other place. Does disabling compression (either by turning it off in the client or setting Compression no in sshd_config) prevent the error?
Also, what compiler did you use to compile OpenSSH? If you compile OpenSSH (and openssl and zlib if possible) with optimization disabled (-O0) does the error still occur?
Created attachment 1071 [details] Apparent fix for bug 1131 against openssh-4.3p2.
Comment on attachment 1071 [details] Apparent fix for bug 1131 against openssh-4.3p2. It appears this can happen when the program being executed on the remote end generates more output than sshd can forward back to the client (ssh2 only, ssh1 is ok). I'm not quite sure why, but the code to throttle the stdout from the program being executed seems to commented out. I'm not quite sure if this patch is correct or not, but it appears to fix the problem for me.
Created attachment 1072 [details] Possible way to reproduce the problem. This may reproduce the problem, it's been tricky for some reason. I have tested this by putting the client (genstdout) and test program (sshtest) on separate machines and it's worked for me so far. Which is to say sshd crashes.
The openssh, openssl and zlib packages that I installed on the system were downloaded from sunfreeware.com.
(In reply to comment #7) > (From update of attachment 1071 [details] [edit]) > It appears this can happen when the program being executed on the remote end > generates more output than sshd can forward back to the client (ssh2 only, ssh1 > is ok). I'm not quite sure why, but the code to throttle the stdout from the > program being executed seems to commented out. I'm not quite sure if this patch > is correct or not, but it appears to fix the problem for me. The code in question corresponds to this commit: date: 2001/10/10 05:01:17; author: djm; state: Exp; lines: +8 -4 - markus@cvs.openbsd.org 2001/10/04 15:05:40 [channels.c serverloop.c] comment out bogus conditions for selecting on connection_in although exactly what that means, I have no idea...
I think that comment may be referring to the "!compat20" in the code. I had to remove that, otherwise I think the routine would be useless.
I don't think that patch is correct - it stops ssh or sshd from processing any packets *received* from the network when any channel's *input* buffer is full. This might fix your problem, but if so I believe it would be by accident. Could you please attach a debug trace ("/usr/sbin/sshd -ddde") from a failing session to this bug?
Created attachment 1092 [details] Limit remote_maxpacket Please try this diff too - I would also be interested in before and after debug traces regardless of whether it fixes the problem.
I believe you're right, I wasn't quite sure why turning off all the FDs instead of just the stdin FD appeared to fix the problem, but that might explain it. Unfortunately your patch didn't seem to work for me. The results appear to be the same: Without patch: urg:~/openssh-4.3p2% sudo `pwd`/sshd -p 2200 -ddde debug2: load_server_config: filename /usr/local/etc/sshd_config debug2: load_server_config: done config len = 346 debug2: parse_server_config: config /usr/local/etc/sshd_config len 346 /usr/local/etc/sshd_config line 72: Unsupported option GSSAPIAuthentication /usr/local/etc/sshd_config line 74: Unsupported option GSSAPICleanupCredentials debug1: sshd version OpenSSH_4.3p2 debug1: private host key: #0 type 0 RSA1 debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #1 type 1 RSA debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #2 type 2 DSA debug1: rexec_argv[0]='/home/employees/cove/openssh-4.3p2/sshd' debug1: rexec_argv[1]='-p' debug1: rexec_argv[2]='2200' debug1: rexec_argv[3]='-ddde' debug2: fd 3 setting O_NONBLOCK debug1: Bind to port 2200 on ::. Server listening on :: port 2200. debug2: fd 4 setting O_NONBLOCK debug1: Bind to port 2200 on 0.0.0.0. Bind to port 2200 on 0.0.0.0 failed: Address already in use. Generating 768 bit RSA key. RSA key generation complete. debug3: fd 4 is not O_NONBLOCK debug1: Server will not fork when running in debugging mode. debug3: send_rexec_state: entering fd = 7 config len 346 debug3: ssh_msg_send: type 0 debug3: send_rexec_state: done debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7 debug3: recv_rexec_state: entering fd = 5 debug3: ssh_msg_recv entering debug3: recv_rexec_state: done debug2: parse_server_config: config rexec len 346 rexec line 72: Unsupported option GSSAPIAuthentication rexec line 74: Unsupported option GSSAPICleanupCredentials debug1: sshd version OpenSSH_4.3p2 debug1: private host key: #0 type 0 RSA1 debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #1 type 1 RSA debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #2 type 2 DSA debug1: inetd sockets after dupping: 3, 3 debug3: Normalising mapped IPv4 in IPv6 address Connection from 10.4.7.131 port 45020 debug1: Client protocol version 2.0; client software version cryptlib debug1: no match: cryptlib debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-1.99-OpenSSH_4.3 debug2: fd 3 setting O_NONBLOCK 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-group14-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,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr 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@openssh.com debug2: kex_parse_kexinit: none,zlib@openssh.com 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-group-exchange-sha1 debug2: kex_parse_kexinit: ssh-rsa debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: none debug2: kex_parse_kexinit: 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 3des-cbc hmac-sha1 none debug2: mac_init: found hmac-sha1 debug1: kex: server->client 3des-cbc hmac-sha1 none debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent debug2: dh_gen_key: priv key bits set: 204/384 debug2: bits set: 539/1024 debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT debug2: bits set: 522/1024 debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent debug2: kex_derive_keys debug2: set_newkeys: mode 1 debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug2: set_newkeys: mode 0 debug1: SSH2_MSG_NEWKEYS received debug1: KEX done debug1: userauth-request for user cove service ssh-connection method password debug1: attempt 0 failures 0 debug2: input_userauth_request: setting up authctxt for cove debug1: PAM: initializing for "cove" debug3: Normalising mapped IPv4 in IPv6 address debug3: Trying to reverse map address 10.4.7.131. debug1: PAM: setting PAM_RHOST to "urg.wildpackets.com" debug1: PAM: setting PAM_TTY to "ssh" debug2: input_userauth_request: try method password debug3: PAM: sshpam_passwd_conv called with 1 messages debug1: PAM: password authentication accepted for cove debug1: do_pam_account: called debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success) debug3: Normalising mapped IPv4 in IPv6 address Accepted password for cove from 10.4.7.131 port 45020 ssh2 debug1: Entering interactive session for SSH2. debug2: fd 6 setting O_NONBLOCK debug2: fd 7 setting O_NONBLOCK debug1: server_init_dispatch_20 debug1: server_input_channel_open: ctype session rchan 0 win 2147483647 max 16384 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 shell reply 0 debug1: session_by_channel: session 0 channel 0 debug1: session_input_channel_req: session 0 req shell debug1: PAM: establishing credentials debug2: fd 9 setting O_NONBLOCK debug3: fd 9 is O_NONBLOCK debug2: fd 11 setting O_NONBLOCK debug2: channel 0: read 30 from efd 11 debug2: channel 0: rwin 2147483647 elen 30 euse 1 debug2: channel 0: sent ext data 30 debug2: channel 0: read 41 from efd 11 debug2: channel 0: rwin 2147483617 elen 41 euse 1 debug2: channel 0: sent ext data 41 debug2: channel 0: read 40 from efd 11 debug2: channel 0: rwin 2147483576 elen 40 euse 1 debug2: channel 0: sent ext data 40 debug2: channel 0: read 49 from efd 11 debug2: channel 0: rwin 2147483536 elen 49 euse 1 debug2: channel 0: sent ext data 49 debug2: channel 0: read 13 from efd 11 debug2: channel 0: rwin 2147483487 elen 13 euse 1 debug2: channel 0: sent ext data 13 debug2: channel 0: read 12 from efd 11 debug2: channel 0: rwin 2147483474 elen 12 euse 1 debug2: channel 0: sent ext data 12 debug2: channel 0: read 15 from efd 11 debug2: channel 0: rwin 2147483462 elen 15 euse 1 debug2: channel 0: sent ext data 15 debug2: channel 0: read 28 from efd 11 debug2: channel 0: rwin 2147483447 elen 28 euse 1 debug2: channel 0: sent ext data 28 debug2: channel 0: read 52 from efd 11 debug2: channel 0: rwin 2147483419 elen 52 euse 1 debug2: channel 0: sent ext data 52 debug2: channel 0: read 190 from efd 11 debug2: channel 0: rwin 2147483367 elen 190 euse 1 debug2: channel 0: sent ext data 190 Connection closed by 10.4.7.131 debug1: channel 0: free: server-session, nchannels 1 debug3: channel 0: status: The following connections are open: #0 server-session (t4 r0 i0/0 o0/0 fd 9/9 cfd -1) debug3: channel 0: close_fds r 9 w 9 e 11 c -1 debug1: session_close: session 0 pid 11585 debug1: do_cleanup debug1: PAM: cleanup debug3: PAM: sshpam_thread_cleanup entering Closing connection to 10.4.7.131 debug1: PAM: cleanup With limit remote maxpacket patch: urg:~/openssh-4.3p2% sudo `pwd`/sshd -p 2200 -ddde debug2: load_server_config: filename /usr/local/etc/sshd_config debug2: load_server_config: done config len = 346 debug2: parse_server_config: config /usr/local/etc/sshd_config len 346 /usr/local/etc/sshd_config line 72: Unsupported option GSSAPIAuthentication /usr/local/etc/sshd_config line 74: Unsupported option GSSAPICleanupCredentials debug1: sshd version OpenSSH_4.3p2 debug1: private host key: #0 type 0 RSA1 debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #1 type 1 RSA debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #2 type 2 DSA debug1: rexec_argv[0]='/home/employees/cove/openssh-4.3p2/sshd' debug1: rexec_argv[1]='-p' debug1: rexec_argv[2]='2200' debug1: rexec_argv[3]='-ddde' debug2: fd 3 setting O_NONBLOCK debug1: Bind to port 2200 on ::. Server listening on :: port 2200. debug2: fd 4 setting O_NONBLOCK debug1: Bind to port 2200 on 0.0.0.0. Bind to port 2200 on 0.0.0.0 failed: Address already in use. Generating 768 bit RSA key. RSA key generation complete. debug3: fd 4 is not O_NONBLOCK debug1: Server will not fork when running in debugging mode. debug3: send_rexec_state: entering fd = 7 config len 346 debug3: ssh_msg_send: type 0 debug3: send_rexec_state: done debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7 debug3: recv_rexec_state: entering fd = 5 debug3: ssh_msg_recv entering debug3: recv_rexec_state: done debug2: parse_server_config: config rexec len 346 rexec line 72: Unsupported option GSSAPIAuthentication rexec line 74: Unsupported option GSSAPICleanupCredentials debug1: sshd version OpenSSH_4.3p2 debug1: private host key: #0 type 0 RSA1 debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #1 type 1 RSA debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #2 type 2 DSA debug1: inetd sockets after dupping: 3, 3 debug3: Normalising mapped IPv4 in IPv6 address Connection from 10.4.7.131 port 45165 debug1: Client protocol version 2.0; client software version cryptlib debug1: no match: cryptlib debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-1.99-OpenSSH_4.3 debug2: fd 3 setting O_NONBLOCK 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-group14-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,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr 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@openssh.com debug2: kex_parse_kexinit: none,zlib@openssh.com 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-group-exchange-sha1 debug2: kex_parse_kexinit: ssh-rsa debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: none debug2: kex_parse_kexinit: 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 3des-cbc hmac-sha1 none debug2: mac_init: found hmac-sha1 debug1: kex: server->client 3des-cbc hmac-sha1 none debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent debug2: dh_gen_key: priv key bits set: 190/384 debug2: bits set: 530/1024 debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT debug2: bits set: 492/1024 debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent debug2: kex_derive_keys debug2: set_newkeys: mode 1 debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug2: set_newkeys: mode 0 debug1: SSH2_MSG_NEWKEYS received debug1: KEX done debug1: userauth-request for user cove service ssh-connection method password debug1: attempt 0 failures 0 debug2: input_userauth_request: setting up authctxt for cove debug1: PAM: initializing for "cove" debug3: Normalising mapped IPv4 in IPv6 address debug3: Trying to reverse map address 10.4.7.131. debug1: PAM: setting PAM_RHOST to "urg.wildpackets.com" debug1: PAM: setting PAM_TTY to "ssh" debug2: input_userauth_request: try method password debug3: PAM: sshpam_passwd_conv called with 1 messages debug1: PAM: password authentication accepted for cove debug1: do_pam_account: called debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success) debug3: Normalising mapped IPv4 in IPv6 address Accepted password for cove from 10.4.7.131 port 45165 ssh2 debug1: Entering interactive session for SSH2. debug2: fd 6 setting O_NONBLOCK debug2: fd 7 setting O_NONBLOCK debug1: server_init_dispatch_20 debug1: server_input_channel_open: ctype session rchan 0 win 2147483647 max 16384 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 shell reply 0 debug1: session_by_channel: session 0 channel 0 debug1: session_input_channel_req: session 0 req shell debug1: PAM: establishing credentials debug2: fd 9 setting O_NONBLOCK debug3: fd 9 is O_NONBLOCK debug2: fd 11 setting O_NONBLOCK debug2: channel 0: read 30 from efd 11 debug2: channel 0: rwin 2147483647 elen 30 euse 1 debug2: channel 0: sent ext data 30 debug2: channel 0: read 41 from efd 11 debug2: channel 0: rwin 2147483617 elen 41 euse 1 debug2: channel 0: sent ext data 41 debug2: channel 0: read 40 from efd 11 debug2: channel 0: rwin 2147483576 elen 40 euse 1 debug2: channel 0: sent ext data 40 debug2: channel 0: read 49 from efd 11 debug2: channel 0: rwin 2147483536 elen 49 euse 1 debug2: channel 0: sent ext data 49 debug2: channel 0: read 13 from efd 11 debug2: channel 0: rwin 2147483487 elen 13 euse 1 debug2: channel 0: sent ext data 13 debug2: channel 0: read 12 from efd 11 debug2: channel 0: rwin 2147483474 elen 12 euse 1 debug2: channel 0: sent ext data 12 debug2: channel 0: read 285 from efd 11 debug2: channel 0: rwin 2147483462 elen 285 euse 1 debug2: channel 0: sent ext data 285 Connection closed by 10.4.7.131 debug1: channel 0: free: server-session, nchannels 1 debug3: channel 0: status: The following connections are open: #0 server-session (t4 r0 i0/0 o0/0 fd 9/9 cfd -1) debug3: channel 0: close_fds r 9 w 9 e 11 c -1 debug1: session_close: session 0 pid 16742 debug1: do_cleanup debug1: PAM: cleanup debug3: PAM: sshpam_thread_cleanup entering Closing connection to 10.4.7.131 debug1: PAM: cleanup
(In reply to comment #14) ... > debug2: channel 0: rwin 2147483367 elen 190 euse 1 > debug2: channel 0: sent ext data 190 > Connection closed by 10.4.7.131 NB: at this point the remote end (cryptlib) returns CRYPT_ERROR_TIMEOUT.
Ok. The reason for the timeout was due to an overloaded machine. Here is what happens with the limit remote maxpacket patch: urg:~/openssh-4.3p2# `pwd`/sshd -p 2200 -ddde debug2: load_server_config: filename /usr/local/etc/sshd_config debug2: load_server_config: done config len = 292 debug2: parse_server_config: config /usr/local/etc/sshd_config len 292 debug1: sshd version OpenSSH_4.3p2 debug1: private host key: #0 type 0 RSA1 debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #1 type 1 RSA debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #2 type 2 DSA debug1: rexec_argv[0]='/home/employees/cove/openssh-4.3p2/sshd' debug1: rexec_argv[1]='-p' debug1: rexec_argv[2]='2200' debug1: rexec_argv[3]='-ddde' debug2: fd 3 setting O_NONBLOCK debug1: Bind to port 2200 on ::. Server listening on :: port 2200. debug2: fd 4 setting O_NONBLOCK debug1: Bind to port 2200 on 0.0.0.0. Bind to port 2200 on 0.0.0.0 failed: Address already in use. Generating 768 bit RSA key. RSA key generation complete. debug3: fd 4 is not O_NONBLOCK debug1: Server will not fork when running in debugging mode. debug3: send_rexec_state: entering fd = 7 config len 292 debug3: ssh_msg_send: type 0 debug3: send_rexec_state: done debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7 debug3: recv_rexec_state: entering fd = 5 debug3: ssh_msg_recv entering debug3: recv_rexec_state: done debug2: parse_server_config: config rexec len 292 debug1: sshd version OpenSSH_4.3p2 debug1: private host key: #0 type 0 RSA1 debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #1 type 1 RSA debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #2 type 2 DSA debug1: inetd sockets after dupping: 3, 3 debug3: Normalising mapped IPv4 in IPv6 address Connection from 10.4.58.3 port 60508 debug1: Client protocol version 2.0; client software version cryptlib debug1: no match: cryptlib debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-1.99-OpenSSH_4.3 debug2: fd 3 setting O_NONBLOCK 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-group14-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,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr 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@openssh.com debug2: kex_parse_kexinit: none,zlib@openssh.com 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-group-exchange-sha1 debug2: kex_parse_kexinit: ssh-rsa debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: none debug2: kex_parse_kexinit: 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 3des-cbc hmac-sha1 none debug2: mac_init: found hmac-sha1 debug1: kex: server->client 3des-cbc hmac-sha1 none debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent debug2: dh_gen_key: priv key bits set: 200/384 debug2: bits set: 521/1024 debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT debug2: bits set: 530/1024 debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent debug2: kex_derive_keys debug2: set_newkeys: mode 1 debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug2: set_newkeys: mode 0 debug1: SSH2_MSG_NEWKEYS received debug1: KEX done debug1: userauth-request for user cove service ssh-connection method password debug1: attempt 0 failures 0 debug2: input_userauth_request: setting up authctxt for cove debug1: PAM: initializing for "cove" debug3: Normalising mapped IPv4 in IPv6 address debug3: Trying to reverse map address 10.4.58.3. debug1: PAM: setting PAM_RHOST to "xo.wildpackets.com" debug1: PAM: setting PAM_TTY to "ssh" debug2: input_userauth_request: try method password debug3: PAM: sshpam_passwd_conv called with 1 messages debug1: PAM: password authentication accepted for cove debug1: do_pam_account: called debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success) debug3: Normalising mapped IPv4 in IPv6 address Accepted password for cove from 10.4.58.3 port 60508 ssh2 debug1: Entering interactive session for SSH2. debug2: fd 6 setting O_NONBLOCK debug2: fd 7 setting O_NONBLOCK debug1: server_init_dispatch_20 debug1: server_input_channel_open: ctype session rchan 0 win 2147483647 max 16384 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 shell reply 0 debug1: session_by_channel: session 0 channel 0 debug1: session_input_channel_req: session 0 req shell debug1: PAM: establishing credentials debug2: fd 9 setting O_NONBLOCK debug3: fd 9 is O_NONBLOCK debug2: fd 11 setting O_NONBLOCK debug2: channel 0: read 30 from efd 11 debug2: channel 0: rwin 2147483647 elen 30 euse 1 debug2: channel 0: sent ext data 30 debug2: channel 0: read 41 from efd 11 debug2: channel 0: rwin 2147483617 elen 41 euse 1 debug2: channel 0: sent ext data 41 debug2: channel 0: read 40 from efd 11 debug2: channel 0: rwin 2147483576 elen 40 euse 1 debug2: channel 0: sent ext data 40 debug2: channel 0: read 49 from efd 11 debug2: channel 0: rwin 2147483536 elen 49 euse 1 debug2: channel 0: sent ext data 49 debug2: channel 0: read 13 from efd 11 debug2: channel 0: rwin 2147483487 elen 13 euse 1 debug2: channel 0: sent ext data 13 debug2: channel 0: read 12 from efd 11 debug2: channel 0: rwin 2147483474 elen 12 euse 1 debug2: channel 0: sent ext data 12 debug2: channel 0: read 15 from efd 11 debug2: channel 0: rwin 2147483462 elen 15 euse 1 debug2: channel 0: sent ext data 15 debug2: channel 0: read 28 from efd 11 debug2: channel 0: rwin 2147483447 elen 28 euse 1 debug2: channel 0: sent ext data 28 debug2: channel 0: read 52 from efd 11 debug2: channel 0: rwin 2147483419 elen 52 euse 1 debug2: channel 0: sent ext data 52 debug2: channel 0: read 22 from efd 11 debug2: channel 0: rwin 2147483367 elen 22 euse 1 debug2: channel 0: sent ext data 22 debug2: channel 0: read 166 from efd 11 debug2: channel 0: rwin 2147483345 elen 166 euse 1 debug2: channel 0: sent ext data 166 buffer_append_space: alloc 10522112 not supported debug1: do_cleanup debug1: PAM: cleanup debug3: PAM: sshpam_thread_cleanup entering
Created attachment 1095 [details] abort() on buffer errors It looks like the client is sending a bad remote_window value which probably indicates a bug on that side, but we still shouldn't blow up. Could you please try to reproduce the bug with this patch applied and sshd rebuilt with debugging symbols enabled (edit Makefile and append "-g" to CFLAGS if you are using gcc). Run sshd using "sshd -ddder". It should then produce a core file on these buffer error. Please try to get a backtrace from it using gdb or similar.
It could be a bug in cryptlib, but I had the same problem with libssh and the first comment in this bug report is with a 3rd implementation. debug2: load_server_config: filename /usr/local/etc/sshd_config debug2: load_server_config: done config len = 292 debug2: parse_server_config: config /usr/local/etc/sshd_config len 292 debug1: sshd version OpenSSH_4.3p2 debug1: private host key: #0 type 0 RSA1 debug3: Not a RSA1 key file /usr/local/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #1 type 1 RSA debug3: Not a RSA1 key file /usr/local/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #2 type 2 DSA debug2: fd 3 setting O_NONBLOCK debug1: Bind to port 2200 on ::. Server listening on :: port 2200. debug2: fd 4 setting O_NONBLOCK debug1: Bind to port 2200 on 0.0.0.0. Bind to port 2200 on 0.0.0.0 failed: Address already in use. Generating 768 bit RSA key. RSA key generation complete. debug3: fd 4 is not O_NONBLOCK debug1: Server will not fork when running in debugging mode. debug3: Normalising mapped IPv4 in IPv6 address Connection from 10.4.58.3 port 41973 debug1: Client protocol version 2.0; client software version cryptlib debug1: no match: cryptlib debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-1.99-OpenSSH_4.3 debug2: fd 4 setting O_NONBLOCK 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-group14-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,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr 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@openssh.com debug2: kex_parse_kexinit: none,zlib@openssh.com 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-group-exchange-sha1 debug2: kex_parse_kexinit: ssh-rsa debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: 3des-cbc debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: none debug2: kex_parse_kexinit: 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 3des-cbc hmac-sha1 none debug2: mac_init: found hmac-sha1 debug1: kex: server->client 3des-cbc hmac-sha1 none debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent debug2: dh_gen_key: priv key bits set: 206/384 debug2: bits set: 495/1024 debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT debug2: bits set: 522/1024 debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent debug2: kex_derive_keys debug2: set_newkeys: mode 1 debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug2: set_newkeys: mode 0 debug1: SSH2_MSG_NEWKEYS received debug1: KEX done debug1: userauth-request for user cove service ssh-connection method password debug1: attempt 0 failures 0 debug2: input_userauth_request: setting up authctxt for cove debug1: PAM: initializing for "cove" debug3: Normalising mapped IPv4 in IPv6 address debug3: Trying to reverse map address 10.4.58.3. debug1: PAM: setting PAM_RHOST to "xo.wildpackets.com" debug1: PAM: setting PAM_TTY to "ssh" debug2: input_userauth_request: try method password debug3: PAM: sshpam_passwd_conv called with 1 messages debug1: PAM: password authentication accepted for cove debug1: do_pam_account: called debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success) debug3: Normalising mapped IPv4 in IPv6 address Accepted password for cove from 10.4.58.3 port 41973 ssh2 debug1: Entering interactive session for SSH2. debug2: fd 6 setting O_NONBLOCK debug2: fd 7 setting O_NONBLOCK debug1: server_init_dispatch_20 debug1: server_input_channel_open: ctype session rchan 0 win 2147483647 max 16384 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 shell reply 0 debug1: session_by_channel: session 0 channel 0 debug1: session_input_channel_req: session 0 req shell debug1: PAM: establishing credentials debug2: fd 9 setting O_NONBLOCK debug3: fd 9 is O_NONBLOCK debug2: fd 11 setting O_NONBLOCK debug2: channel 0: read 30 from efd 11 debug2: channel 0: rwin 2147483647 elen 30 euse 1 debug2: channel 0: sent ext data 30 debug2: channel 0: read 41 from efd 11 debug2: channel 0: rwin 2147483617 elen 41 euse 1 debug2: channel 0: sent ext data 41 debug2: channel 0: read 40 from efd 11 debug2: channel 0: rwin 2147483576 elen 40 euse 1 debug2: channel 0: sent ext data 40 debug2: channel 0: read 49 from efd 11 debug2: channel 0: rwin 2147483536 elen 49 euse 1 debug2: channel 0: sent ext data 49 debug2: channel 0: read 13 from efd 11 debug2: channel 0: rwin 2147483487 elen 13 euse 1 debug2: channel 0: sent ext data 13 debug2: channel 0: read 295 from efd 11 debug2: channel 0: rwin 2147483474 elen 295 euse 1 debug2: channel 0: sent ext data 295 buffer_append_space: alloc 10522112 not supported zsh: 8776 abort (core dumped) `pwd`/sshd -p 2200 -ddder Heres the stack trace: #0 0x008337a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2 (gdb) bt #0 0x008337a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2 #1 0x008737d5 in raise () from /lib/tls/libc.so.6 #2 0x00875149 in abort () from /lib/tls/libc.so.6 #3 0x0806b6f4 in buffer_append_space (buffer=0x93825c0, len=16384) at buffer.c:115 #4 0x0806b5a9 in buffer_append (buffer=0x93825c0, data=0xbfeccdf0, len=16384) at buffer.c:65 #5 0x0806f1c0 in channel_handle_rfd (c=0x9382580, readset=0x92e1e88, writeset=0x92e07b8) at channels.c:1449 #6 0x0806f9bf in channel_post_open (c=0x9382580, readset=0x92e1e88, writeset=0x92e07b8) at channels.c:1636 #7 0x0806fe30 in channel_handler (ftab=0x809a480, readset=0x92e1e88, writeset=0x92e07b8) at channels.c:1778 #8 0x0806ff41 in channel_after_select (readset=0x92e1e88, writeset=0x92e07b8) at channels.c:1817 #9 0x0805536d in server_loop2 (authctxt=0x92d7750) at serverloop.c:805 #10 0x0805cacd in do_authenticated2 (authctxt=0x92d7750) at session.c:2420 #11 0x08058c81 in do_authenticated (authctxt=0x92d7750) at session.c:217 #12 0x0804f928 in main (ac=4, av=0x92d5018) at sshd.c:1755
First, please attach debug traces at attachements rather than pasting them into the comments. It clutters the bug. Have you applied any patches to your OpenSSH source, or are you no longer using 4.2p1? The line numbers in the stack trace don't line up with the functions in 4.2p1.
Created attachment 1100 [details] Trace with remote_maxpacket and abort patch against pristine 4.3p2 source. I've been working with this source a bit, so it's possible the line numbers got out of sync. Attached a trace from a pristine copy of the 4.3p2 source.
Created attachment 1103 [details] Debug buffer limits Ignore those previous diffs (and remove them from your tree if you can). Could you try this? It should produce some extra detail that will narrow it down. If you look at the first part of the diff, you might notice that we try to avoid overfilling the buffer like this but for some reason this check doesn't seem to be working...
Created attachment 1113 [details] Output using the Debug Buffer Limits patch Same thing.
Created attachment 1114 [details] Hopefully fix the problem I think I get it now :) It looks like the problem is occuring when the buffer offset is close to, but not exceeding BUFFER_MAX_CHUNK and the allocation is close to BUFFER_MAX_LEN. channels.c tries to do the right thing and stop reading when the buffer is full like this, but it didn't take into account the 32768 byte allocation increment that the buffer code uses to avoid having to go and fetch more memory at each buffer_append_space() call. Hopefully this patch will fix the problem. It adds a buffer_check_alloc(buffer, len) function that the channel.c code can use to test whether a CHAN_RBUF allocation can fit. It is more logical to keep this check in the buffer.c code so it can stay synced with the actual append_space math. The patch also chunks the buffer memory allocations, so the number of bytes allocated to the buffer is always a multiple of 32768, which is a little neater. Please let me know if it solves your problem (you will probably need to pull out the last debug patch to apply it)
Well I don't get the alloc failure anymore (yea!), but sshd stops forwarding data back after sending aprox 10.6MB (try 1 was 11,143,698 bytes, and try 2 11,124,970). I'll post some debug logs shortly.
Created attachment 1115 [details] sshd debug output for hang at byte 10647071 My previous comment about the hang happening at byte 11143698 and 11124970 accidently included some application overhead, so ignore those. It's consistently stopping at byte 10647071.
Created attachment 1116 [details] strace of hang at byte 10647071
Created attachment 1117 [details] Revised diff My bad, the previous diff didn't follow the logic of buffer_append_space() closely enough. Please try this one.
Works for me. Thanks!
ok, the fix has been committed and will be in openssh-4.4. Thanks for your patience and assistance in debugging this.
Much appreciated.
With the release of 4.4, we believe that this bug is now closed. For information about the release please see http://www.openssh.com/txt/release-4.4 .