Logins take a long time

Question

After upgrading to Debian 7.4 password authentication from any service take a long time. This is true for SSH logins, sudo'ing and authentication with dovecot (which is configured to use PAM).

I am able to reverse lookup DNS entries, this does not seem to be the problem. It feels like some authentication mechanism is running into a timeout. I have tried to enable pam_debug, but I don't see any debugging output going anywhere.

Here is an example of how long it takes to do a sudo (with a password prompt, during the time that sudo caches the password, it works instantly):

ceicke@h1633420:~$ time sudo who
[sudo] password for ceicke:
ceicke   pts/0        2014-08-01 09:19 (80.131.XXX.XXX)

real    0m27.976s
user    0m0.009s
sys 0m0.014s

Also SSHing into the box with my private key works instantly. So really the password checking process takes a long time.

I am a little lost on what else I can try, especially since the PAM module is very very silent about what it is doing.

Update #1

Here is the output of strace: http://pastebin.com/dRvqsrcd

There are a lot of calls of time(null) which I guess gets the current Unix timestamp. Seems like something is actively checking for a timeout.

I notice two things:

1. the time(null) call is often preceded with an open call to /dev/urandom, can it be that my server is waiting to gather enough entropy?
2. there are a lot of references to krb5 in various places. I do not use Kerberos to authenticate, can I simply take out pam_krb5.so from my pam configs?

I do not have a lot of experiences readying strace output, maybe you can see more?

Update #2

Entropy is fairly low on the server, between 100 - 200.

Answer 1

My first advice would also be trying strace -f sudo who. But this won't work, since strace will not trace SUID programs. You have to attach to your shell using strace as root and then call sudo.

In your shell type

$ echo $$

to get your shells PID. Then open another terminal and become root in that terminal. There you type

# strace -f -t -T -p $pid -o /tmp/sudo.strace

where $pid is the PID you got from the other terminal. Then go back to your first terminal and start

$ sudo who

After you got the output, go back to the root terminal, stop the strace process with CTRL-C and analyze /tmp/sudo.strace

Update: Sorry, I forgot to mention two options to strace. With -t it prefixes each line with the time of the day and with -T it shows the time spent in system calls. These facilitate finding the point where it gets slow.

Update 2: Given that you don't need Kerberos, disabling pam_krb5 could be an option. You can comment it out in the files in /etc/pam.d/, usually in the files named *common-**. Kerberos needs some entropy and this could be the culprit. But nevertheless verify this assumption by running strace with -t.

And you shoud change your password, since it is readable in the text file you uploaded to pastebin.

Answer 2

So, it turned out that Kerberos in combination with low entropy was causing the problem. Since I was not using Kerberos, I ran pam-auth-update and unselected Kerberos.