My SSH sessions take a very long time to initiate. This applies for logins with and without passwords, interactive and non-interactive. I have tried setting 'GSSAPIAuthentication no' and 'IPQoS 0x00' on the client side, and 'UseDNS no' on the server side, but no dice. I'm really stumped and frustrated. The worst part is that it SFTP takes forever to establish connections too, making file transfer much longer than it would be otherwise.
I thought the problem might be something with PAM, because of where the hang is in the sshd log below, so I tried commenting out each line one-by-one in the /etc/pam.d/sshd file. Some caused login to be impossible, some had no apparent effect. I can't really tell if PAM is stalling for other services, but I can say that su'ing into my account from another account with 'su -l' has no apparent delay. I tried creating a new user account, just to see if there was something wrong with my existing account, and the same problem persisted. Any ideas of what's going on?
On the client side, the most verbose mode outputs (redacted where reasonable):
OpenSSH_5.9p1, OpenSSL 0.9.8r 8 Feb 2011
debug1: Reading configuration data ...
debug1: ... line 1: Applying options for ...
debug1: Reading configuration data /etc/ssh_config
debug1: /etc/ssh_config line 20: Applying options for *
debug1: /etc/ssh_config line 53: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to ... [x.x.x.x] port 22.
debug1: Connection established.
debug1: identity file /.../.ssh/id_rsa type -1
debug1: identity file /.../.ssh/id_rsa-cert type -1
debug3: Incorrect RSA1 identifier
debug3: Could not load "/.../.ssh/id_dsa" as a RSA1 public key
debug1: identity file /.../.ssh/id_dsa type 2
debug1: identity file /.../.ssh/id_dsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.2
debug1: match: OpenSSH_5.2 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.9
debug2: fd 3 setting O_NONBLOCK
debug3: load_hostkeys: loading entries for host "..." from file "/.../.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /.../.ssh/known_hosts:9
debug3: load_hostkeys: loaded 1 keys
debug3: order_hostkeyalgs: prefer hostkeyalgs:
[email protected],
[email protected],ssh-rsa
debug1: SSH2_MSG_KEXINIT sent
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:
[email protected],
[email protected],ssh-rsa,
[email protected],
[email protected],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,
[email protected].
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,
[email protected].
se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,
[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,
[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,
[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,
[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,
[email protected],zlib
debug2: kex_parse_kexinit: none,
[email protected],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,
[email protected].
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,
[email protected].
se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,
[email protected],hmac-ripemd160,
[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,
[email protected],hmac-ripemd160,
[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,
[email protected]
debug2: kex_parse_kexinit: none,
[email protected]
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
debug2: dh_gen_key: priv key bits set: 136/256
debug2: bits set: 523/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: RSA ...
debug3: load_hostkeys: loading entries for host "..." from file "/.../.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /.../.ssh/known_hosts:9
debug3: load_hostkeys: loaded 1 keys
debug3: load_hostkeys: loading entries for host "x.x.x.x" from file "/.../.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /.../.ssh/known_hosts:9
debug3: load_hostkeys: loaded 1 keys
debug1: Host '...' is known and matches the RSA host key.
debug1: Found key in /.../.ssh/known_hosts:9
debug2: bits set: 492/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
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /.../.ssh/id_dsa (0x7f8b7b41d6c0)
debug2: key: /.../.ssh/id_rsa (0x0)
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 authentication method: publickey
debug1: Offering DSA public key: /.../.ssh/id_dsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-dss blen 434
debug2: input_userauth_pk_ok: fp ...
debug3: sign_and_send_pubkey: DSA ...
debug1: Authentication succeeded (publickey).
Authenticated to ... ([x.x.x.x]:22).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting
[email protected]
debug1: Entering interactive session.
****** Hangs here ******
debug2: callback start
debug2: client_session2_setup: id 0
debug2: fd 3 setting TCP_NODELAY
debug2: channel 0: request pty-req confirm 1
debug1: Sending environment.
debug3: Ignored env TERM_PROGRAM
debug3: Ignored env SHELL
debug3: Ignored env TERM
debug3: Ignored env TMPDIR
debug3: Ignored env Apple_PubSub_Socket_Render
debug3: Ignored env TERM_PROGRAM_VERSION
debug3: Ignored env TERM_SESSION_ID
debug3: Ignored env USER
debug3: Ignored env COMMAND_MODE
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env Apple_Ubiquity_Message
debug3: Ignored env __CF_USER_TEXT_ENCODING
debug3: Ignored env PATH
debug3: Ignored env MKL_NUM_THREADS
debug3: Ignored env PWD
debug1: Sending env LANG = en_US.UTF-8
debug2: channel 0: request env confirm 0
debug3: Ignored env HOME
debug3: Ignored env SHLVL
debug3: Ignored env DYLD_LIBRARY_PATH
debug3: Ignored env PYTHONPATH
debug3: Ignored env LOGNAME
debug3: Ignored env DISPLAY
debug3: Ignored env SECURITYSESSIONID
debug3: Ignored env _
debug2: channel 0: request shell confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
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
On the server side, the debug output looks like:
Sep 16 18:46:40 ... sshd[31435]: debug1: inetd sockets after dupping: 3, 4
Sep 16 18:46:40 ... sshd[31435]: Connection from x.x.x.x port 52758
Sep 16 18:46:40 ... sshd[31435]: debug1: Current Session ID is 56AC0FB0 / Session Attributes are 00008000
Sep 16 18:46:40 ... sshd[31435]: debug1: Running in inetd mode in a non-root session... assuming inetd created the session for us.
Sep 16 18:46:40 ... sshd[31435]: debug1: Client protocol version 2.0; client software version OpenSSH_5.9
Sep 16 18:46:40 ... sshd[31435]: debug1: match: OpenSSH_5.9 pat OpenSSH*
Sep 16 18:46:40 ... sshd[31435]: debug1: Enabling compatibility mode for protocol 2.0
Sep 16 18:46:40 ... sshd[31435]: debug1: Local version string SSH-2.0-OpenSSH_5.2
Sep 16 18:46:40 ... sshd[31435]: debug1: Checking with Service ACLs for ssh login restrictions
Sep 16 18:46:40 ... sshd[31435]: debug1: call to mbr_user_name_to_uuid with <...> suceeded to retrieve user_uuid
Sep 16 18:46:40 ... sshd[31435]: debug1: Call to mbr_check_service_membership failed with status <0>
Sep 16 18:46:40 ... sshd[31435]: debug1: PAM: initializing for "..."
Sep 16 18:46:40 ... sshd[31435]: debug1: PAM: setting PAM_RHOST to "x.x.x.x"
Sep 16 18:46:40 ... sshd[31435]: Failed none for ... from x.x.x.x port 52758 ssh2
Sep 16 18:46:40 ... sshd[31435]: debug1: temporarily_use_uid: 509/20 (e=0/0)
Sep 16 18:46:40 ... sshd[31435]: debug1: trying public key file /.../.ssh/authorized_keys
Sep 16 18:46:40 ... sshd[31435]: debug1: restore_uid: 0/0
Sep 16 18:46:40 ... sshd[31435]: debug1: temporarily_use_uid: 509/20 (e=0/0)
Sep 16 18:46:40 ... sshd[31435]: debug1: trying public key file /.../.ssh/authorized_keys2
Sep 16 18:46:40 ... sshd[31435]: debug1: fd 5 clearing O_NONBLOCK
Sep 16 18:46:40 ... sshd[31435]: debug1: matching key found: file /.../.ssh/authorized_keys2, line 1
Sep 16 18:46:40 ... sshd[31435]: Found matching DSA key: ...
Sep 16 18:46:40 ... sshd[31435]: debug1: restore_uid: 0/0
Sep 16 18:46:40 ... sshd[31435]: debug1: temporarily_use_uid: 509/20 (e=0/0)
Sep 16 18:46:40 ... sshd[31435]: debug1: trying public key file /.../.ssh/authorized_keys
Sep 16 18:46:40 ... sshd[31435]: debug1: restore_uid: 0/0
Sep 16 18:46:40 ... sshd[31435]: debug1: temporarily_use_uid: 509/20 (e=0/0)
Sep 16 18:46:40 ... sshd[31435]: debug1: trying public key file /.../.ssh/authorized_keys2
Sep 16 18:46:40 ... sshd[31435]: debug1: fd 5 clearing O_NONBLOCK
Sep 16 18:46:40 ... sshd[31435]: debug1: matching key found: file /.../.ssh/authorized_keys2, line 1
Sep 16 18:46:40 ... sshd[31435]: Found matching DSA key: ...
Sep 16 18:46:40 ... sshd[31435]: debug1: restore_uid: 0/0
Sep 16 18:46:40 ... sshd[31435]: debug1: ssh_dss_verify: signature correct
Sep 16 18:46:40 ... sshd[31435]: debug1: do_pam_account: called
Sep 16 18:46:40 ... sshd[31435]: Accepted publickey for ... from x.x.x.x port 52758 ssh2
Sep 16 18:46:40 ... sshd[31435]: debug1: monitor_child_preauth: ... has been authenticated by privileged process
Sep 16 18:46:40 ... sshd[31435]: debug1: PAM: establishing credentials
***** Hangs here *****
Sep 16 18:46:54 ... sshd[31435]: User child is on pid 31654
Sep 16 18:46:54 ... sshd[31654]: debug1: PAM: establishing credentials
Sep 16 18:46:54 ... sshd[31654]: debug1: permanently_set_uid: 509/20
Sep 16 18:46:54 ... sshd[31654]: debug1: Entering interactive session for SSH2.
Sep 16 18:46:54 ... sshd[31654]: debug1: server_init_dispatch_20
Sep 16 18:46:54 ... sshd[31654]: debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
Sep 16 18:46:54 ... sshd[31654]: debug1: input_session_request
Sep 16 18:46:54 ... sshd[31654]: debug1: channel 0: new [server-session]
Sep 16 18:46:54 ... sshd[31654]: debug1: session_new: session 0
Sep 16 18:46:54 ... sshd[31654]: debug1: session_open: channel 0
Sep 16 18:46:54 ... sshd[31654]: debug1: session_open: session 0: link with channel 0
Sep 16 18:46:54 ... sshd[31654]: debug1: server_input_channel_open: confirm session
Sep 16 18:46:54 ... sshd[31654]: debug1: server_input_global_request: rtype
[email protected] want_reply 0
Sep 16 18:46:54 ... sshd[31654]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Sep 16 18:46:54 ... sshd[31654]: debug1: session_by_channel: session 0 channel 0
Sep 16 18:46:54 ... sshd[31654]: debug1: session_input_channel_req: session 0 req pty-req
Sep 16 18:46:54 ... sshd[31654]: debug1: Allocating pty.
Sep 16 18:46:54 ... sshd[31435]: debug1: session_new: session 0
Sep 16 18:46:54 ... sshd[31654]: debug1: session_pty_req: session 0 alloc /dev/ttys008
Sep 16 18:46:54 ... sshd[31654]: debug1: server_input_channel_req: channel 0 request env reply 0
Sep 16 18:46:54 ... sshd[31654]: debug1: session_by_channel: session 0 channel 0
Sep 16 18:46:54 ... sshd[31654]: debug1: session_input_channel_req: session 0 req env
Sep 16 18:46:54 ... sshd[31654]: debug1: server_input_channel_req: channel 0 request shell reply 1
Sep 16 18:46:54 ... sshd[31654]: debug1: session_by_channel: session 0 channel 0
Sep 16 18:46:54 ... sshd[31654]: debug1: session_input_channel_req: session 0 req shell
Sep 16 18:46:54 ... sshd[31655]: debug1: Setting controlling tty using TIOCSCTTY.
