Case where ssh hangs on exit with 2.9.9p2 on Sol8

[Ed Phillips]

Here's the appropriate output with blow-by-blow explanation embedded...

I start by making a connection with X11 forwarding enabled:

polycut:~> ssh -v -v -v -X dazel
OpenSSH_2.9.9p2, SSH protocols 1.5/2.0, OpenSSL 0x0090602f
debug1: Reading configuration data /opt/openssh-2.9.9p2/etc/ssh_config
debug3: Reading output from 'ls -alni /var/log'
debug3: Time elapsed: 23 msec
debug3: Got 2.00 bytes of entropy from 'ls -alni /var/log'
debug3: Reading output from 'ls -alni /var/adm'
debug3: Time elapsed: 26 msec
debug3: Got 2.00 bytes of entropy from 'ls -alni /var/adm'
debug3: Reading output from 'ls -alni /usr/adm'
debug3: Time elapsed: 16 msec
debug3: Got 0.18 bytes of entropy from 'ls -alni /usr/adm'
debug3: Reading output from 'ls -alni /var/mail'
debug3: Time elapsed: 18 msec
debug3: Got 0.71 bytes of entropy from 'ls -alni /var/mail'
debug3: Reading output from 'ls -alni /usr/mail'
debug3: Time elapsed: 16 msec
debug3: Got 0.18 bytes of entropy from 'ls -alni /usr/mail'
debug3: Reading output from 'ls -alni /proc'
debug3: Time elapsed: 60 msec
debug3: Got 2.00 bytes of entropy from 'ls -alni /proc'
debug3: Reading output from 'ls -alni /tmp'
debug3: Time elapsed: 26 msec
debug3: Got 2.00 bytes of entropy from 'ls -alni /tmp'
debug3: Reading output from 'ls -alni /var/tmp'
debug3: Time elapsed: 113 msec
debug3: Got 2.00 bytes of entropy from 'ls -alni /var/tmp'
debug3: Reading output from 'ls -alni /usr/tmp'
debug3: Time elapsed: 16 msec
debug3: Got 0.18 bytes of entropy from 'ls -alni /usr/tmp'
debug3: Reading output from 'netstat -an'
debug3: Time elapsed: 37 msec
debug3: Got 2.00 bytes of entropy from 'netstat -an'
debug3: Reading output from 'netstat -in'
debug3: Time elapsed: 34 msec
debug3: Got 2.00 bytes of entropy from 'netstat -in'
debug3: Reading output from 'netstat -rn'
debug3: Time elapsed: 34 msec
debug3: Got 1.84 bytes of entropy from 'netstat -rn'
debug3: Reading output from 'netstat -pn'
debug3: Time elapsed: 43 msec
debug3: Got 2.00 bytes of entropy from 'netstat -pn'
debug3: Reading output from 'netstat -ia'
debug3: Time elapsed: 43 msec
debug3: Got 2.00 bytes of entropy from 'netstat -ia'
debug3: Reading output from 'netstat -s'
debug3: Time elapsed: 38 msec
debug3: Got 2.00 bytes of entropy from 'netstat -s'
debug3: Reading output from 'netstat -is'
debug3: Time elapsed: 45 msec
debug3: Got 2.00 bytes of entropy from 'netstat -is'
debug3: Reading output from 'arp -a -n'
debug3: Time elapsed: 156 msec
debug3: Got 2.00 bytes of entropy from 'arp -a -n'
debug3: Reading output from 'ifconfig -a'
debug3: Time elapsed: 185 msec
debug3: Got 0.86 bytes of entropy from 'ifconfig -a'
debug3: Reading output from 'ps -al'
debug3: Time elapsed: 46 msec
debug3: Got 2.00 bytes of entropy from 'ps -al'
debug3: Reading output from 'ps -efl'
debug3: Time elapsed: 98 msec
debug3: Got 2.00 bytes of entropy from 'ps -efl'
debug3: Reading output from 'w'
debug3: Time elapsed: 75 msec
debug3: Got 2.00 bytes of entropy from 'w'
debug3: Reading output from 'last'
debug3: Time elapsed: 186 msec
debug2: Command 'last' timed out
debug3: Got 2.00 bytes of entropy from 'last'
debug3: Reading output from 'df'
debug3: Time elapsed: 22 msec
debug3: Got 0.71 bytes of entropy from 'df'
debug3: Reading output from 'vmstat'
debug3: Time elapsed: 20 msec
debug3: Got 0.23 bytes of entropy from 'vmstat'
debug3: Reading output from 'uptime'
debug3: Time elapsed: 29 msec
debug3: Got 0.07 bytes of entropy from 'uptime'
debug3: Reading output from 'ipcs -a'
debug3: Time elapsed: 251 msec
debug2: Command 'ipcs -a' timed out
debug3: Got 0.00 bytes of entropy from 'ipcs -a'
debug3: Reading output from 'tail -200 /var/log/syslog'
debug3: Time elapsed: 14 msec
debug3: Got 0.00 bytes of entropy from 'tail -200 /var/log/syslog'
debug3: Reading output from 'tail -200 /var/adm/messages'
debug3: Time elapsed: 16 msec
debug3: Got 2.00 bytes of entropy from 'tail -200 /var/adm/messages'
debug1: Seeded RNG with 47 bytes from programs
debug1: Seeded RNG with 3 bytes from system calls
debug1: Rhosts Authentication disabled, originating port will not be
trusted.
debug1: restore_uid
debug1: ssh_connect: getuid 16476 geteuid 0 anon 1
debug1: Connecting to dazel [128.175.13.68] port 22.
debug1: temporarily_use_uid: 16476/10 (e=0)
debug1: restore_uid
debug1: temporarily_use_uid: 16476/10 (e=0)
debug1: restore_uid
debug1: Connection established.
debug1: read PEM private key done: type RSA
debug1: identity file /home/polycut.nss/usra/ed/.ssh/identity type 0
debug3: No RSA1 key file /home/polycut.nss/usra/ed/.ssh/id_rsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: no key found
debug2: key_type_from_name: unknown key type 'Proc-Type:'
debug3: key_read: no key found
debug2: key_type_from_name: unknown key type 'DEK-Info:'
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
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 /home/polycut.nss/usra/ed/.ssh/id_rsa type 1
debug1: identity file /home/polycut.nss/usra/ed/.ssh/id_dsa type -1
debug1: Remote protocol version 1.99, remote software version
OpenSSH_2.9.9p2
debug1: match: OpenSSH_2.9.9p2 pat ^OpenSSH
Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_2.9.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: 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: 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: 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 none
debug2: mac_init: found hmac-md5
debug1: kex: client->server aes128-cbc hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: dh_gen_key: priv key bits set: 115/256
debug1: bits set: 1613/3191
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: check_host_in_hostfile: filename
/home/polycut.nss/usra/ed/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 1
debug3: check_host_in_hostfile: filename
/home/polycut.nss/usra/ed/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 1
debug1: Host 'dazel' is known and matches the RSA host key.
debug1: Found key in /home/polycut.nss/usra/ed/.ssh/known_hosts:1
debug1: bits set: 1603/3191
debug1: ssh_rsa_verify: signature correct
debug1: kex_derive_keys
debug1: newkeys: mode 1
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,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: next auth method to try is publickey
debug1: userauth_pubkey_agent: testing agent key
/home/polycut.nss/usra/ed/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: input_userauth_pk_ok: pkalg ssh-rsa blen 149 lastkey 145480 hint
-1
debug2: input_userauth_pk_ok: fp
f7:19:b1:e8:56:1c:81:55:44:9b:b4:f7:e1:b0:c8:ca
debug3: sign_and_send_pubkey
debug3: clear_auth_state: key_free 145480
debug1: ssh-userauth2 successful: method publickey
debug3: clear hostkey 0
debug3: clear hostkey 2
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug1: send channel open 0
debug1: Entering interactive session.
debug2: callback start
debug1: ssh_session2_setup: id 0
debug3: tty_make_modes: ospeed 9600
debug3: tty_make_modes: ispeed 9600
debug3: tty_make_modes: 1 3
debug3: tty_make_modes: 2 28
debug3: tty_make_modes: 3 8
debug3: tty_make_modes: 4 21
debug3: tty_make_modes: 5 4
debug3: tty_make_modes: 6 0
debug3: tty_make_modes: 7 0
debug3: tty_make_modes: 8 17
debug3: tty_make_modes: 9 19
debug3: tty_make_modes: 10 26
debug3: tty_make_modes: 11 25
debug3: tty_make_modes: 12 18
debug3: tty_make_modes: 13 23
debug3: tty_make_modes: 14 22
debug3: tty_make_modes: 16 0
debug3: tty_make_modes: 18 15
debug3: tty_make_modes: 30 0
debug3: tty_make_modes: 31 0
debug3: tty_make_modes: 32 0
debug3: tty_make_modes: 33 0
debug3: tty_make_modes: 34 0
debug3: tty_make_modes: 35 0
debug3: tty_make_modes: 36 1
debug3: tty_make_modes: 37 0
debug3: tty_make_modes: 38 1
debug3: tty_make_modes: 39 0
debug3: tty_make_modes: 40 1
debug3: tty_make_modes: 41 0
debug3: tty_make_modes: 50 1
debug3: tty_make_modes: 51 1
debug3: tty_make_modes: 52 0
debug3: tty_make_modes: 53 1
debug3: tty_make_modes: 54 1
debug3: tty_make_modes: 55 1
debug3: tty_make_modes: 56 0
debug3: tty_make_modes: 57 0
debug3: tty_make_modes: 58 0
debug3: tty_make_modes: 59 1
debug3: tty_make_modes: 60 1
debug3: tty_make_modes: 61 1
debug3: tty_make_modes: 62 0
debug3: tty_make_modes: 70 1
debug3: tty_make_modes: 71 0
debug3: tty_make_modes: 72 1
debug3: tty_make_modes: 73 0
debug3: tty_make_modes: 74 0
debug3: tty_make_modes: 75 0
debug3: tty_make_modes: 90 1
debug3: tty_make_modes: 91 1
debug3: tty_make_modes: 92 0
debug3: tty_make_modes: 93 1
debug1: Requesting X11 forwarding with authentication spoofing.
debug1: channel request 0: shell
debug2: callback done
debug1: channel 0: open confirm rwindow 0 rmax 16384
debug2: channel 0: rcvd adjust 32768
Last login: Thu Nov 15 16:03:46 2001 from polycut.nss.ude
Sun Microsystems Inc.   SunOS 5.8       Generic February 2000
/usr/openwin/bin/xauth:  creating new authority file
/opt/home/ed/.Xauthority
Sun Microsystems Inc.   SunOS 5.8       Generic February 2000

(Side note: in this case, it's using my ~/.Xauthority file - but when I
connect from 2.9.9p2 to v2.9p1 it uses /tmp/ssh-XXXXXXXX/cookies)

Okay, now that I have a shell, I make an X11 request from another shell
with a contrived cookie (that is invalid) and set the DISPLAY to be the
same DISPLAY that was created by this ssh session...

debug1: client_input_channel_open: ctype x11 rchan 3 win 4096 max 2048
debug1: client_request_x11: request from 128.175.13.160 46799
debug1: fd 10 setting O_NONBLOCK
debug2: fd 10 is O_NONBLOCK
debug1: channel 1: new [x11]
debug1: confirm x11
debug1: X11 connection uses different authentication protocol.
debug1: X11 rejected 1 i1/o16
debug1: channel 1: read failed
debug1: channel 1: input open -> drain
debug1: channel 1: close_read
debug1: channel 1: write failed
debug1: channel 1: output open -> closed
debug1: channel 1: close_write
debug1: X11 closed 1 i2/o128
debug1: channel 1: rcvd eof
debug1: channel 1: FORCE input drain

Then I press CTRL-D on the client...

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
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
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: send close
debug1: channel 0: is dead
debug1: channel_free: channel 0: client-session, nchannels 2
debug3: channel_free: status: The following connections are open:
  #0 client-session (t4 r0 i8/0 o128/0 fd -1/-1)
  #1 x11 (t7 r3 i2/0 o128/0 fd 10/10)

debug1: channel_free: channel 0: detaching channel user
debug3: channel_close_fds: channel 0: r -1 w -1 e 9

At this point, the ssh client is hung and I can hit CTRL-C to get it to
exit...

^Cdebug1: channel_free: channel 1: x11, nchannels 1
debug3: channel_free: status: The following connections are open:
  #1 x11 (t7 r3 i2/0 o128/0 fd 10/10)

debug3: channel_close_fds: channel 1: r 10 w 10 e -1
Killed by signal 2.
debug1: Calling cleanup 0x3dfa0(0x0)
debug1: Calling cleanup 0x531d8(0x0)
debug1: Calling cleanup 0x5cba0(0x0)
debug1: writing PRNG seed to file /home/polycut.nss/usra/ed/.ssh/prng_seed
polycut:~>

Can someone verify this with 3.0pX?

Thanks,

	Ed

Ed Phillips <ed at udel.edu> University of Delaware (302) 831-6082
Systems Programmer III, Network and Systems Services
finger -l ed at polycut.nss.udel.edu for PGP public key