login process taking a long time
I'm having a bit of a login performance issue.. wondering if anyone has any ideas where I might look.
Here's the scenario...
Linux Red Hat ES 4 update 5
regardless of where I login from (ssh or on the text console) after providing the password the system seems to pause for between 30 and 60 seconds.
I've checked DNS reserve lookup for the remote host(s) and DNS responds immediately, so it doesn't appear related to that.
I've run ssh -vvv user@hostname and the output is included below...
It proceeds to the first red colored line very quickly, less than a second and sits there for about 30 seconds or so, then quickly to the second red colored line and again about 30 seconds and then finished the login and present a command prompt in under a second. the time behavior from the console is almost identical, possible a little faster, and I'm not sure how I can debug that process.. again, any help would would appreciated. Ho, as a note, this behavior just started in the last day or so.. it had always been very quick previously. Also, the system is 99% idle most of the time, and during the login I did not notice any processes taking any significant resources, nor did memory appear over utilized. We also did a tcpdump during the ssh and that log is also below.... didn't see anything there that seemed odd except again it appears to pause at the same time the ssh did. Another symptom that might help in diagnosis... when starting tcpdump it also seems to pause about 60 seconds before displaying any output
======ssh -vvv
OpenSSH_3.6.1p2-pwexp22, SSH protocols 1.5/2.0, OpenSSL 0x0090607f
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Failed dlopen: /usr/krb5/lib/libkrb5.a(libkrb5.a.so): A file or directory in the path name does not exist.
debug1: Failed dlopen: /usr/krb5/lib/libkrb5.a(libkrb5.a.so): A file or directory in the path name does not exist.
debug3: Seeding PRNG from /usr/sbin/ssh-rand-helper
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug2: ssh_connect: needpriv 0
debug1: Connecting to hostname [192.168.1.1] port 22.
debug1: Connection established.
debug1: identity file /xxxxx/.ssh/identity type -1
debug3: Not a RSA1 key file /xxxxx/.ssh/id_rsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: missing keytype
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: missing keytype
debug1: identity file /xxxxx/.ssh/id_rsa type 1
debug1: identity file /xxxxx/.ssh/id_dsa type -1
debug1: Remote protocol version 1.99, remote software version OpenSSH_3.9p1
debug1: match: OpenSSH_3.9p1 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_3.6.1p2-pwexp22
debug3: RNG is ready, skipping seeding
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,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@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: kex_parse_kexinit: 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-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@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,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@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
debug2: dh_gen_key: priv key bits set: 130/256
debug2: bits set: 977/2048
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: check_host_in_hostfile: filename /xxxxx/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 8
debug3: check_host_in_hostfile: filename /xxxxx/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 9
debug1: Host 'isiweb' is known and matches the RSA host key.
debug1: Found key in /xxxxx/.ssh/known_hosts:8
debug2: bits set: 1023/2048
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: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,gssapi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-with-mic,password
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: Trying private key: /xxxxx/.ssh/identity
debug3: no such identity: /xxxxx/.ssh/identity
debug1: Offering public key: /xxxxx/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 149 lastkey 2004a5d8 hint 1
debug2: input_userauth_pk_ok: fp cc:ff:dd:bb:aa:ff:cc:aa:ff:df:ee:cc:bb:aa:yy:xx
debug3: sign_and_send_pubkey
debug1: read PEM private key done: type RSA
debug1: Authentication succeeded (publickey).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Entering interactive session.
debug2: callback start
debug2: ssh_session2_setup: id 0
debug1: channel 0: request pty-req
debug3: tty_make_modes: ospeed 38400
debug3: tty_make_modes: ispeed 38400
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 255
debug3: tty_make_modes: 7 255
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: 14 22
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 0
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 0
debug3: tty_make_modes: 55 0
debug3: tty_make_modes: 56 0
debug3: tty_make_modes: 57 0
debug3: tty_make_modes: 58 0
debug3: tty_make_modes: 59 0
debug3: tty_make_modes: 60 0
debug3: tty_make_modes: 61 0
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 0
debug1: channel 0: request shell
debug2: callback done
debug1: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 131072
Last login: Thu Jun 4 12:13:20 2009 from xxx.domain.com
=======TCPDUMP
12:44:42.478820 IP dsthost.domain.com.52518 > srchost.ssh: S 3229320833:3229320833(0) win 16384 <mss 1460>
12:44:42.478847 IP srchost.ssh > user.domain.com.52518: S 1386695152:1386695152(0) ack 3229320834 win 5840 <mss 1460>
12:44:42.479067 IP dsthost.domain.com.52518 > srchost.ssh: . ack 1 win 17520
12:44:42.487287 IP srchost.ssh > dsthost.domain.com.52518: P 1:24(23) ack 1 win 5840
12:44:42.487755 IP dsthost.domain.com.52518 > srchost.ssh: P 1:33(32) ack 24 win 17520
12:44:42.487819 IP srchost.ssh > dsthost.domain.com.52518: . ack 33 win 5840
12:44:42.488290 IP dsthost.domain.com.52518 > srchost.ssh: P 33:577(544) ack 24 win 17520
12:44:42.488307 IP srchost.ssh > dsthost.domain.com.52518: . ack 577 win 6528
12:44:42.489169 IP srchost.ssh > dsthost.domain.com.52518: P 24:664(640) ack 577 win 6528
12:44:42.490880 IP dsthost.domain.com.52518 > srchost.ssh: P 577:601(24) ack 664 win 17520
12:44:42.494020 IP srchost.ssh > dsthost.domain.com.52518: P 664:944(280) ack 601 win 6528
12:44:42.513663 IP dsthost.domain.com.52518 > srchost.ssh: P 601:873(272) ack 944 win 17520
12:44:42.529798 IP srchost.ssh > dsthost.domain.com.52518: P 944:1536(592) ack 873 win 7616
12:44:42.545548 IP dsthost.domain.com.52518 > srchost.ssh: . ack 1536 win 17520
12:44:42.555264 IP dsthost.domain.com.52518 > srchost.ssh: P 873:889(16) ack 1536 win 17520
12:44:42.595575 IP srchost.ssh > dsthost.domain.com.52518: . ack 889 win 7616
12:44:42.595786 IP dsthost.domain.com.52518 > srchost.ssh: P 889:937(48) ack 1536 win 17520
12:44:42.595803 IP srchost.ssh > dsthost.domain.com.52518: . ack 937 win 7616
12:44:42.595929 IP srchost.ssh > dsthost.domain.com.52518: P 1536:1584(48) ack 937 win 7616
12:44:42.596292 IP dsthost.domain.com.52518 > srchost.ssh: P 937:1001(64) ack 1584 win 17520
12:44:42.596601 IP srchost.ssh > dsthost.domain.com.52518: P 1584:1664(80) ack 1001 win 7616
12:44:42.597444 IP dsthost.domain.com.52518 > srchost.ssh: P 1001:1241(240) ack 1664 win 17520
12:44:42.637569 IP srchost.ssh > dsthost.domain.com.52518: . ack 1241 win 8704
=== pauses
12:45:12.598495 IP srchost.ssh > dsthost.domain.com.52518: P 1664:1856(192) ack 1241 win 8704
12:45:12.610190 IP dsthost.domain.com.52518 > srchost.ssh: P 1241:1625(384) ack 1856 win 17520
12:45:12.610208 IP srchost.ssh > dsthost.domain.com.52518: . ack 1625 win 9792
12:45:12.620298 IP srchost.ssh > dsthost.domain.com.52518: P 1856:1888(32) ack 1625 win 9792
12:45:12.620950 IP dsthost.domain.com.52518 > srchost.ssh: P 1625:1689(64) ack 1888 win 17520
12:45:12.660951 IP srchost.ssh > dsthost.domain.com.52518: . ack 1689 win 9792
=== pauses
12:45:42.623962 IP srchost.ssh > dsthost.domain.com.52518: P 1888:1936(48) ack 1689 win 9792
12:45:42.626432 IP dsthost.domain.com.52518 > srchost.ssh: P 1689:2073(384) ack 1936 win 17520
12:45:42.626449 IP srchost.ssh > dsthost.domain.com.52518: . ack 2073 win 10880
12:45:42.635027 IP srchost.ssh > dsthost.domain.com.52518: P 1936:1984(48) ack 2073 win 10880
12:45:42.635078 IP srchost.ssh > dsthost.domain.com.52518: P 1984:2080(96) ack 2073 win 10880
12:45:42.747865 IP dsthost.domain.com.52518 > srchost.ssh: . ack 2080 win 17520
12:45:42.780331 IP srchost.ssh > dsthost.domain.com.52518: P 2080:2224(144) ack 2073 win 10880
12:45:42.780395 IP srchost.ssh > dsthost.domain.com.52518: P 2224:2608(384) ack 2073 win 10880
12:45:42.783165 IP srchost.ssh > dsthost.domain.com.52518: P 2608:2672(64) ack 2073 win 10880
12:45:42.947868 IP dsthost.domain.com.52518 > srchost.ssh: . ack 2672 win 17520
12:45:42.947885 IP srchost.ssh > dsthost.domain.com.52518: P 2672:2768(96) ack 2073 win 10880
12:45:43.147868 IP dsthost.domain.com.52518 > srchost.ssh: . ack 2768 win 17520
