On Tue, Feb 09, 2021 at 11:33:15AM -0500, Robert Kudyba via FreeIPA-users wrote:
> >
> > looks like sshd is trying to read /home/ouruser/.ssh/authorized_keys and
> > is stuck. Can you read this file from the command line? Is it e.g. on
> > NFS which might not be properly mounted?
> >
> > Does it work if you skip pubkey authentication
> >
> > ssh -o PubkeyAuthentication=no -vv -k ouruser@ourserver
> >
> > bye,
> > Sumit
> >
>
> Thanks for the suggestion. What happens is the NIS password works. The
> FreeIPA password, which I update with:
> ipa user-mod ouruser --setattr "userpassword=xxxx", fails with the below
> errors/logs
>
> Feb 9 11:10:34 ourserver sshd[381563]: debug1: Forked child 536086.
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: Set
> /proc/self/oom_score_adj to 0
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: rexec start in 5 out 5
> newsock 5 pipe 7 sock 8
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: inetd sockets after
> dupping: 4, 4
> Feb 9 11:10:34 ourserver sshd[536086]: Connection from x.x.x.x port 53332
> on 150.108.64.156 port 22 rdomain ""
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: Local version string
> SSH-2.0-OpenSSH_8.4
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: Remote protocol version
> 2.0, remote software version OpenSSH_8.4
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: match: OpenSSH_8.4 pat
> OpenSSH* compat 0x04000000
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SELinux support disabled
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: permanently_set_uid: 74/74
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: list_hostkey_types:
> rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_KEXINIT sent
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_KEXINIT received
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: algorithm:
> curve25519-sha256 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: host key algorithm:
> ecdsa-sha2-nistp256 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: client->server cipher:
> aes256-gcm@openssh.com MAC: <implicit> compression: none [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: server->client cipher:
> aes256-gcm@openssh.com MAC: <implicit> compression: none [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: curve25519-sha256
> need=32 dh_need=32 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: curve25519-sha256
> need=32 dh_need=32 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: expecting
> SSH2_MSG_KEX_ECDH_INIT [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: rekey out after 4294967296
> blocks [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_NEWKEYS sent
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: Sending SSH2_MSG_EXT_INFO
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: expecting SSH2_MSG_NEWKEYS
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_NEWKEYS received
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: rekey in after 4294967296
> blocks [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: KEX done [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: userauth-request for user
> ouruser service ssh-connection method none [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: attempt 0 failures 0
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: PAM: initializing for
> "ouruser"
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: PAM: setting PAM_RHOST to
> "x.x.x.x"
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: PAM: setting PAM_TTY to
> "ssh"
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: userauth-request for user
> ouruser service ssh-connection method keyboard-interactive [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: attempt 1 failures 0
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: keyboard-interactive devs
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: auth2_challenge:
> user=ouruser devs= [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kbdint_alloc: devices 'pam'
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: auth2_challenge_start:
> trying authentication method 'pam' [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: Postponed keyboard-interactive for
> ouruser from x.x.x.x port 53332 ssh2 [preauth]
> Feb 9 11:10:39 ourserver sshd[536091]: pam_unix(sshd:auth): authentication
> failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=x.x.x.x user=ouruser
> Feb 9 11:10:39 ourserver sshd[536091]: pam_sss(sshd:auth): authentication
> failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=x.x.x.x user=ouruser
> Feb 9 11:10:39 ourserver sshd[536091]: pam_sss(sshd:auth): received for
> user ouruser: 9 (Authentication service cannot retrieve authentication info)
> Feb 9 11:10:41 ourserver sshd[536086]: error: PAM: Authentication failure
> for ouruser from x.x.x.x
> Feb 9 11:10:41 ourserver sshd[536086]: Failed keyboard-interactive/pam for
> ouruser from x.x.x.x port 53332 ssh2
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: userauth-request for user
> ouruser service ssh-connection method keyboard-interactive [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: attempt 2 failures 1
> [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: keyboard-interactive devs
> [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: auth2_challenge:
> user=ouruser devs= [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: kbdint_alloc: devices 'pam'
> [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: auth2_challenge_start:
> trying authentication method 'pam' [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: Postponed keyboard-interactive for
> ouruser from x.x.x.x port 53332 ssh2 [preauth]
>
>
> Feb 9 11:10:34 ourserver sshd[381563]: debug1: Forked child 536086.
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: Set
> /proc/self/oom_score_adj to 0
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: rexec start in 5 out 5
> newsock 5 pipe 7 sock 8
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: inetd sockets after
> dupping: 4, 4
> Feb 9 11:10:34 ourserver sshd[536086]: Connection from x.x.x.x port 53332
> on 150.108.64.156 port 22 rdomain ""
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: Local version string
> SSH-2.0-OpenSSH_8.4
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: Remote protocol version
> 2.0, remote software version OpenSSH_8.4
> Feb 9 11:10:34 ourserver sshd[536086]: debug1: match: OpenSSH_8.4 pat
> OpenSSH* compat 0x04000000
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SELinux support disabled
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: permanently_set_uid: 74/74
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: list_hostkey_types:
> rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_KEXINIT sent
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_KEXINIT received
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: algorithm:
> curve25519-sha256 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: host key algorithm:
> ecdsa-sha2-nistp256 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: client->server cipher:
> aes256-gcm@openssh.com MAC: <implicit> compression: none [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: server->client cipher:
> aes256-gcm@openssh.com MAC: <implicit> compression: none [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: curve25519-sha256
> need=32 dh_need=32 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kex: curve25519-sha256
> need=32 dh_need=32 [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: expecting
> SSH2_MSG_KEX_ECDH_INIT [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: rekey out after 4294967296
> blocks [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_NEWKEYS sent
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: Sending SSH2_MSG_EXT_INFO
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: expecting SSH2_MSG_NEWKEYS
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: SSH2_MSG_NEWKEYS received
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: rekey in after 4294967296
> blocks [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: KEX done [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: userauth-request for user
> ouruser service ssh-connection method none [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: attempt 0 failures 0
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: PAM: initializing for
> "ouruser"
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: PAM: setting PAM_RHOST to
> "x.x.x.x"
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: PAM: setting PAM_TTY to
> "ssh"
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: userauth-request for user
> ouruser service ssh-connection method keyboard-interactive [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: attempt 1 failures 0
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: keyboard-interactive devs
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: auth2_challenge:
> user=ouruser devs= [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: kbdint_alloc: devices 'pam'
> [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: debug1: auth2_challenge_start:
> trying authentication method 'pam' [preauth]
> Feb 9 11:10:35 ourserver sshd[536086]: Postponed keyboard-interactive for
> ouruser from x.x.x.x port 53332 ssh2 [preauth]
> Feb 9 11:10:39 ourserver sshd[536091]: pam_unix(sshd:auth): authentication
> failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=x.x.x.x user=ouruser
> Feb 9 11:10:39 ourserver sshd[536091]: pam_sss(sshd:auth): authentication
> failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=x.x.x.x user=ouruser
> Feb 9 11:10:39 ourserver sshd[536091]: pam_sss(sshd:auth): received for
> user ouruser: 9 (Authentication service cannot retrieve authentication info)
> Feb 9 11:10:41 ourserver sshd[536086]: error: PAM: Authentication failure
> for ouruser from x.x.x.x
> Feb 9 11:10:41 ourserver sshd[536086]: Failed keyboard-interactive/pam for
> ouruser from x.x.x.x port 53332 ssh2
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: userauth-request for user
> ouruser service ssh-connection method keyboard-interactive [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: attempt 2 failures 1
> [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: keyboard-interactive devs
> [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: auth2_challenge:
> user=ouruser devs= [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: kbdint_alloc: devices 'pam'
> [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: debug1: auth2_challenge_start:
> trying authentication method 'pam' [preauth]
> Feb 9 11:10:41 ourserver sshd[536086]: Postponed keyboard-interactive for
> ouruser from x.x.x.x port 53332 ssh2 [preauth]
>
> With the NIS password the logs show this:
Hi,
did you drop what happened before or is this the only debug output for
the NIS password?
The below here are just logs from /var/log/secure for the user that successfully logs in with his/her NIS password.
By "drop what happened before" do you mean the original log snip? Yes I removed those in an attempt to shorten the message content.
> Feb 9 11:16:57 debug1: do_pam_account: called
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: PAM: num PAM env strings 2
> Feb 9 11:16:57 ourserver sshd[536226]: Postponed keyboard-interactive/pam
> for cai from 150.108.68.26 port 53646 ssh2 [preauth]
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: do_pam_account: called
> Feb 9 11:16:57 ourserver sshd[536226]: Accepted keyboard-interactive/pam
> for cai from 150.108.68.26 port 53646 ssh2
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: monitor_child_preauth: cai
> has been authenticated by privileged process
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: monitor_read_log: child log
> fd closed
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: audit_event: unhandled
> event 2
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: temporarily_use_uid:
> 5879/200 (e=0/0)
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: ssh_gssapi_storecreds: Not
> a GSSAPI mechanism
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: restore_uid: 0/0
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: SELinux support disabled
> Feb 9 11:16:57 ourserver sshd[536226]: debug1: PAM: establishing
> credentials
> Feb 9 11:16:57 ourserver systemd[536237]: pam_unix(systemd-user:session):
> session opened for user cai(uid=5879) by (uid=0)
>
> What options should be set in /etc/ssh/sshd_config? Is sssd necessary for
> this to work with the FreeIPA password
Yes, SSSD must be configured and runnnig. ssd does appear to be working fine and in /etc/ipa/ca.crt and the service is running correctly:
[domain/
ourdomain.edu]
id_provider = ipa
ipa_server_mode = True
ipa_server =
ourdomain.eduipa_domain =
ourdomain.eduipa_hostname =
ourdomain.eduauth_provider = ipa
chpass_provider = ipa
access_provider = ipa
cache_credentials = True
ldap_tls_cacert = /etc/ipa/ca.crt
krb5_store_password_if_offline = True
[sssd]
services = nss, pam, ifp, ssh, sudo
domains =
ourdomain.edu[nss]
homedir_substring = /home
memcache_timeout = 600
[ifp]
allowed_uids = ipaapi, root
systemctl status sssd
* sssd.service - System Security Services Daemon
Loaded: loaded (/usr/lib/systemd/system/sssd.service; enabled; vendor preset: enabled)
Active: active (running) since Fri 2021-01-29 14:31:34 EST; 1 weeks 3 days ago