intermittent problems obtaining shell with gssapi-with-mic

[Jonathan Underwood]

Hi,

I am seeing a rather strange issue with openssh-5.3p1 (both client and
server) under scientific linux 6. The systems in question are set up
to authenticate against a Kerberos server. ssh'ing between machines
works fine 99% of the time with the gssapi-with-mic method. But on
occasion an ssh session will fail to spawn a sheel for the user after
authentication. An example -vvv output in this situation is below:

$ ssh -vvv callista
OpenSSH_5.3p1, OpenSSL 1.0.0-fips 29 Mar 2010
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to callista [128.40.5.73] port 22.
debug1: Connection established.
debug1: identity file /home/jgu/.ssh/identity type -1
debug1: identity file /home/jgu/.ssh/id_rsa type -1
debug1: identity file /home/jgu/.ssh/id_dsa type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.3
debug1: match: OpenSSH_5.3 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.3
debug2: fd 4 setting O_NONBLOCK
debug1: SSH2_MSG_KEXINIT sent
debug3: Wrote 792 bytes for a total of 813
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha256,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-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib at openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib at openssh.com,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-sha256,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-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,umac-64 at openssh.com,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: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug3: Wrote 24 bytes for a total of 837
debug2: dh_gen_key: priv key bits set: 140/256
debug2: bits set: 537/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: Wrote 144 bytes for a total of 981
debug3: check_host_in_hostfile: filename /home/jgu/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 11
debug3: check_host_in_hostfile: filename /home/jgu/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 11
debug1: Host 'callista' is known and matches the RSA host key.
debug1: Found key in /home/jgu/.ssh/known_hosts:11
debug2: bits set: 511/1024
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: Wrote 16 bytes for a total of 997
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug3: Wrote 48 bytes for a total of 1045
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /home/jgu/.ssh/identity ((nil))
debug2: key: /home/jgu/.ssh/id_rsa ((nil))
debug2: key: /home/jgu/.ssh/id_dsa ((nil))
debug3: Wrote 64 bytes for a total of 1109
debug1: Authentications that can continue:
publickey,gssapi-keyex,gssapi-with-mic,password
debug3: start over, passed a different list
publickey,gssapi-keyex,gssapi-with-mic,password
debug3: preferred
gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-keyex
debug3: remaining preferred:
gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-keyex
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug2: we did not send a packet, disable method
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug3: Trying to reverse map address 128.40.5.73.
debug2: we sent a gssapi-with-mic packet, wait for reply
debug3: Wrote 96 bytes for a total of 1205
debug3: Wrote 704 bytes for a total of 1909
debug3: Wrote 64 bytes for a total of 1973
debug1: Authentication succeeded (gssapi-with-mic).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting no-more-sessions at openssh.com
debug1: Entering interactive session.
debug3: Wrote 128 bytes for a total of 2101
debug2: callback start
debug2: client_session2_setup: id 0
debug2: channel 0: request pty-req confirm 1
debug1: Sending environment.
debug3: Ignored env MKLROOT
debug3: Ignored env MANPATH
debug3: Ignored env ORBIT_SOCKETDIR
debug3: Ignored env HOSTNAME
debug3: Ignored env IMSETTINGS_INTEGRATE_DESKTOP
debug3: Ignored env INTEL_LICENSE_FILE
debug3: Ignored env GPG_AGENT_INFO
debug3: Ignored env SHELL
debug3: Ignored env TERM
debug3: Ignored env HISTSIZE
debug3: Ignored env XDG_SESSION_COOKIE
debug3: Ignored env LIBRARY_PATH
debug3: Ignored env GTK_RC_FILES
debug3: Ignored env WINDOWID
debug3: Ignored env FPATH
debug3: Ignored env QTDIR
debug3: Ignored env QTINC
debug3: Ignored env IMSETTINGS_MODULE
debug3: Ignored env USER
debug3: Ignored env LS_COLORS
debug3: Ignored env LD_LIBRARY_PATH
debug3: Ignored env CPATH
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env GNOME_KEYRING_SOCKET
debug3: Ignored env COBBLER_SERVER
debug3: Ignored env USERNAME
debug3: Ignored env SESSION_MANAGER
debug3: Ignored env NLSPATH
debug3: Ignored env PATH
debug3: Ignored env DESKTOP_SESSION
debug3: Ignored env MAIL
debug3: Ignored env QT_IM_MODULE
debug3: Ignored env PWD
debug1: Sending env XMODIFIERS = @im=none
debug2: channel 0: request env confirm 0
debug3: Ignored env GDM_KEYBOARD_LAYOUT
debug3: Ignored env KDE_IS_PRELINKED
debug1: Sending env LANG = en_GB.utf8
debug2: channel 0: request env confirm 0
debug3: Ignored env GNOME_KEYRING_PID
debug3: Ignored env GDM_LANG
debug3: Ignored env MODULEPATH
debug3: Ignored env LOADEDMODULES
debug3: Ignored env KDEDIRS
debug3: Ignored env GDMSESSION
debug3: Ignored env HISTCONTROL
debug3: Ignored env KRB5CCNAME
debug3: Ignored env SSH_ASKPASS
debug3: Ignored env HOME
debug3: Ignored env SHLVL
debug3: Ignored env GNOME_DESKTOP_SESSION_ID
debug3: Ignored env LOGNAME
debug3: Ignored env CVS_RSH
debug3: Ignored env QTLIB
debug3: Ignored env DBUS_SESSION_BUS_ADDRESS
debug3: Ignored env MODULESHOME
debug3: Ignored env LESSOPEN
debug3: Ignored env WINDOWPATH
debug3: Ignored env DISPLAY
debug3: Ignored env INCLUDE
debug3: Ignored env G_BROKEN_FILENAMES
debug3: Ignored env XAUTHORITY
debug3: Ignored env COLORTERM
debug3: Ignored env module
debug3: Ignored env _
debug2: channel 0: request shell confirm 1
debug2: fd 4 setting TCP_NODELAY
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug3: Wrote 512 bytes for a total of 2613
debug2: channel_input_status_confirm: type 99 id 0
debug2: PTY allocation request accepted on channel 0
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: shell request accepted on channel 0

At this point the session hangs seemingly forever and a command prompt
never appears. When I see this issue, it isn't resolved by restarting
the sshd server, and it continues to be an issue if I kill the session
and start again. However, if I then do a

ssh -o GSSAPIAuthentication=no callista

I enter the password and log in successfully, as expected.
Subsequently if I disconnect, and then retry without
GSSAPIAuthentication=no everything is fine again.

I am having a hard time with debugging this any further, any advice
would be happily received.

Please cc me on any responses as I am not subscribed to the list.

Thanks in advance,
Jonathan.