thr3ads.net - CentOS - [CentOS] how to debug ssh slow connection issues. [May 2008]

If this information is useful, please help other people find it:
Share via:

Jason Pyeron

2008-May-23 16:41 UTC

[CentOS] how to debug ssh slow connection issues.

I do not have any ideas on this.

Where should I start.

[root at 192.168.1.80 security]# date && time ssh -v 192.168.1.21 date
Fri May 23 11:43:53 EDT 2008
OpenSSH_3.9p1, OpenSSL 0.9.7a Feb 19 2003
debug1: Reading configuration data /root/.ssh/config
debug1: Applying options for 192.168.1.21
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Applying options for *
debug1: Connecting to 192.168.1.21 [192.168.1.21] port 22.
debug1: Connection established.
debug1: permanently_set_uid: 0/0
debug1: identity file /root/.ssh/identity type -1
debug1: identity file /root/.ssh/id_rsa type -1
debug1: identity file /root/.ssh/id_dsa type 2
debug1: Remote protocol version 1.99, remote software version OpenSSH_4.6
debug1: match: OpenSSH_4.6 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_3.9p1
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-cbc hmac-md5 none
debug1: kex: client->server aes128-cbc hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Host '192.168.1.21' is known and matches the RSA host key.
debug1: Found key in /root/.ssh/known_hosts:4
debug1: ssh_rsa_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received


Paused 9 seconds.


debug1: Authentications that can continue: publickey,password
debug1: Next authentication method: publickey
debug1: Trying private key: /root/.ssh/identity
debug1: Trying private key: /root/.ssh/id_rsa
debug1: Offering public key: /root/.ssh/id_dsa
debug1: Server accepts key: pkalg ssh-dss blen 433
debug1: read PEM private key done: type DSA


Paused 9 seconds.

debug1: Authentication succeeded (publickey).
debug1: channel 0: new [client-session]
debug1: Entering interactive session.

Paused 16 seconds.

debug1: Sending command: echo

debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: channel 0: free: client-session, nchannels 1
debug1: Transferred: stdin 0, stdout 0, stderr 0 bytes in 13.5 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 0

real    0m34.027s
user    0m0.014s
sys     0m0.083s
Fri May 23 11:51:32 EDT 2008
[root at statics31 security]#


And the log from 192.168.1.21 (different run so the dates won't match):

==> /var/log/secure <=May 23 12:01:56 192.168.1.21 pam_stack[23836]:
called for "PAM_ACCOUNT"
May 23 12:01:56 192.168.1.21 pam_stack[23836]: called from "sshd"
May 23 12:01:56 192.168.1.21 pam_stack[23836]: initializing
May 23 12:01:56 192.168.1.21 pam_stack[23836]: creating child stack
`system-auth'
May 23 12:01:56 192.168.1.21 pam_stack[23836]: creating environment
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_AUTHTOK to
child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_CONV to child
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_FAIL_DELAY to
child: source not set
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_OLDAUTHTOK to
child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_RHOST to child
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_RUSER to
child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_SERVICE to child
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_TTY to child
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_USER to child
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_USER_PROMPT
to child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing data to child
May 23 12:01:56 192.168.1.21 pam_stack[23836]: calling substack
May 23 12:01:56 192.168.1.21 pam_stack[23836]: substack returned 0 (Success)
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_AUTHTOK to
parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_CONV to parent
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_FAIL_DELAY to
parent: source not set
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_OLDAUTHTOK to
parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_RHOST to parent
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_RUSER to
parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_SERVICE to parent
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_TTY to parent
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing PAM_USER to parent
May 23 12:01:56 192.168.1.21 pam_stack[23836]: NOT passing PAM_USER_PROMPT
to parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing data back
May 23 12:01:56 192.168.1.21 pam_stack[23836]: passing former back
May 23 12:01:56 192.168.1.21 pam_stack[23836]: returning 0 (Success)
May 23 12:01:56 192.168.1.21 pam_stack[23844]: called for
"PAM_OPEN_SESSION"
May 23 12:01:56 192.168.1.21 pam_stack[23844]: called from "sshd"
May 23 12:01:56 192.168.1.21 pam_stack[23844]: initializing
May 23 12:01:56 192.168.1.21 pam_stack[23844]: found previously-used child
stack `system-auth'
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_CONV to child
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
child: source not set
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to child
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to child
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_TTY to child
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_USER to child
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to child: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing data to child
May 23 12:01:56 192.168.1.21 pam_stack[23844]: calling substack
May 23 12:01:56 192.168.1.21 pam_stack[23844]: substack returned 0 (Success)
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_CONV to parent
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
parent: source not set
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to parent
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to parent
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_TTY to parent
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing PAM_USER to parent
May 23 12:01:56 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to parent: source is NULL
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing data back
May 23 12:01:56 192.168.1.21 pam_stack[23844]: passing former back
May 23 12:01:56 192.168.1.21 pam_stack[23844]: returning 0 (Success)

==> /var/log/messages <=May 23 12:01:56 192.168.1.21 sshd[23836]: Accepted
publickey for root from
192.168.1.80 port 39910 ssh2
May 23 12:01:56 192.168.1.21 sshd(pam_unix)[23844]: session opened for user
root by (uid=0)

==> /var/log/secure <=May 23 12:02:01 192.168.1.21 pam_stack[23844]:
called for "PAM_SETCRED"
May 23 12:02:01 192.168.1.21 pam_stack[23844]: called from "sshd"
May 23 12:02:01 192.168.1.21 pam_stack[23844]: initializing
May 23 12:02:01 192.168.1.21 pam_stack[23844]: found previously-used child
stack `system-auth'
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
child: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_CONV to child
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
child: source not set
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
child: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to child
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
child: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to child
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_TTY to child
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_USER to child
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to child: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing data to child
May 23 12:02:01 192.168.1.21 pam_stack[23844]: calling substack
May 23 12:02:01 192.168.1.21 pam_stack[23844]: substack returned 0 (Success)
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
parent: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_CONV to parent
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
parent: source not set
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
parent: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to parent
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
parent: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to parent
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_TTY to parent
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing PAM_USER to parent
May 23 12:02:01 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to parent: source is NULL
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing data back
May 23 12:02:01 192.168.1.21 pam_stack[23844]: passing former back
May 23 12:02:01 192.168.1.21 pam_stack[23844]: returning 0 (Success)

==> /var/log/messages <=May 23 12:02:16 192.168.1.21 sshd[23844]: error:
channel 0: chan_read_failed
for istate 3

==> /var/log/secure <=May 23 12:02:16 192.168.1.21 pam_stack[23844]:
called for "PAM_SETCRED"
May 23 12:02:16 192.168.1.21 pam_stack[23844]: called from "sshd"
May 23 12:02:16 192.168.1.21 pam_stack[23844]: initializing
May 23 12:02:16 192.168.1.21 pam_stack[23844]: found previously-used child
stack `system-auth'
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
child: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_CONV to child
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
child: source not set
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
child: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to child
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
child: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to child
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_TTY to child
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_USER to child
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to child: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing data to child
May 23 12:02:16 192.168.1.21 pam_stack[23844]: calling substack
May 23 12:02:16 192.168.1.21 pam_stack[23844]: substack returned 0 (Success)
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
parent: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_CONV to parent
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
parent: source not set
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
parent: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to parent
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
parent: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to parent
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_TTY to parent
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing PAM_USER to parent
May 23 12:02:16 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to parent: source is NULL
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing data back
May 23 12:02:16 192.168.1.21 pam_stack[23844]: passing former back
May 23 12:02:16 192.168.1.21 pam_stack[23844]: returning 0 (Success)
May 23 12:02:21 192.168.1.21 pam_stack[23844]: called for
"PAM_CLOSE_SESSION"
May 23 12:02:21 192.168.1.21 pam_stack[23844]: called from "sshd"
May 23 12:02:21 192.168.1.21 pam_stack[23844]: initializing
May 23 12:02:21 192.168.1.21 pam_stack[23844]: found previously-used child
stack `system-auth'
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
child: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_CONV to child
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
child: source not set
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
child: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to child
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
child: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to child
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_TTY to child
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_USER to child
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to child: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing data to child
May 23 12:02:21 192.168.1.21 pam_stack[23844]: calling substack
May 23 12:02:21 192.168.1.21 pam_stack[23844]: substack returned 0 (Success)
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_AUTHTOK to
parent: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_CONV to parent
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_FAIL_DELAY to
parent: source not set
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_OLDAUTHTOK to
parent: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_RHOST to parent
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_RUSER to
parent: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_SERVICE to parent
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_TTY to parent
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing PAM_USER to parent
May 23 12:02:21 192.168.1.21 pam_stack[23844]: NOT passing PAM_USER_PROMPT
to parent: source is NULL
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing data back
May 23 12:02:21 192.168.1.21 pam_stack[23844]: passing former back
May 23 12:02:21 192.168.1.21 pam_stack[23844]: returning 0 (Success)

==> /var/log/messages <=May 23 12:02:16 192.168.1.21 last message repeated
2 times
May 23 12:02:21 192.168.1.21 sshd(pam_unix)[23844]: session closed for user
root


-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
-                                                               -
- 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.

Paul Heinlein

2008-May-23 17:05 UTC

head link

[CentOS] how to debug ssh slow connection issues.

On Fri, 23 May 2008, Jason Pyeron wrote:
> I do not have any ideas on this.
>
> Where should I start. [... lots and lots of snippage ...]
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

On the client, do

   ssh -p 2222 your.server

If that doesn't provide good info, wrap sshd in strace:

   strace -o /tmp/sshd-trace.txt sshd -d -p 2222

The strace output will show where the delays are occuring. (You can 
modify timestamp info in the strace output. See the man page for 
details.)

-- 
Paul Heinlein <> heinlein at madboa.com <> http://www.madboa.com/

Reasonably Related Threads

Search for more apparently analagous threads

CentOS - May 2008 - how to debug ssh slow connection issues.

[CentOS] how to debug ssh slow connection issues.

[CentOS] how to debug ssh slow connection issues.

Reasonably Related Threads