[CentOS] how to debug ssh slow connection issues.

Fri May 23 17:53:44 UTC 2008
Jason Pyeron <jpyeron at pdinc.us>


> -----Original Message-----
> From: centos-bounces at centos.org [mailto:centos-bounces at centos.org] On
> Behalf Of Paul Heinlein
> Sent: Friday, May 23, 2008 1:06 PM
> 
> 
> When sshd looks to be the culprit, my troubleshooting begins by
> launching it in foreground mode on a non-standard port on the server:
> 
>    sshd -ddd -p 2222
> 

Will snip in reply to this. Putting it in full just in case.

[root at 192.168.1.21 ~]# /usr/sbin/sshd -ddd -p 22222
debug2: load_server_config: filename /etc/ssh/sshd_config
debug2: load_server_config: done config len = 191
debug2: parse_server_config: config /etc/ssh/sshd_config len 191
debug3: /etc/ssh/sshd_config:86 setting UsePAM yes
debug3: /etc/ssh/sshd_config:89 setting GatewayPorts yes
debug3: /etc/ssh/sshd_config:111 setting Subsystem sftp
/usr/libexec/openssh/sftp-server
debug1: sshd version OpenSSH_4.6p1
debug1: private host key: #0 type 0 RSA1
debug3: Not a RSA1 key file /etc/ssh/ssh_host_rsa_key.
debug1: read PEM private key done: type RSA
debug1: private host key: #1 type 1 RSA
debug3: Not a RSA1 key file /etc/ssh/ssh_host_dsa_key.
debug1: read PEM private key done: type DSA
debug1: private host key: #2 type 2 DSA
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-ddd'
debug1: rexec_argv[2]='-p'
debug1: rexec_argv[3]='22222'
debug2: fd 3 setting O_NONBLOCK
debug1: Bind to port 22222 on ::.
Server listening on :: port 22222.
debug2: fd 4 setting O_NONBLOCK
debug1: Bind to port 22222 on 0.0.0.0.
Bind to port 22222 on 0.0.0.0 failed: Address already in use.
Generating 768 bit RSA key.
RSA key generation complete.
debug3: fd 4 is not O_NONBLOCK
debug1: Server will not fork when running in debugging mode.
debug3: send_rexec_state: entering fd = 7 config len 191
debug3: ssh_msg_send: type 0
debug3: send_rexec_state: done
debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7
debug1: inetd sockets after dupping: 3, 3
debug3: Normalising mapped IPv4 in IPv6 address
debug3: Normalising mapped IPv4 in IPv6 address
Connection from 192.168.1.80 port 40084
debug1: Client protocol version 2.0; client software version OpenSSH_3.9p1
debug1: match: OpenSSH_3.9p1 pat OpenSSH_3.*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-1.99-OpenSSH_4.6
debug2: fd 3 setting O_NONBLOCK
debug3: privsep user:group 74:74
debug1: permanently_set_uid: 74/74
debug1: list_hostkey_types: ssh-rsa,ssh-dss
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diff
ie-hellman-group14-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,arcfour128,arcfour256,arcfour,a
es192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes25
6-ctr
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,a
es192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes25
6-ctr
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hm
ac-md5-96
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hm
ac-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: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellma
n-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,r
ijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,r
ijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hm
ac-md5-96
debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hm
ac-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
debug2: Network child is on pid 25687
debug3: preauth child monitor started
debug3: mm_request_receive entering
debug1: kex: client->server aes128-cbc hmac-md5 none
debug2: mac_init: found hmac-md5
debug1: kex: server->client aes128-cbc hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received
debug3: mm_request_send entering: type 0
debug3: monitor_read: checking request 0
debug3: mm_answer_moduli: got parameters: 1024 1024 8192
debug3: mm_request_send entering: type 1
debug2: monitor_read: 0 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI
debug3: mm_request_receive_expect entering: type 1
debug3: mm_request_receive entering
debug3: mm_choose_dh: remaining 0
debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
debug2: dh_gen_key: priv key bits set: 116/256
debug2: bits set: 514/1024
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
debug2: bits set: 514/1024
debug3: mm_key_sign entering
debug3: mm_request_send entering: type 4
debug3: monitor_read: checking request 4
debug3: mm_answer_sign
debug3: mm_answer_sign: signature 0x660ac0(143)
debug3: mm_request_send entering: type 5
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN
debug3: mm_request_receive_expect entering: type 5
debug3: mm_request_receive entering
debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
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: KEX done
debug1: userauth-request for user root service ssh-connection method none
debug1: attempt 0 failures 0
debug3: mm_getpwnamallow entering
debug3: mm_request_send entering: type 6
debug3: monitor_read: checking request 6
debug3: mm_answer_pwnamallow
debug3: Normalising mapped IPv4 in IPv6 address
debug3: Trying to reverse map address 192.168.1.80.

paused 7 seconds

debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM
debug3: mm_request_receive_expect entering: type 7
debug3: mm_request_receive entering
debug2: parse_server_config: config reprocess config len 191
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 7
debug2: monitor_read: 6 used once, disabling now
debug3: mm_request_receive entering
debug2: input_userauth_request: setting up authctxt for root
debug3: mm_start_pam entering
debug3: mm_request_send entering: type 45
debug3: mm_inform_authserv entering
debug3: mm_request_send entering: type 3
debug2: input_userauth_request: try method none
debug3: mm_auth_password entering
debug3: mm_request_send entering: type 10
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD
debug3: mm_request_receive_expect entering: type 11
debug3: mm_request_receive entering
debug3: monitor_read: checking request 45
debug1: PAM: initializing for "root"
debug1: PAM: setting PAM_RHOST to "host80.1.internal.pdinc.us"
debug1: PAM: setting PAM_TTY to "ssh"
debug2: monitor_read: 45 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 3
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 3 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 10
debug3: mm_answer_authpassword: sending result 0
debug3: mm_request_send entering: type 11
debug3: mm_auth_password: user not authenticated
Failed none for root from 192.168.1.80 port 40084 ssh2
debug3: mm_request_receive entering
debug1: userauth-request for user root service ssh-connection method
publickey
debug1: attempt 1 failures 1
debug2: input_userauth_request: try method publickey
debug1: test whether pkalg/pkblob are acceptable
debug3: mm_key_allowed entering
debug3: mm_request_send entering: type 20
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED
debug3: mm_request_receive_expect entering: type 21
debug3: mm_request_receive entering
debug3: monitor_read: checking request 20
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x6f4240
debug1: temporarily_use_uid: 11001/504 (e=0/0)
debug1: trying public key file /root/.ssh/authorized_keys
debug3: secure_filename: checking '/root/.ssh'
debug3: secure_filename: checking '/root'
debug3: secure_filename: terminating check at '/root'
debug1: matching key found: file /root/.ssh/authorized_keys, line 1
Found matching DSA key: f0:aa:c8:ee:46:67:f1:88:f9:21:46:ab:f6:2c:29:31
debug1: restore_uid: 0/0
debug3: mm_answer_keyallowed: key 0x6f4240 is allowed
debug3: mm_request_send entering: type 21
debug3: mm_request_receive entering
debug2: userauth_pubkey: authenticated 0 pkalg ssh-dss
Postponed publickey for root from 192.168.1.80 port 40084 ssh2
debug1: userauth-request for user root service ssh-connection method
publickey
debug1: attempt 2 failures 1
debug2: input_userauth_request: try method publickey
debug3: mm_key_allowed entering
debug3: mm_request_send entering: type 20
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED
debug3: mm_request_receive_expect entering: type 21
debug3: mm_request_receive entering
debug3: monitor_read: checking request 20
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x6f3210
debug1: temporarily_use_uid: 11001/504 (e=0/0)
debug1: trying public key file /root/.ssh/authorized_keys
debug3: secure_filename: checking '/root/.ssh'
debug3: secure_filename: checking '/root'
debug3: secure_filename: terminating check at '/root'
debug1: matching key found: file /root/.ssh/authorized_keys, line 1
Found matching DSA key: f0:aa:c8:ee:46:67:f1:88:f9:21:46:ab:f6:2c:29:31
debug1: restore_uid: 0/0
debug3: mm_answer_keyallowed: key 0x6f3210 is allowed
debug3: mm_request_send entering: type 21
debug3: mm_request_receive entering
debug3: mm_key_verify entering
debug3: mm_request_send entering: type 22
debug3: mm_key_verify: waiting for MONITOR_ANS_KEYVERIFY
debug3: mm_request_receive_expect entering: type 23
debug3: mm_request_receive entering
debug3: monitor_read: checking request 22
debug1: ssh_dss_verify: signature correct
debug3: mm_answer_keyverify: key 0x6f4390 signature verified
debug3: mm_request_send entering: type 23
debug3: mm_request_receive_expect entering: type 46
debug2: userauth_pubkey: authenticated 1 pkalg ssh-dss
debug3: mm_do_pam_account entering
debug3: mm_request_send entering: type 46
debug3: mm_request_receive_expect entering: type 47
debug3: mm_request_receive entering
debug3: mm_request_receive entering
debug1: do_pam_account: called

pause 7 seconds

debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success)
debug3: mm_request_send entering: type 47
Accepted publickey for root from 192.168.1.80 port 40084 ssh2
debug1: monitor_child_preauth: root has been authenticated by privileged
process
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_request_receive_expect entering: type 24
debug3: mm_request_receive entering
debug3: mm_do_pam_account returning 1
debug3: mm_send_keystate: Sending new keys: 0x65dc40 0x65dbc0
debug3: mm_newkeys_to_blob: converting 0x65dc40
debug3: mm_newkeys_to_blob: converting 0x65dbc0
debug3: mm_send_keystate: New keys have been sent
debug3: mm_send_keystate: Sending compression state
debug3: mm_request_send entering: type 24
debug3: mm_send_keystate: Finished sending state
debug3: mm_newkeys_from_blob: 0x6faeb0(122)
debug2: mac_init: found hmac-md5
debug3: mm_get_keystate: Waiting for second key
debug3: mm_newkeys_from_blob: 0x6faeb0(122)
debug2: mac_init: found hmac-md5
debug3: mm_get_keystate: Getting compression state
debug3: mm_get_keystate: Getting Network I/O buffers
debug3: mm_share_sync: Share sync
debug3: mm_share_sync: Share sync end
debug2: User child is on pid 25688
debug3: mm_request_receive entering
debug3: PAM: opening session

pause 7 seconds

debug1: PAM: reinitializing credentials

pause 20 seconds 

debug1: permanently_set_uid: 0/0
debug2: set_newkeys: mode 0
debug2: set_newkeys: mode 1
debug1: Entering interactive session for SSH2.
debug2: fd 6 setting O_NONBLOCK
debug2: fd 9 setting O_NONBLOCK
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 131072 max
32768
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: init
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_channel_req: channel 0 request exec reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req exec
debug2: fd 3 setting TCP_NODELAY
debug2: fd 11 setting O_NONBLOCK
debug3: fd 11 is O_NONBLOCK
debug2: fd 13 setting O_NONBLOCK
debug2: channel 0: read 49 from efd 13
debug2: channel 0: rwin 131072 elen 49 euse 1
debug2: channel 0: sent ext data 49
debug2: channel 0: read 13 from efd 13
debug2: channel 0: rwin 131023 elen 13 euse 1
debug2: channel 0: sent ext data 13
debug2: channel 0: read 17 from efd 13
debug2: channel 0: rwin 131010 elen 17 euse 1
debug2: channel 0: sent ext data 17
debug2: channel 0: read 267 from efd 13
debug2: channel 0: rwin 130993 elen 267 euse 1
debug2: channel 0: sent ext data 267
debug2: channel 0: read failed
debug2: channel 0: close_read
debug2: channel 0: input open -> drain
debug2: channel 0: ibuf_empty delayed efd 13/(0)
debug2: notify_done: reading
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 25696
debug1: session_exit_message: session 0 channel 0 pid 25696
debug2: channel 0: request exit-status confirm 0
debug1: session_exit_message: release channel 0
debug2: channel 0: write failed
debug2: channel 0: close_write
debug2: channel 0: output open -> closed
debug2: channel 0: read<=0 rfd 11 len 0
debug2: channel 0: read failed
channel 0: chan_read_failed for istate 1
debug2: channel 0: read 0 from efd 13
debug2: channel 0: closing read-efd 13
debug2: channel 0: ibuf empty
debug2: channel 0: send eof
debug2: channel 0: input drain -> closed
debug2: channel 0: send close
debug2: channel 0: read<=0 rfd 11 len 0
debug2: channel 0: read failed
channel 0: chan_read_failed for istate 3
debug3: channel 0: will not send data after close
debug2: channel 0: read<=0 rfd 11 len 0
debug2: channel 0: read failed
channel 0: chan_read_failed for istate 3
debug2: channel 0: rcvd close
debug3: channel 0: will not send data after close
debug2: channel 0: is dead
debug2: channel 0: gc: notify user
debug1: session_by_channel: session 0 channel 0
debug1: session_close_by_channel: channel 0 child 0
debug1: session_close: session 0 pid 0
debug2: channel 0: gc: user detached
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: server-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 server-session (t4 r0 i3/0 o3/0 fd 11/11 cfd -1)

debug3: channel 0: close_fds r 11 w 11 e -1 c -1
Connection closed by 192.168.1.80
debug1: do_cleanup
debug1: PAM: cleanup
debug3: PAM: sshpam_thread_cleanup entering
Closing connection to 192.168.1.80
debug1: PAM: cleanup
debug3: mm_request_send entering: type 58
debug3: monitor_read: checking request 58
debug3: mm_answer_term: tearing down sessions
[root at 192.168.1.21 ~]#


Will snip in reply to this.


-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
-                                                               -
- Jason Pyeron                      PD Inc. http://www.pdinc.us -
- Principal Consultant              10 West 24th Street #100    -
- +1 (443) 269-1555 x333            Baltimore, Maryland 21218   -
-                                                               -
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
 
This message is for the designated recipient only and may contain
privileged, proprietary, or otherwise private information. If you
have received it in error, purge the message from your system and
notify the sender immediately.  Any other use of the email by you
is prohibited.