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.