Markus Friedl wrote:> > ?'m not sure where the 'bug' is and whether this is 'really' a bug. > > try to talk to the openssh-unix-dev list, i'm too busy right now :( > > -m > > On Thu, Aug 16, 2001 at 03:51:19PM +0100, Mark Reardon wrote: > > Hello Markus, > > > > I recently posted you with a mention of the 2.9p2 possible problem with > > Solaris 2.6 - 8. > > > > Just forwarding on other feedback that users are sending me regarding my > > original posting to the mailing list. > > > > If there is any way at all I can help [ including go away :) ] please do > > not hesitate to mail me. > > > > Rgds, > > > > Mark > > > > "Hull, Deron" wrote: > > > > > > Mark, > > > > > > We have the exact same problem with ssh hanging if called from a cron job. > > > We're also running solaris 2.6 at the server but I'm calling ssh from a cron > > > job on a 2.8 box > > > Both are openssh 2.9p2. The only thing I did in the configure script was to > > > include --with-pam. > > > We would have used 2.9p1 but X forwarding was broken on our 2.6 boxes by it. > > > It was creating a directory under tmp (for mit cookie ) with permissions of > > > 600 even though truss showed it attempting to do a mkdir of 0700. ??? umask > > > problem? > > > > > > I'd be very interested to hear if there was any resolution to this problem. > > > Haven't seen anything on the mailing list. > > > I'm going to talk to one of our C programmers that has made custom changes > > > to openssh for us in the past. > > > > > > Please let me know if you hear anything. > > > > > > Thanks > > > > > > Deron Hull> > 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
mouring at etoh.eviladmin.org
2001-Aug-22 14:41 UTC
[Fwd: [Fwd: openssh 2.9p2 hang problem]]
If it's a problem with ssh it does not seem to affect scp. I do scp multiple times a day from Solaris 7 to Solaris 2.5.1 in cron with no problems. Have you tried doing ssh -n to see if that stops it from happening? I just setup a test here at work using 'ssh' instead of scp. And I'll see if I can reproduce it. Off hand it looks a lot like when ssh hangs on background processes on some platforms. - Ben On Wed, 22 Aug 2001, Mark Reardon wrote:> Markus Friedl wrote: > > > > ?'m not sure where the 'bug' is and whether this is 'really' a bug. > > > > try to talk to the openssh-unix-dev list, i'm too busy right now :( > > > > -m > > > > On Thu, Aug 16, 2001 at 03:51:19PM +0100, Mark Reardon wrote: > > > Hello Markus, > > > > > > I recently posted you with a mention of the 2.9p2 possible problem with > > > Solaris 2.6 - 8. > > > > > > Just forwarding on other feedback that users are sending me regarding my > > > original posting to the mailing list. > > > > > > If there is any way at all I can help [ including go away :) ] please do > > > not hesitate to mail me. > > > > > > Rgds, > > > > > > Mark > > > > > > "Hull, Deron" wrote: > > > > > > > > Mark, > > > > > > > > We have the exact same problem with ssh hanging if called from a cron job. > > > > We're also running solaris 2.6 at the server but I'm calling ssh from a cron > > > > job on a 2.8 box > > > > Both are openssh 2.9p2. The only thing I did in the configure script was to > > > > include --with-pam. > > > > We would have used 2.9p1 but X forwarding was broken on our 2.6 boxes by it. > > > > It was creating a directory under tmp (for mit cookie ) with permissions of > > > > 600 even though truss showed it attempting to do a mkdir of 0700. ??? umask > > > > problem? > > > > > > > > I'd be very interested to hear if there was any resolution to this problem. > > > > Haven't seen anything on the mailing list. > > > > I'm going to talk to one of our C programmers that has made custom changes > > > > to openssh for us in the past. > > > > > > > > Please let me know if you hear anything. > > > > > > > > Thanks > > > > > > > > Deron Hull > > > > > > 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 >