login process taking a long time

 
Thread Tools Search this Thread
Operating Systems Linux Red Hat login process taking a long time
# 1  
Old 06-04-2009
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
# 2  
Old 06-04-2009
Where are your users defined?

Local/nis/ldap/ADS ?
# 3  
Old 06-04-2009
user definitions

I neglected to include that.. they are standard /etc/passwd and /etc/shadow...
# 4  
Old 06-04-2009
It kinda looks like you are trying to use Kerberos for authentication but it is not there.
I don't know why it "hangs' like that though, or if that contributes to the problem.
# 5  
Old 06-05-2009
kerberos.. I hope not

Well, we never configured the use of Kerberos, so I hope it isn't using that. Where would I check to make sure it isn't??? I continue to look at this, and I can't get any additional info. I turned on audit for the PAM processing, and I the only thing I get is once the session starts an entry that indicates the session started.

-----Post Update-----

Alright, it's working now... I still do not understand why it started mis-behaving, as I do not believe the confiiguration wass changed in the last couple days, however, what I did to resolve the delay was run authconfig
and disable all LDAP and Kerberos options.... it's now behaving as it did previously.
Login or Register to Ask a Question

Previous Thread | Next Thread

10 More Discussions You Might Find Interesting

1. Shell Programming and Scripting

Process running time by taking user input

Need help in scripting . Below is the situation and need your inputs Checking all the processes, scripts running time based on user input time . Below Example ps -aef -o user,pid,etime,stime,args| grep sleep <user> 28995 01:24 14:14:39 sleep 120 <user> 29385 00:52 14:15:10... (8 Replies)
Discussion started by: ajayram_arya
8 Replies

2. UNIX for Dummies Questions & Answers

ls is taking long time to list

Hi, All the data are kept on Netapp using NFS. some directories are so fast when doing ls but few of them are slow. After doing few times, it becomes fast. Then again after few minutes, it becomes slow again. Can you advise what's going on? This one directory I am very interested is giving... (3 Replies)
Discussion started by: samnyc
3 Replies

3. UNIX and Linux Applications

database takes long time to process

Hi, we currently having a issue where when we send jobs to the server for the application lawson, it is taking a very long time to complete. here are the last few lines of the database log. 2012-09-18-10.35.55.707279-240 E244403536A576 LEVEL: Warning PID : 950492 ... (1 Reply)
Discussion started by: techy1
1 Replies

4. Solaris

How to find out bottleneck if system is taking long time in gzip

Dear All, OS = Solaris 5.10 Hardware Sun Fire T2000 with 1 Ghz quode core We have oracle application 11i with 10g database. When ever i am trying to take cold backup of database with 55GB size its taking long time to finish. As the application is down nobody is using the server at all... (8 Replies)
Discussion started by: yoojamu
8 Replies

5. UNIX for Dummies Questions & Answers

Job is taking long time

Hi , We have 20 jobs are scheduled. In that one of our job is taking long time ,it's not completing. If we are not terminating it's running infinity time actually the job completion time is 5 minutes. The job is deleting some records from the table and two insert statements and one select... (7 Replies)
Discussion started by: ajaykumarkona
7 Replies

6. UNIX for Dummies Questions & Answers

Changing Password process takes a long time

We are running unix. After a reboot of the server we have found that changing password takes a long time. if type in passwd "username" you can type in the 1st instance of the password , press enter , then it will wait for about 3 minutes before bringing up the confirm password line typing it in... (4 Replies)
Discussion started by: AIXlewis
4 Replies

7. UNIX for Dummies Questions & Answers

gref -f taking long time for big file

grep -f taking long time to compare for big files, any alternate for fast check I am using grep -f file1 file2 to check - to ckeck dups/common rows prsents. But my files contains file1 contains 5gb and file 2 contains 50 mb and its taking such a long time to compare the files. Do we have any... (10 Replies)
Discussion started by: gkskumar
10 Replies

8. Shell Programming and Scripting

<AIX>Problem in purge script, taking very very long time to complete 18.30hrs

Hi, I have here a script which is used to purge older files/directories based on defined purge period. The script consists of 45 find commands, where each command will need to traverse through more than a million directories. Therefore a single find command executes around 22-25 mins... (7 Replies)
Discussion started by: sravicha
7 Replies

9. Linux

it takes long time to login on server

Hi, I am trying to login using ssh on Red Hat Linux 5 server, The password appears immediately but after I enter the password it takes about 90 seconds to login completely. Please suggest what changes require? Regards, Manoj (4 Replies)
Discussion started by: manoj.solaris
4 Replies

10. UNIX for Dummies Questions & Answers

fetchmail taking long time to fetchmail...

Hi peeps, We are having around 60 users. The time set to retrieve the mail is 300 sec. But it's taking around 1 hour to deliver mails. I am using debian sarge 3.1. any clues? And how it will affect if I decrease the time? My machine has got 1 p4 3.0 GHZ processor and 1 GB ram. The home... (2 Replies)
Discussion started by: squid04
2 Replies
Login or Register to Ask a Question

Featured Tech Videos