openssh bugs - Mar 2006 - [Bug 1131] buffer_append_space: alloc not supported Error with V 4.2p1

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #18 from cove at wildpackets.com  2006-03-17 09:06 -------
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
at 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
at lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at
openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at
openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib at openssh.com
debug2: kex_parse_kexinit: none,zlib at 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




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #19 from djm at mindrot.org  2006-03-19 10:33 -------
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.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #20 from cove at wildpackets.com  2006-03-21 09:23 -------
Created an attachment (id=1100)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1100&action=view)
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.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131


djm at mindrot.org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
Attachment #1071 is|0                           |1
           obsolete|                            |
Attachment #1092 is|0                           |1
           obsolete|                            |




------- Comment #21 from djm at mindrot.org  2006-03-25 21:17 -------
Created an attachment (id=1103)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1103&action=view)
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...




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #22 from cove at wildpackets.com  2006-04-04 08:34 -------
Created an attachment (id=1113)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1113&action=view)
Output using the  Debug Buffer Limits patch

Same thing.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #23 from djm at mindrot.org  2006-04-04 10:51 -------
Created an attachment (id=1114)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1114&action=view)
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)




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #24 from cove at wildpackets.com  2006-04-05 09:26 -------
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.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #25 from cove at wildpackets.com  2006-04-05 10:20 -------
Created an attachment (id=1115)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1115&action=view)
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.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #26 from cove at wildpackets.com  2006-04-05 10:23 -------
Created an attachment (id=1116)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1116&action=view)
strace of hang at byte 10647071




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131


djm at mindrot.org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
Attachment #1114 is|0                           |1
           obsolete|                            |




------- Comment #27 from djm at mindrot.org  2006-04-05 12:37 -------
Created an attachment (id=1117)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1117&action=view)
Revised diff

My bad, the previous diff didn't follow the logic of buffer_append_space()
closely enough. Please try this one.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131





------- Comment #28 from cove at wildpackets.com  2006-04-06 07:01 -------
Works for me. Thanks!




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1131


djm at mindrot.org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
OtherBugsDependingO|                            |1155
              nThis|                            |
             Status|NEW                         |RESOLVED
         Resolution|                            |FIXED




------- Comment #29 from djm at mindrot.org  2006-04-16 10:48 -------
ok, the fix has been committed and will be in openssh-4.4. Thanks for your
patience and assistance in debugging this.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.