SSH only works after intentionally failed password

Question

So, I'm having a rather weird problem. I have a server, that when I try to SSH into, immediately closes the connection if I type in the correct password on the first attempt. However, if I purposefully enter a wrong password on the first attempt, and then enter a correct password at the second or third prompt, it successfully logs me into the computer. Similarly, when I try to use public key authentication, I get an immediate closed connection. If, however, I enter a wrong password for my key file, followed by another wrong password once it reverts to password authentication, I can successfully log in as long as I provide the correct password at the second or third prompt.

The machine is running Red Hat Enterprise Linux Server release 6.2 (Santiago), and is using LDAP and PAM for authentication. Any ideas on where to start debugging this one? Let me know what config files I need to provide and I'll be happy to do so.

Here's some debugging information. The following code blocks represents these 3 scenarios, in order: 1) Correct private-key password on first try, 2) skip private-key, correct regular password on first try, 3) skip private-key, intentionally enter bad password, then enter the good one...this is the only scenario that actually let's me connect.

OpenSSH_5.9p1 Debian-5ubuntu1, OpenSSL 1.0.1 14 Mar 2012
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to [removed for privacy].
debug1: Connection established.
debug3: Incorrect RSA1 identifier
debug3: Could not load "/home/trevor/.ssh/id_rsa" as a RSA1 public key
debug1: identity file /home/trevor/.ssh/id_rsa type 1
debug1: Checking blacklist file /usr/share/ssh/blacklist.RSA-2048
debug1: Checking blacklist file /etc/ssh/blacklist.RSA-2048
debug1: identity file /home/trevor/.ssh/id_rsa-cert type -1
debug1: identity file /home/trevor/.ssh/id_dsa type -1
debug1: identity file /home/trevor/.ssh/id_dsa-cert type -1
debug1: identity file /home/trevor/.ssh/id_ecdsa type -1
debug1: identity file /home/trevor/.ssh/id_ecdsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.3
debug1: match: OpenSSH_5.3 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.9p1 Debian-5ubuntu1
debug2: fd 3 setting O_NONBLOCK
debug3: load_hostkeys: loading entries for host "[removed]" from file "/home/trevor/.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /home/trevor/.ssh/known_hosts:90
debug3: load_hostkeys: loaded 1 keys
debug3: order_hostkeyalgs: prefer hostkeyalgs: [email protected],[email protected],ssh-rsa
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: [email protected],[email protected],ssh-rsa,[email protected],[email protected],[email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,[email protected],zlib
debug2: kex_parse_kexinit: none,[email protected],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-sha256,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-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,[email protected]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-ripemd160,[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected],hmac-ripemd160,[email protected],hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,[email protected]
debug2: kex_parse_kexinit: none,[email protected]
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug2: dh_gen_key: priv key bits set: 120/256
debug2: bits set: 531/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: RSA cb:1c:78:3f:f7:7d:8a:10:27:86:a3:12:0c:27:f4:19
debug3: load_hostkeys: loading entries for host "[removed]" from file "/home/trevor/.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /home/trevor/.ssh/known_hosts:90
debug3: load_hostkeys: loaded 1 keys
debug3: load_hostkeys: loading entries for host "[removed]" from file "/home/trevor/.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /home/trevor/.ssh/known_hosts:80
debug3: load_hostkeys: loaded 1 keys
debug1: Host '[removed]' is known and matches the RSA host key.
debug1: Found key in /home/trevor/.ssh/known_hosts:90
debug2: bits set: 541/1024
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: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /home/trevor/.ssh/id_rsa (0x7f3a228127d0)
debug2: key: /home/trevor/.ssh/id_dsa ((nil))
debug2: key: /home/trevor/.ssh/id_ecdsa ((nil))
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-keyex,gssapi-with-mic,password
debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-keyex
debug3: remaining preferred: gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-keyex
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug2: we did not send a packet, disable method
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug1: Unspecified GSS failure.  Minor code may provide more information
Credentials cache file '/tmp/krb5cc_1000' not found

debug1: Unspecified GSS failure.  Minor code may provide more information
Credentials cache file '/tmp/krb5cc_1000' not found

debug1: Unspecified GSS failure.  Minor code may provide more information


debug1: Unspecified GSS failure.  Minor code may provide more information
Credentials cache file '/tmp/krb5cc_1000' not found

debug2: we did not send a packet, disable method
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /home/trevor/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 279
debug2: input_userauth_pk_ok: fp 9c:b0:15:a4:92:9c:a5:31:8b:00:ea:f6:cb:e1:96:17
debug3: sign_and_send_pubkey: RSA 9c:b0:15:a4:92:9c:a5:31:8b:00:ea:f6:cb:e1:96:17
debug1: key_parse_private_pem: PEM_read_PrivateKey failed
debug1: read PEM private key done: type <unknown>
Enter passphrase for key '/home/trevor/.ssh/id_rsa': 
debug1: read PEM private key done: type RSA
Connection closed by [removed_ip]

Now I skip the private-key, and use the correct user password on the first try:

Enter passphrase for key '/home/trevor/.ssh/id_rsa': 
debug2: no passphrase given, try next key
debug1: Trying private key: /home/trevor/.ssh/id_dsa
debug3: no such identity: /home/trevor/.ssh/id_dsa
debug1: Trying private key: /home/trevor/.ssh/id_ecdsa
debug3: no such identity: /home/trevor/.ssh/id_ecdsa
debug2: we did not send a packet, disable method
debug3: authmethod_lookup password
debug3: remaining preferred: ,password
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
[user]@[server]'s password: 
debug3: packet_send2: adding [##] (len [##] padlen [#] extra_pad [##])
debug2: we sent a password packet, wait for reply
Connection closed by [removed_ip]

Finally I skip the private key, enter an incorrect password, and then enter the correct password on the 2nd try, this approach finally lets me in s

debug1: Next authentication method: password
[user]@[server]'s password: 
debug3: packet_send2: adding [##] (len [##] padlen [#] extra_pad [##])
debug2: we sent a password packet, wait for reply
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
Permission denied, please try again.
[user]@[server]'s password: 
debug3: packet_send2: adding [##] (len [##] padlen [##] extra_pad [#])
debug2: we sent a password packet, wait for reply
debug1: Authentication succeeded (password).
Authenticated to [server] ([[server_ip]]:22).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting [email protected]
debug1: Entering interactive session.
debug2: callback start
debug2: x11_get_proto: /usr/bin/xauth  list :0 2>/dev/null
debug1: Requesting X11 forwarding with authentication spoofing.
debug2: channel 0: request x11-req confirm 1
debug1: Requesting authentication agent forwarding.
debug2: channel 0: request [email protected] confirm 0
debug2: client_session2_setup: id 0
debug2: fd 3 setting TCP_NODELAY
debug2: channel 0: request pty-req confirm 1
debug1: Sending environment.
debug3: Ignored env LANGUAGE
debug3: Ignored env KDE_MULTIHEAD
debug3: Ignored env KDE_SESSION_VERSION
debug3: Ignored env KONSOLE_DBUS_SERVICE
debug3: Ignored env LOGNAME
debug3: Ignored env WINDOWPATH
debug3: Ignored env GTK_MODULES
debug3: Ignored env GTK2_RC_FILES
debug3: Ignored env KDE_FULL_SESSION
debug3: Ignored env SHLVL
debug3: Ignored env DBUS_SESSION_BUS_ADDRESS
debug3: Ignored env PATH
debug3: Ignored env USER
debug1: Sending env LANG = en_US.UTF-8
debug2: channel 0: request env confirm 0
debug3: Ignored env DEFAULTS_PATH
debug3: Ignored env GTK_RC_FILES
debug3: Ignored env WINDOWID
debug3: Ignored env XCURSOR_SIZE
debug3: Ignored env XDG_CONFIG_DIRS
debug3: Ignored env XDM_MANAGED
debug3: Ignored env XDG_DATA_DIRS
debug3: Ignored env DM_CONTROL
debug3: Ignored env _
debug3: Ignored env DISPLAY
debug3: Ignored env PWD
debug3: Ignored env XCURSOR_THEME
debug3: Ignored env GS_LIB
debug3: Ignored env COLORFGBG
debug3: Ignored env KDE_SESSION_UID
debug3: Ignored env SSH_AGENT_PID
debug3: Ignored env XDG_SESSION_COOKIE
debug3: Ignored env OLDPWD
debug3: Ignored env TERM
debug3: Ignored env PROFILEHOME
debug3: Ignored env SESSION_MANAGER
debug3: Ignored env UBUNTU_MENUPROXY
debug3: Ignored env QT_PLUGIN_PATH
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env KONSOLE_DBUS_SESSION
debug3: Ignored env DESKTOP_SESSION
debug3: Ignored env MANDATORY_PATH
debug3: Ignored env SHELL_SESSION_ID
debug3: Ignored env HOME
debug3: Ignored env SHELL
debug3: Ignored env GREP_OPTIONS
debug3: Ignored env GREP_COLOR
debug3: Ignored env PAGER
debug1: Sending env LC_CTYPE = en_US.UTF-8
debug2: channel 0: request env confirm 0
debug3: Ignored env LSCOLORS
debug3: Ignored env rvm_prefix
debug3: Ignored env rvm_path
debug3: Ignored env __array_start
debug3: Ignored env rvm_bin_path
debug3: Ignored env escape_flag
debug3: Ignored env _first
debug3: Ignored env _second
debug3: Ignored env rvm_version
debug3: Ignored env RUBY_VERSION
debug3: Ignored env GEM_HOME
debug3: Ignored env GEM_PATH
debug3: Ignored env MY_RUBY_HOME
debug3: Ignored env IRBRC
debug3: Ignored env rvm_alias_expanded
debug3: Ignored env rvm_docs_type
debug3: Ignored env rvm_gemstone_package_file
debug3: Ignored env rvm_gemstone_url
debug3: Ignored env rvm_niceness
debug3: Ignored env rvm_nightly_flag
debug3: Ignored env rvm_proxy
debug3: Ignored env rvm_quiet_flag
debug3: Ignored env rvm_ruby_file
debug3: Ignored env rvm_ruby_make
debug3: Ignored env rvm_ruby_make_install
debug3: Ignored env rvm_ruby_mode
debug3: Ignored env rvm_script_name
debug3: Ignored env rvm_sdk
debug3: Ignored env rvm_silent_flag
debug3: Ignored env rvm_wrapper_name
debug2: channel 0: request shell confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel_input_status_confirm: type 99 id 0
debug2: X11 forwarding request accepted on channel 0
debug2: channel_input_status_confirm: type 99 id 0
debug2: PTY allocation request accepted on channel 0
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: shell request accepted on channel 0
Last login: [DateTime removed] from [location removed]

As you can tell from the debugging code, my name is Trevor. Thanks for the help! Let me know what pam config files I need to include.

Per requests in the comments, here's some more log/debugging information.

/var/log/secure (my username is twhitney):

Oct  9 12:01:26 [server] sshd[25087]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=[removed]  user=twhitney
Oct  9 12:01:26 [server] sshd[25087]: pam_krb5[25087]: authentication fails for 'twhitney' (twhitney@[domain]): Authentication failure (Decrypt integrity check failed)
Oct  9 12:01:26 [server] sshd[25087]: pam_ldap: ldap_starttls_s: Operations error
Oct  9 12:01:28 [server] sshd[25087]: Failed password for twhitney from [server_ip] port 47541 ssh2
Oct  9 12:01:32 [server] sshd[25087]: Accepted password for twhitney from [server_ip] port 47541 ssh2
Oct  9 12:01:32 [server] sshd[25087]: pam_unix(sshd:session): session opened for user twhitney by (uid=0)

The key clue here is probably "pam_ldap: ldap_starttls_s: Operations error", I'll have to do some research into that.

Up next, are the pam configs. I'll start with /etc/pam.d/system-auth:

auth        required      pam_env.so
auth        sufficient    pam_unix.so nullok try_first_pass
auth        requisite     pam_succeed_if.so uid >= 500 quiet
auth        sufficient    pam_sss.so use_first_pass
auth        required      pam_deny.so

account     required      pam_unix.so broken_shadow
account     sufficient    pam_localuser.so
account     sufficient    pam_succeed_if.so uid < 500 quiet
account     [default=bad success=ok user_unknown=ignore] pam_sss.so
account     required      pam_permit.so

password    requisite     pam_cracklib.so try_first_pass retry=3 type=
password    sufficient    pam_unix.so md5 shadow nullok try_first_pass use_authtok
password    sufficient    pam_sss.so use_authok
password    required      pam_deny.so

session     required      pam_oddjob_mkhomedir.so skel=/etc/skel/ umask=0027
session     optional      pam_keyinit.so revoke
session     required      pam_limits.so
session     [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
session     sufficient    pam_sss.so
session     required      pam_unix.so

And now /etc/pam.d/password-auth:

auth        required      pam_env.so
auth        sufficient    pam_unix.so nullok try_first_pass
auth        requisite     pam_succeed_if.so uid >= 500 quiet
auth        sufficient    pam_krb5.so use_first_pass
auth        sufficient    pam_ldap.so use_first_pass
auth        required      pam_deny.so

account     required      pam_unix.so broken_shadow
account     sufficient    pam_localuser.so
account     sufficient    pam_succeed_if.so uid < 500 quiet
account     [default=bad success=ok user_unknown=ignore] pam_ldap.so
account     [default=bad success=ok user_unknown=ignore] pam_krb5.so
account     required      pam_permit.so

password    requisite     pam_cracklib.so try_first_pass retry=3 type=
password    sufficient    pam_unix.so md5 shadow nullok try_first_pass use_authtok
password    sufficient    pam_krb5.so use_authtok
password    sufficient    pam_ldap.so use_authtok
password    required      pam_deny.so

session     optional      pam_keyinit.so revoke
session     required      pam_limits.so
session     optional      pam_oddjob_mkhomedir.so skel=/etc/skel/ umask=0027
session     [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
session     required      pam_unix.so
session     optional      pam_krb5.so
session     optional      pam_ldap.so

Thanks again for any light you can shed on my conundrum!

Answer 1

Don't have reputation to add comments, but to debug PAM auth problems you are looking on the wrong side, you need to do that on server side.

To do so ssh into the server and run:

sshd -d -D -p 4000

That will start an ssh daemon on port 4000 (-p 4000) with debug enabled (-d), without detaching from console (-D).

Then try again but connecting to port 4000, on the server side you will see a lot of output, there's the truth of the root of your problem, not on client side.

If you need more verbose you can add multiple -d, up to three.

If you can't figure out from the output paste it here for us to see it.

Answer 2

So I found a solution, I don't know if it's the best, but it lets me SSH in on the first try. The trick was to get rid of all password-auth includes in /etc/pam.d/sshd, and to replace them with system-auth includes. So, my final /etc/pam.d/sshd file looks like this:

#%PAM-1.0
auth       required     pam_sepermit.so
auth       include      system-auth
#auth      include      password-auth
#account   required     pam_nologin.so
account    required     pam_access.so
account    include      system-auth
password   include      system-auth
#account   include      password-auth
#password  include      password-auth
# pam_selinux.so close should be the first session rule
session    required     pam_selinux.so close
session    required     pam_loginuid.so
# pam_selinux.so open should only be followed by sessions to be executed in the user context
session    required     pam_selinux.so open env_params
session    optional     pam_keyinit.so force revoke
#session   include      password-auth
session    include      system-auth

As you can probably tell, I'm a little new to PAM. The system-auth and password-auth files are included above, in my original question. Can someone explain to me why the above changes fixed things? I did this same fix, replacing all include password-auth statements with include system-auth, in /etc/pam.d/crond since it wasn't allowing anyone (including root) to use cron/crontab. What's the difference between these configurations? Have these changes compromised my security in any way?

Thanks again for all the help and suggestions.