bugzilla-daemon at mindrot.org
2006-Nov-22 11:32 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 Summary: Channel not close by sshd Server Product: Portable OpenSSH Version: 4.3p2 Platform: Other OS/Version: HP-UX Status: NEW Severity: critical Priority: P2 Component: sshd AssignedTo: bitbucket at mindrot.org ReportedBy: ajain at hp.com Hi, This is regarding the issue found on SSHD (OpenSSH 4.3) on HP-UX. Our application works well with OPENSSH4.2 and below version for HP-UX. Further it works fine for all versions of OpenSSH for all other OS like Linux, Solaris, AIX, Tru64 etc. Our application is using SSH protocol [Version 2] to connect to the SSHD server and it runs few commands on the server. It uses Perl SSH2 libraries, which gives us the wrapper functionality for ssh2 protocol. For each command to execute on the server it uses a function called cmd() which internally opens a new channel and closes it after executing the command. But in this case, the channel is not closed by the SSH server which is supposed to do and it continues to open uptill 10 channels. When it tries to open the 11th channel it says "no more sessions". So only the first 10 commands gets executed and we receive the output and rest of the commands are not executed. We found that this problem is only on HPUX where OpenSSH 4.3 is installed. It works fine with other OS where OpenSSH 4.3 is installed. Please provide some help on this The server log [sshd log in debug mode] debug2: load_server_config: filename /opt/ssh/etc/sshd_config debug2: load_server_config: done config len = 350 debug2: parse_server_config: config /opt/ssh/etc/sshd_config len 350 debug1: TOKEN IS protocol debug1: TOKEN IS loglevel debug1: TOKEN IS kerberosauthentication debug1: TOKEN IS usepam debug1: TOKEN IS x11forwarding debug1: TOKEN IS x11displayoffset debug1: TOKEN IS x11uselocalhost debug1: TOKEN IS clientaliveinterval debug1: TOKEN IS maxstartups debug1: TOKEN IS subsystem debug3: RNG is ready, skipping seeding debug1: sshd version OpenSSH_4.3p2-hpn [ HP-UX Secure Shell-A.04.30.015 ] debug3: Not a RSA1 key file /opt/ssh/etc/ssh_host_rsa_key. debug1: read PEM private key done: type RSA debug1: private host key: #0 type 1 RSA debug3: Not a RSA1 key file /opt/ssh/etc/ssh_host_dsa_key. debug1: read PEM private key done: type DSA debug1: private host key: #1 type 2 DSA debug1: rexec_argv[0]='/opt/ssh/sbin/sshd' debug1: rexec_argv[1]='-ddd' debug2: fd 4 setting O_NONBLOCK debug1: Bind to port 22 on ::. Server listening on :: port 22. debug2: fd 5 setting O_NONBLOCK debug1: Bind to port 22 on 0.0.0.0. Server listening on 0.0.0.0 port 22. debug3: fd 6 is not O_NONBLOCK debug1: Server will not fork when running in debugging mode. debug3: send_rexec_state: entering fd = 9 config len 350 debug3: ssh_msg_send: type 0 debug3: send_rexec_state: done debug1: rexec start in 6 out 6 newsock 6 pipe -1 sock 9 debug1: inetd sockets after dupping: 4, 4 debug1: audit connection from 15.1.196.211 port 1023 euid 0 Connection from 15.1.196.211 port 1023 debug1: Client protocol version 2.0; client software version 1.29 debug1: no match: 1.29 debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-2.0-OpenSSH_4.3p2-hpn debug2: fd 4 setting O_NONBLOCK debug2: Network child is on pid 19937 debug3: preauth child monitor started debug3: mm_request_receive entering debug3: privsep user:group 102:102 debug1: permanently_set_uid: 102/102 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-group1-sha1 debug2: kex_parse_kexinit: ssh-dss,ssh-rsa debug2: kex_parse_kexinit: 3des-cbc,blowfish-cbc,arcfour debug2: kex_parse_kexinit: 3des-cbc,blowfish-cbc,arcfour debug2: kex_parse_kexinit: hmac-sha1,hmac-md5 debug2: kex_parse_kexinit: hmac-sha1,hmac-md5 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 debug2: dh_gen_key: priv key bits set: 202/384 debug2: bits set: 495/1024 debug1: expecting SSH2_MSG_KEXDH_INIT debug2: bits set: 512/1024 debug3: mm_key_sign entering debug3: mm_request_send entering: type 4 debug3: monitor_read: checking request 4 debug3: mm_answer_sign debug3: mm_answer_sign: signature 4004f000(55) debug3: mm_request_send entering: type 5 debug2: monitor_read: 4 used once, disabling now debug3: mm_request_receive entering debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN debug3: mm_request_receive_expect entering: type 5 debug3: mm_request_receive entering 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 root service ssh-connection method none debug1: attempt 0 failures 0 debug3: mm_getpwnamallow entering debug3: mm_request_send entering: type 6 debug3: monitor_read: checking request 6 debug3: mm_answer_pwnamallow debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1 debug3: mm_request_send entering: type 7 debug2: monitor_read: 6 used once, disabling now debug3: mm_request_receive entering debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM debug3: mm_request_receive_expect entering: type 7 debug3: mm_request_receive entering debug2: input_userauth_request: setting up authctxt for root debug3: mm_start_pam entering debug3: mm_request_send entering: type 45 debug3: monitor_read: checking request 45 debug1: PAM: initializing for "root" debug3: Trying to reverse map address 15.1.196.211. debug3: mm_inform_authserv entering debug3: mm_request_send entering: type 3 debug3: auth_allowed: method=none user=root debug3: Trying to reverse map address 15.1.196.211. debug2: input_userauth_request: try method none debug3: mm_auth_password entering debug3: mm_request_send entering: type 10 debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD debug3: mm_request_receive_expect entering: type 11 debug3: mm_request_receive entering debug1: PAM: setting PAM_RHOST to "rssstpa.esr.hp.com" debug2: monitor_read: 45 used once, disabling now debug3: mm_request_receive entering debug3: monitor_read: checking request 3 debug3: mm_answer_authserv: service=ssh-connection, style= debug2: monitor_read: 3 used once, disabling now debug3: mm_request_receive entering debug3: monitor_read: checking request 10 debug3: mm_answer_authpassword: sending result 0 debug3: mm_request_send entering: type 11 debug3: mm_auth_password: user not authenticated Failed none for root from 15.1.196.211 port 1023 ssh2 debug3: audit failed auth attempt, method none euid 102 debug3: auth_allowed: method=publickey user=root debug3: auth_allowed: method=password user=root debug3: auth_allowed: method=keyboard-interactive user=root Failed none for root from 15.1.196.211 port 1023 ssh2 debug3: audit failed auth attempt, method none euid 0 debug1: audit event euid 0 user root event 3 (AUTH_FAIL_NONE) debug3: mm_request_receive entering debug1: userauth-request for user root service ssh-connection method password debug1: attempt 1 failures 1 debug3: auth_allowed: method=password user=root debug2: input_userauth_request: try method password debug3: mm_auth_password entering debug3: mm_request_send entering: type 10 debug3: monitor_read: checking request 10 debug3: auth_allowed: method=kerberos user=root debug1: temporarily_use_uid: 0/3 (e=0/3) debug1: restore_uid: 0/3 debug1: Kerberos password authentication failed: -1765328249 debug1: krb5_cleanup_proc called debug3: auth_allowed: method=kerberos_or_local user=root debug3: PAM: sshpam_passwd_conv called with 1 messages debug1: PAM: password authentication accepted for root debug3: mm_answer_authpassword: sending result 1 debug3: mm_request_send entering: type 11 debug3: mm_request_receive_expect entering: type 46 debug3: mm_request_receive entering debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD debug3: mm_request_receive_expect entering: type 11 debug3: mm_request_receive entering debug3: mm_auth_password: user authenticated debug3: mm_do_pam_account entering debug3: mm_request_send entering: type 46 debug1: do_pam_account: called debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success) debug3: mm_request_send entering: type 47 Accepted password for root from 15.1.196.211 port 1023 ssh2 debug1: monitor_child_preauth: root has been authenticated by privileged process debug3: mm_get_keystate: Waiting for new keys debug3: mm_request_receive_expect entering: type 24 debug3: mm_request_receive entering debug3: mm_request_receive_expect entering: type 47 debug3: mm_request_receive entering debug3: mm_do_pam_account returning 1 Accepted password for root from 15.1.196.211 port 1023 ssh2 debug3: mm_send_keystate: Sending new keys: 40028b10 40028bd0 debug3: mm_newkeys_to_blob: converting 40028b10 debug3: mm_newkeys_to_blob: converting 40028bd0 debug3: mm_send_keystate: New keys have been sent debug3: mm_send_keystate: Sending compression state debug3: mm_request_send entering: type 24 debug3: mm_newkeys_from_blob: 40083790(121) debug2: mac_init: found hmac-sha1 debug3: mm_get_keystate: Waiting for second key debug3: mm_newkeys_from_blob: 40083790(121) debug2: mac_init: found hmac-sha1 debug3: mm_get_keystate: Getting compression state debug3: mm_get_keystate: Getting Network I/O buffers debug3: mm_share_sync: Share sync debug3: mm_share_sync: Share sync end debug3: mm_send_keystate: Finished sending state debug1: audit event euid 0 user root event 2 (AUTH_SUCCESS) debug2: set_newkeys: mode 0 debug2: set_newkeys: mode 1 debug1: Entering interactive session for SSH2. debug2: fd 6 setting O_NONBLOCK debug2: fd 10 setting O_NONBLOCK debug1: server_init_dispatch_20 debug1: server_input_channel_open: ctype session rchan 0 win 32768 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: audit run command euid 0 user root command '/sbin/sh' debug1: PAM: establishing credentials debug2: fd 13 setting O_NONBLOCK debug2: fd 12 setting O_NONBLOCK debug2: fd 15 setting O_NONBLOCK debug2: tcpwinsz: 32768 for connection: 4 debug2: channel 0: read 461 from efd 15 debug2: channel 0: rwin 32768 elen 461 euse 1 debug2: channel 0: sent ext data 461 debug2: channel 0: read 44 from efd 15 debug2: channel 0: rwin 32307 elen 44 euse 1 debug2: channel 0: sent ext data 44 debug2: channel 0: read 25 from efd 15 debug2: channel 0: rwin 32263 elen 25 euse 1 debug2: channel 0: sent ext data 25 debug2: channel 0: read 15 from efd 15 debug2: channel 0: rwin 31071 elen 15 euse 1 debug2: channel 0: sent ext data 15 debug2: channel 0: read 25 from efd 15 debug2: channel 0: rwin 31056 elen 25 euse 1 debug2: channel 0: sent ext data 25 debug2: channel 0: read 25 from efd 15 debug2: channel 0: rwin 31031 elen 25 euse 1 debug2: channel 0: sent ext data 25 debug1: server_input_channel_open: ctype session rchan 1 win 32768 max 16384 debug1: input_session_request debug1: channel 1: new [server-session] debug1: session_new: session 1 debug1: session_open: channel 1 debug1: session_open: session 1: link with channel 1 debug1: server_input_channel_open: confirm session debug1: server_input_channel_req: channel 1 request exec reply 0 debug1: session_by_channel: session 1 channel 1 debug1: session_input_channel_req: session 1 req exec debug1: audit run command euid 0 user root command 'which cat' debug1: PAM: establishing credentials debug2: fd 16 setting O_NONBLOCK debug2: fd 14 setting O_NONBLOCK debug2: fd 18 setting O_NONBLOCK debug2: tcpwinsz: 32768 for connection: 4 debug2: channel 1: read 511 from efd 18 debug2: channel 1: rwin 32768 elen 511 euse 1 debug2: channel 1: sent ext data 511 debug1: Received SIGCHLD. debug1: session_by_pid: pid 19952 debug1: session_exit_message: session 1 channel 1 pid 19952 debug2: channel 1: request exit-status confirm 0 debug1: session_exit_message: release channel 1 debug2: channel 1: write failed debug2: channel 1: close_write debug2: channel 1: output open -> closed debug2: notify_done: reading debug2: channel 1: read<=0 rfd 16 len 0 debug2: channel 1: read failed debug2: channel 1: close_read debug2: channel 1: input open -> drain debug2: channel 1: read 0 from efd 18 debug2: channel 1: closing read-efd 18 debug2: channel 1: ibuf empty debug2: channel 1: send eof debug2: channel 1: input drain -> closed debug2: channel 1: send close debug3: channel 1: will not send data after close debug2: channel 1: rcvd close debug3: channel 1: will not send data after close debug2: channel 1: is dead debug2: channel 1: gc: notify user debug1: session_by_channel: session 1 channel 1 debug1: session_close_by_channel: channel 1 child 19952 debug1: session_close_by_channel: channel 1: has child debug2: channel 1: is dead debug2: channel 1: gc: notify user debug1: session_by_channel: session 1 channel 1 debug1: session_close_by_channel: channel 1 child 19952 debug1: session_close_by_channel: channel 1: has child debug1: server_input_channel_open: ctype session rchan 2 win 32768 max 16384 debug1: input_session_request debug1: input_session_request debug1: channel 10: new [server-session] debug1: session_open: channel 10 no more sessions debug1: session open failed, free channel 10 debug1: channel 10: free: server-session, nchannels 11 debug3: channel 10: status: The following connections are open: #0 server-session (t4 r0 i0/0 o0/0 fd 13/12 cfd -1) #1 server-session (t4 r1 i3/0 o3/0 fd -1/-1 cfd -1) #2 server-session (t4 r2 i3/0 o3/0 fd -1/-1 cfd -1) #3 server-session (t4 r3 i3/0 o3/0 fd -1/-1 cfd -1) #4 server-session (t4 r4 i3/0 o3/0 fd -1/-1 cfd -1) #5 server-session (t4 r5 i3/0 o3/0 fd -1/-1 cfd -1) #6 server-session (t4 r6 i3/0 o3/0 fd -1/-1 cfd -1) #7 server-session (t4 r7 i3/0 o3/0 fd -1/-1 cfd -1) #8 server-session (t4 r8 i3/0 o3/0 fd -1/-1 cfd -1) #9 server-session (t4 r9 i3/0 o3/0 fd -1/-1 cfd -1) #10 server-session (t10 r-1 i0/0 o0/0 fd -1/-1 cfd -1) debug3: channel 10: close_fds r -1 w -1 e -1 c -1 debug1: server_input_channel_open: failure session Regards, Ajay ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 11:46 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 ------- Comment #1 from dtucker at zip.com.au 2006-11-22 22:46 ------- Firstly, that debug trace is from a modified sshd. Can you reproduce your problem with an unmodified current (OpenSSH 4.5p1) sshd? If so, please attach it (ie use "create a new attachment", the one inline is nearly unreadable). Secondly, my guess is that the sessions are hanging waiting for a descriptor to close. Can you please run "lsof" against one of the pids of the commands spawned and the unprivileged sshd? ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 11:59 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 ------- Comment #2 from ajain at hp.com 2006-11-22 22:59 ------- Created an attachment (id=1211) --> (http://bugzilla.mindrot.org/attachment.cgi?id=1211&action=view) Attachment contains zip files which include SSH client and server logs Attachment contains zip files which include SSH client and server logs. ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 12:21 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 ------- Comment #3 from dtucker at zip.com.au 2006-11-22 23:21 ------- OK, nothing jumps out from the logs. (BTW, please don't zip or compress the logs but just attach them as text files, they're easier to review that way). Another thing to try: does the problem stop if you set 'UsePAM no' in sshd? ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 12:45 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 ajain at hp.com changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #1211 is|0 |1 obsolete| | ------- Comment #4 from ajain at hp.com 2006-11-22 23:45 ------- Created an attachment (id=1212) --> (http://bugzilla.mindrot.org/attachment.cgi?id=1212&action=view) Attachment contains SSHD logs By setting "UsePAM no" in the sshd_config file and restarting the service. Has not resolved the problem ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 12:48 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 ------- Comment #5 from ajain at hp.com 2006-11-22 23:48 ------- Created an attachment (id=1213) --> (http://bugzilla.mindrot.org/attachment.cgi?id=1213&action=view) Attachment contains SSH client log ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 13:08 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 ------- Comment #6 from dtucker at zip.com.au 2006-11-23 00:08 ------- (From update of attachment 1212) That output is still from a modified sshd. Can you reproduce this with an unmodified OpenSSH 4.5p1 and can you get lsof output from the processes requested in comment #1? ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 13:09 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 dtucker at zip.com.au changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #1212|application/octet-stream |text/plain mime type| | ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Nov-22 13:10 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 dtucker at zip.com.au changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #1213|application/octet-stream |text/plain mime type| | ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Dec-06 07:12 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 ------- Comment #7 from ajain at hp.com 2006-12-06 18:12 ------- This bug is fixed in the latest release of OpenSSH 4.4p1 (HPUX). so please close this Issue ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.
bugzilla-daemon at mindrot.org
2006-Dec-06 07:14 UTC
[Bug 1264] Channel not close by sshd Server
http://bugzilla.mindrot.org/show_bug.cgi?id=1264 djm at mindrot.org changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution| |FIXED ------- Comment #8 from djm at mindrot.org 2006-12-06 18:14 ------- Thanks for following up (BTW, the latest version of OpenSSH is 4.5p1 and it contains a minor security fix) ------- You are receiving this mail because: ------- You are the assignee for the bug, or are watching the assignee.