I recently upgraded my server from RedHat7.2 to RedHat9.0.
Since the upgrade I have noticed an annoying delay of about 2-3 seconds when I login using SSH from
Windows Client boxes around our office. The delay is making the CVS operations (which are configured
to use ssh) unbearably slow.
I have tracked the delay down to a call from sshd into PAM to authenticate the remote user. We
mostly use RSA keys for authentication so that no password interaction is necessary - however, it
seems that sshd first tries to authenticate the user using a password before attempting to use the
keys. It calls PAM to authenticate the user, which fails since no password has been given, then it
attempts the keys, which succeed. The call into PAM is taking about 3 seconds to return a failure.
This behavior was not noticed with the 7.2 version of RedHat.
In further experiments I have noticed that if I turn off password verification in sshd.config
entirely ("PasswordAuthentication no"), this issue goes away. This however breaks some of our users
that use SFTP and ssh logins without keys.
Any idea why this delay is occurring - or how to work around it and still allow ssh logins using
both keys and passwords?
My versions:
libpam.so.0.75
sshd version OpenSSH_3.5p1
I have turned on various debug flags for SSH and PAM to try and find this as well.
Here is the debug output from sshd -d:
Connection from 172.30.0.100 port 11742
debug1: Client protocol version 1.5; client software version PuTTY-Release-0.52
debug1: no match: PuTTY-Release-0.52
debug1: Local version string SSH-1.99-OpenSSH_3.5p1
debug1: permanently_set_uid: 74/74
debug1: Sent 768 bit server key and 1024 bit host key.
debug1: Encryption type: blowfish
debug1: Received session key; encryption turned on.
debug1: Installing crc compensation attack detector.
debug1: Starting up PAM with username "test"
debug1: PAM setting rhost to "test"
debug1: Attempting authentication for test.
debug1: PAM Password authentication for "test" failed[7]: Authentication failure
Failed none for test from 172.30.0.100 port 11742
debug1: temporarily_use_uid: 501/500 (e=0/0)
debug1: trying public RSA key file /home/test/.ssh/authorized_keys
debug1: restore_uid: 0/0
Accepted rsa for test from 172.30.0.100 port 11742
debug1: monitor_child_preauth: test has been authenticated by privileged process
Here is the debug output from PAM (I put debug behind all lines in 'pam.d/sshd'):
Sep 5 18:27:26 mustang pam_stack[2276]: called for "PAM_AUTHENTICATE"
Sep 5 18:27:26 mustang pam_stack[2276]: called from "sshd"
Sep 5 18:27:26 mustang pam_stack[2276]: initializing
Sep 5 18:27:26 mustang pam_stack[2276]: creating child stack `system-auth'
Sep 5 18:27:26 mustang pam_stack[2276]: creating environment
Sep 5 18:27:26 mustang pam_stack[2276]: NOT passing PAM_AUTHTOK to child: source is NULL
Sep 5 18:27:26 mustang pam_stack[2276]: passing PAM_CONV to child
Sep 5 18:27:26 mustang pam_stack[2276]: NOT passing PAM_FAIL_DELAY to child: source not set
Sep 5 18:27:26 mustang pam_stack[2276]: NOT passing PAM_OLDAUTHTOK to child: source is NULL
Sep 5 18:27:26 mustang pam_stack[2276]: passing PAM_RHOST to child
Sep 5 18:27:26 mustang pam_stack[2276]: NOT passing PAM_RUSER to child: source is NULL
Sep 5 18:27:26 mustang pam_stack[2276]: passing PAM_SERVICE to child
Sep 5 18:27:26 mustang pam_stack[2276]: passing PAM_TTY to child
Sep 5 18:27:26 mustang pam_stack[2276]: passing PAM_USER to child
Sep 5 18:27:26 mustang pam_stack[2276]: NOT passing PAM_USER_PROMPT to child: source is NULL
Sep 5 18:27:26 mustang pam_stack[2276]: passing data to child
Sep 5 18:27:26 mustang pam_stack[2276]: calling substack
Sep 5 18:27:26 mustang pam_stack[2276]: substack returned 7 (Authentication failure)
Sep 5 18:27:26 mustang pam_stack[2276]: passing PAM_AUTHTOK to parent
Sep 5 18:27:26 mustang pam_stack[2276]: NOT passing PAM_CONV to parent: destination already set
Sep 5 18:27:26 mustang pam_stack[2276]: passing PAM_FAIL_DELAY to parent
Sep 5 18:27:26 mustang pam_stack[2276]: NOT passing PAM_OLDAUTHTOK to parent: source is NULL
Sep 5 18:27:27 mustang pam_stack[2276]: passing PAM_RHOST to parent
Sep 5 18:27:27 mustang pam_stack[2276]: NOT passing PAM_RUSER to parent: source is NULL
Sep 5 18:27:27 mustang pam_stack[2276]: passing PAM_SERVICE to parent
Sep 5 18:27:27 mustang pam_stack[2276]: passing PAM_TTY to parent
Sep 5 18:27:27 mustang pam_stack[2276]: passing PAM_USER to parent
Sep 5 18:27:27 mustang pam_stack[2276]: NOT passing PAM_USER_PROMPT to parent: source is NULL
Sep 5 18:27:27 mustang pam_stack[2276]: passing data back
Sep 5 18:27:27 mustang pam_stack[2276]: passing former back
Sep 5 18:27:27 mustang pam_stack[2276]: returning 7 (Authentication failure)
Sep 5 18:27:29 mustang pam_stack[2276]: called for "PAM_ACCOUNT"
Sep 5 18:27:29 mustang pam_stack[2276]: called from "sshd"
Sep 5 18:27:29 mustang pam_stack[2276]: initializing
Sep 5 18:27:29 mustang pam_stack[2276]: found previously-used child stack `system-auth'
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_AUTHTOK to child: source is NULL
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_CONV to child: destination already set
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_FAIL_DELAY to child: source not set
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_OLDAUTHTOK to child: source is NULL
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_RHOST to child
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_RUSER to child: sourceis NULL
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_SERVICE to child
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_TTY to child
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_USER to child
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_USER_PROMPT to child: source is NULL
Sep 5 18:27:29 mustang pam_stack[2276]: passing data to child
Sep 5 18:27:29 mustang pam_stack[2276]: calling substack
Sep 5 18:27:29 mustang pam_stack[2276]: substack returned 0 (Success)
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_AUTHTOK to parent
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_CONV to parent: destination already set
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_FAIL_DELAY to parent
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_OLDAUTHTOK to parent: source is NULL
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_RHOST to parent
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_RUSER to parent: source is NULL
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_SERVICE to parent
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_TTY to parent
Sep 5 18:27:29 mustang pam_stack[2276]: passing PAM_USER to parent
Sep 5 18:27:29 mustang pam_stack[2276]: NOT passing PAM_USER_PROMPT to parent: source is NULL
Sep 5 18:27:29 mustang pam_stack[2276]: passing data back
Sep 5 18:27:29 mustang pam_stack[2276]: passing former back
Sep 5 18:27:29 mustang pam_stack[2276]: returning 0 (Success)
Sep 5 18:27:29 mustang sshd[2276]: Accepted rsa for test from 172.30.0.100 port 11741
_______________________________________________
Pam-list@xxxxxxxxxx
https://www.redhat.com/mailman/listinfo/pam-list
