possible bug: OpenSSH appears to freeze on exit
Mark Reardon
mark.reardon at irl.xerox.com
Thu Jul 26 18:44:32 EST 2001
Hello,
I believe I may have discovered what appears to be a small anomoly in
the way
OpenSSH closes connections and thought if I gave you some feedback I
might
be able to make a very small contributution to the development of
openssh.
This might be a Solaris 2.6 anomoly or an openssh anomoly or a
combination of both.
I came across this apparent anomoly because we use openssh (via cron)
here
to check on our many Solaris boxes for archive logs filling up so we can
kick
off an archive log backup on the machine if needs be. It was noticed
after a
few days that cron began to behave strangely on the box that was ssh'ing
out
to all the servers. This was because cron had too many outstanding
processes
to kick off any more ( we would literally be doing hundreds of cron'd
ssh tasks
every hour ). It appears that openssh sometimes has trouble closing
connections
on Solaris. To try and get as much detail as possible I set up a simple
job
that continually ssh'd into a box and executed a command until it
finally froze.
It took literally hours for it to happen, but eventually it did. I also
hacked
around with the sshd code in a effort to be able to run sshd continually
in debug
mode to try and pick up any information there but this yielded no more
clues to
what the problem might be ( apart from pointing back to ssh closing
connections
on the Solaris client). Included below is the tail of the debug log on
the client.
last successful connection and then the freeze...
If I can provide any more information I will be glad to help.
Best Regards,
Mark Reardon
PS Many thanks for an excellent piece of software.
+ ssh -v -v -v xcalibur ps -ef | egrep '(arc0|arch)'_xitprd00 | grep -v
grep | wc -l
OpenSSH_2.9p2, SSH protocols 1.5/2.0, OpenSSL 0x0090601f
debug1: Reading configuration data //.ssh/config
debug1: Applying options for *
debug1: Reading configuration data /usr/local/etc/ssh_config
debug1: Applying options for *
debug1: Seeding random number generator
debug1: Rhosts Authentication disabled, originating port will not be
trusted.
debug1: restore_uid
debug1: ssh_connect: getuid 0 geteuid 0 anon 1
debug1: Connecting to xcalibur [13.219.48.22] port 22.
debug1: temporarily_use_uid: 0/1 (e=0)
debug1: restore_uid
debug1: temporarily_use_uid: 0/1 (e=0)
debug1: restore_uid
debug1: Connection established.
debug1: identity file //.ssh/identity type 0
debug3: No RSA1 key file //.ssh/id_dsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: no key found
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: no key found
debug1: identity file //.ssh/id_dsa type 2
debug1: identity file //.ssh/id_rsa1 type -1
debug1: identity file //.ssh/id_rsa2 type -1
debug1: Remote protocol version 1.99, remote software version
OpenSSH_2.9p2
debug1: match: OpenSSH_2.9p2 pat ^OpenSSH
Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_2.9p2
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
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: zlib
debug2: kex_parse_kexinit: zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-dss,ssh-rsa
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
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
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_init: found hmac-md5
debug1: kex: server->client aes128-cbc hmac-md5 zlib
debug2: mac_init: found hmac-md5
debug1: kex: client->server aes128-cbc hmac-md5 zlib
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: dh_gen_key: priv key bits set: 127/256
debug1: bits set: 1019/2049
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: check_host_in_hostfile: filename //.ssh/known_hosts2
debug3: check_host_in_hostfile: match line 195
debug3: check_host_in_hostfile: filename //.ssh/known_hosts2
debug3: key_read: type mismatch
debug3: check_host_in_hostfile: match line 195
debug1: Host 'xcalibur' is known and matches the RSA host key.
debug1: Found key in //.ssh/known_hosts2:195
debug1: bits set: 1017/2049
debug1: ssh_rsa_verify: signature correct
debug1: kex_derive_keys
debug1: newkeys: mode 1
debug1: Enabling compression at level 6.
debug1: SSH2_MSG_NEWKEYS sent
debug1: waiting for SSH2_MSG_NEWKEYS
debug1: newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: done: ssh_kex2.
debug1: send SSH2_MSG_SERVICE_REQUEST
debug1: service_accept: ssh-userauth
debug1: got SSH2_MSG_SERVICE_ACCEPT
debug1: authentications that can continue:
publickey,password,keyboard-interactive
debug3: start over, passed a different list
publickey,password,keyboard-interactive
debug3: preferred publickey,password,keyboard-interactive
debug3: authmethod_lookup publickey
debug3: remaining preferred: password,keyboard-interactive
debug3: authmethod_is_enabled publickey
debug1: next auth method to try is publickey
debug1: try pubkey: //.ssh/id_dsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: input_userauth_pk_ok: pkalg ssh-dss blen 434 lastkey 10ae98 hint
1
debug2: input_userauth_pk_ok: fp
b2:48:f6:61:cd:b8:d0:b5:58:85:95:be:7e:20:68:a8
debug3: sign_and_send_pubkey
debug1: read PEM private key done: type DSA
debug1: sig size 20 20
debug1: ssh-userauth2 successful: method publickey
debug1: fd 6 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug1: channel_new: 0
debug1: send channel open 0
debug1: Entering interactive session.
debug2: callback start
debug1: client_init id 0 arg 0
debug1: Sending command: ps -ef | egrep '(arc0|arch)'_xitprd00 | grep -v
grep | wc -l
debug2: callback done
debug1: channel 0: open confirm rwindow 0 rmax 16384
debug2: channel 0: rcvd adjust 32768
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: channel 0: rcvd eof
debug1: channel 0: output open -> drain
debug1: channel 0: rcvd close
debug1: channel 0: input open -> closed
debug1: channel 0: close_read
debug2: channel 0: no data after CLOSE
debug1: channel 0: obuf empty
debug1: channel 0: output drain -> closed
debug1: channel 0: close_write
debug1: channel 0: send close
debug1: channel 0: is dead
debug1: channel_free: channel 0: status: The following connections are
open:
#0 client-session (t4 r0 i8/0 o128/0 fd -1/-1)
debug1: channel_free: channel 0: dettaching channel user
debug1: Transferred: stdin 0, stdout 0, stderr 0 bytes in 0.3 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0
debug1: compress outgoing: raw data 1198, compressed 667, factor 0.56
debug1: compress incoming: raw data 592, compressed 580, factor 0.98
+ ssh -v -v -v xcalibur ps -ef | egrep '(arc0|arch)'_xitprd00 | grep -v
grep | wc -l
OpenSSH_2.9p2, SSH protocols 1.5/2.0, OpenSSL 0x0090601f
debug1: Reading configuration data //.ssh/config
debug1: Applying options for *
debug1: Reading configuration data /usr/local/etc/ssh_config
debug1: Applying options for *
debug1: Seeding random number generator
debug1: Rhosts Authentication disabled, originating port will not be
trusted.
debug1: restore_uid
debug1: ssh_connect: getuid 0 geteuid 0 anon 1
debug1: Connecting to xcalibur [13.219.48.22] port 22.
debug1: temporarily_use_uid: 0/1 (e=0)
debug1: restore_uid
debug1: temporarily_use_uid: 0/1 (e=0)
debug1: restore_uid
debug1: Connection established.
debug1: identity file //.ssh/identity type 0
debug3: No RSA1 key file //.ssh/id_dsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: no key found
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug3: key_read: no space
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: no key found
debug1: identity file //.ssh/id_dsa type 2
debug1: identity file //.ssh/id_rsa1 type -1
debug1: identity file //.ssh/id_rsa2 type -1
debug1: Remote protocol version 1.99, remote software version
OpenSSH_2.9p2
debug1: match: OpenSSH_2.9p2 pat ^OpenSSH
Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_2.9p2
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
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: zlib
debug2: kex_parse_kexinit: zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-dss,ssh-rsa
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,rijndael-cbc at lysator.liu.se
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
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_init: found hmac-md5
debug1: kex: server->client aes128-cbc hmac-md5 zlib
debug2: mac_init: found hmac-md5
debug1: kex: client->server aes128-cbc hmac-md5 zlib
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: dh_gen_key: priv key bits set: 134/256
debug1: bits set: 1009/2049
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: check_host_in_hostfile: filename //.ssh/known_hosts2
debug3: check_host_in_hostfile: match line 195
debug3: check_host_in_hostfile: filename //.ssh/known_hosts2
debug3: key_read: type mismatch
debug3: check_host_in_hostfile: match line 195
debug1: Host 'xcalibur' is known and matches the RSA host key.
debug1: Found key in //.ssh/known_hosts2:195
debug1: bits set: 1039/2049
debug1: ssh_rsa_verify: signature correct
debug1: kex_derive_keys
debug1: newkeys: mode 1
debug1: Enabling compression at level 6.
debug1: SSH2_MSG_NEWKEYS sent
debug1: waiting for SSH2_MSG_NEWKEYS
debug1: newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: done: ssh_kex2.
debug1: send SSH2_MSG_SERVICE_REQUEST
debug1: service_accept: ssh-userauth
debug1: got SSH2_MSG_SERVICE_ACCEPT
debug1: authentications that can continue:
publickey,password,keyboard-interactive
debug3: start over, passed a different list
publickey,password,keyboard-interactive
debug3: preferred publickey,password,keyboard-interactive
debug3: authmethod_lookup publickey
debug3: remaining preferred: password,keyboard-interactive
debug3: authmethod_is_enabled publickey
debug1: next auth method to try is publickey
debug1: try pubkey: //.ssh/id_dsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: input_userauth_pk_ok: pkalg ssh-dss blen 434 lastkey 10ae98 hint
1
debug2: input_userauth_pk_ok: fp
b2:48:f6:61:cd:b8:d0:b5:58:85:95:be:7e:20:68:a8
debug3: sign_and_send_pubkey
debug1: read PEM private key done: type DSA
debug1: sig size 20 20
debug1: ssh-userauth2 successful: method publickey
debug1: fd 6 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug1: channel_new: 0
debug1: send channel open 0
debug1: Entering interactive session.
debug2: callback start
debug1: client_init id 0 arg 0
debug1: Sending command: ps -ef | egrep '(arc0|arch)'_xitprd00 | grep -v
grep | wc -l
debug2: callback done
debug1: channel 0: open confirm rwindow 0 rmax 16384
debug2: channel 0: rcvd adjust 32768
debug1: channel 0: rcvd eof
debug1: channel 0: output open -> drain
debug1: channel 0: obuf empty
debug1: channel 0: output drain -> closed
debug1: channel 0: close_write
freeze happens here...( I have run this test lots of times and it always
freezes at exactly the same spot
- when it eventually does freeze )
On the server we are ssh'ing from ( next morninng there are a few
freezes overnight but not all are on host xcalibur )
> # ps -ef | grep ssh | grep -v sshd
> root 6202 6201 0 06:30:29 ? 0:00 ssh xcalibur df -k /oracle/u01/admin/xnnprd00/arch
> root 21855 21854 0 01:00:20 ? 0:00 ssh xcalibur du -sk /oracle/u01/admin/xdnprd00/arch
> root 21904 21903 0 16:45:41 ? 0:00 ssh xcalibur df -k /oracle/u01/admin/xvkprd00/arch
> root 27654 27653 0 01:15:38 ? 0:00 ssh xcalibur df -k /oracle/u01/admin/xunprd00/arch
> root 6857 6856 0 17:45:09 ? 0:00 ssh xcalibur df -k /oracle/u01/admin/xanprd00/arch
> root 25886 25885 0 15:00:40 ? 0:00 ssh xcalibur du -sk /oracle/u01/admin/xvkprd00/arch
> root 22924 22923 0 14:45:27 ? 0:00 ssh xcalibur du -sk /oracle/u01/admin/xitprd00/arch
> root 6335 6334 0 09:19:33 ? 0:00 /usr/local/bin/ssh -x -oFallBackToRsh no -C -4 monet scp -p -f /etc/hosts.allow
> root 25047 25026 0 08:20:56 pts/16 0:00 grep ssh
> root 22533 22393 0 08:13:13 pts/6 0:00 ssh middleware
> root 10348 10347 0 05:45:07 ? 0:00 ssh xesapbw df -k | grep saparch
> root 17284 17283 0 14:27:59 ? 0:00 ssh xcalibur du -sk /oracle/u01/admin/xunprd00/arch
> root 3007 3006 0 15:30:20 ? 0:00 ssh xcalibur df -k /oracle/u01/admin/xdnprd00/arch
> root 9024 8592 0 18:00:46 ? 0:00 ssh xesapdb1 grep '^tmproot' /etc/shadow | grep -v '*LK*'
> root 26020 2746 0 17:03:19 pts/17 0:00 ssh -v -v -v xcalibur ps -ef | egrep '(arc0|arch)'_xitprd00 | grep -v grep | wc
> root 13526 13525 0 06:00:22 ? 0:00 ssh xcalibur df -k /oracle/u01/admin/xenprd00/arch
> root 12757 12673 0 14:24:03 pts/2 0:01 ssh solar-2
> root 28679 28678 0 17:15:40 ? 0:00 ssh xcalibur df -k /oracle/u01/admin/xvkprd00/arch
> root 20119 40 0 07:55:18 pts/22 0:00 ssh devsrv1
> root 13956 13955 0 02:00:03 ? 0:00 ssh -v -v -v devsrv1 df -k | grep saparch
More information about the openssh-unix-dev
mailing list