Hi folks. This morning I found that one of my IPA servers no longer
wants to authenticate any users (specifically, it doesn't want to issue
any TGTs to users).
It's a fully updated RHEL 9 server; I am sure this has only been a
problem since upgrading to RHEL 9.2 (see my remarks about krb5kdc.log
below); my other servers are on RHEL 8 and are working fine.
Package versions:
ipa-client-common-4.10.1-6.el9.noarch
ipa-server-common-4.10.1-6.el9.noarch
ipa-healthcheck-core-0.12-1.el9.noarch
ipa-selinux-4.10.1-6.el9.noarch
ipa-common-4.10.1-6.el9.noarch
ipa-client-4.10.1-6.el9.x86_64
ipa-server-4.10.1-6.el9.x86_64
ipa-server-dns-4.10.1-6.el9.noarch
ipa-healthcheck-0.12-1.el9.noarch
I see the following syslog messages when trying to SSH in to the server:
May 12 08:34:52 sshd[2207]: main: sshd: ssh-rsa algorithm is disabled
May 12 08:34:52 sshd[2207]: Postponed keyboard-interactive for user from
192.168.0.23 port 42210 ssh2 [preauth]
May 12 08:34:56 sshd[2207]: Postponed keyboard-interactive/pam for user
from 192.168.0.23 port 42210 ssh2 [preauth]
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: request received
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: user query start
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: user query end:
uid=user,cn=users,cn=accounts,dc=ipa,dc=example,dc=com
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: bind start:
uid=user,cn=users,cn=accounts,dc=ipa,dc=example,dc=com
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: bind end: success
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: sent: 0 data: 20
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: ..sent: 20 data: 20
May 12 08:35:02 ipa-otpd[2200]: u...@example.com: response sent:
Access-Accept
May 12 08:35:02 krb5_child[2213]: Generic error (see e-text)
May 12 08:35:02 krb5_child[2213]: Generic error (see e-text)
May 12 08:35:02 sshd[2211]: pam_sss(sshd:auth): authentication failure;
logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.0.23 user=user
May 12 08:35:02 sshd[2211]: pam_sss(sshd:auth): received for user user: 4
(System error)
May 12 08:35:04 sshd[2207]: error: PAM: Authentication failure for user
from 192.168.0.23
/var/log/sssd/krb5_child.log gives me:
(2023-05-12 8:39:50): [krb5_child[2271]] [get_and_save_tgt] (0x0020):
[RID#79] 2009: [-1765328324][Generic error (see e-text)]
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING
BACKTRACE:
* (2023-05-12 8:39:50): [krb5_child[2271]] [main] (0x0400): [RID#79]
krb5_child started.
* (2023-05-12 8:39:50): [krb5_child[2271]] [unpack_buffer] (0x1000):
[RID#79] total buffer size: [140]
* (2023-05-12 8:39:50): [krb5_child[2271]] [unpack_buffer] (0x0100):
[RID#79] cmd [241 (auth)] uid [2000000503] gid [2000000503] validate [true]
enterprise principal [false] offline [false] UPN [u...@example.com]
* (2023-05-12 8:39:50): [krb5_child[2271]] [unpack_buffer] (0x0100):
[RID#79] ccname: [KCM:] old_ccname: [KCM:] keytab: [/etc/krb5.keytab]
* (2023-05-12 8:39:50): [krb5_child[2271]] [switch_creds] (0x0200):
[RID#79] Switch user to [2000000503][2000000503].
* (2023-05-12 8:39:50): [krb5_child[2271]] [switch_creds] (0x0200):
[RID#79] Switch user to [0][0].
* (2023-05-12 8:39:50): [krb5_child[2271]] [k5c_check_old_ccache]
(0x4000): [RID#79] Ccache_file is [KCM:] and is active and TGT is valid.
* (2023-05-12 8:39:50): [krb5_child[2271]] [k5c_setup_fast] (0x0100):
[RID#79] Fast principal is set to [host/ipa6.example....@example.com]
* (2023-05-12 8:39:50): [krb5_child[2271]] [find_principal_in_keytab]
(0x4000): [RID#79] Trying to find principal host/ipa6.example....@example.com
in keytab.
* (2023-05-12 8:39:50): [krb5_child[2271]] [match_principal] (0x1000):
[RID#79] Principal matched to the sample (host/ipa6.example....@example.com).
* (2023-05-12 8:39:50): [krb5_child[2271]] [check_fast_ccache]
(0x0200): [RID#79] FAST TGT is still valid.
* (2023-05-12 8:39:50): [krb5_child[2271]] [become_user] (0x0200):
[RID#79] Trying to become user [2000000503][2000000503].
* (2023-05-12 8:39:50): [krb5_child[2271]] [main] (0x2000): [RID#79]
Running as [2000000503][2000000503].
* (2023-05-12 8:39:50): [krb5_child[2271]] [set_lifetime_options]
(0x0100): [RID#79] No specific renewable lifetime requested.
* (2023-05-12 8:39:50): [krb5_child[2271]] [set_lifetime_options]
(0x0100): [RID#79] No specific lifetime requested.
* (2023-05-12 8:39:50): [krb5_child[2271]] [set_canonicalize_option]
(0x0100): [RID#79] Canonicalization is set to [true]
* (2023-05-12 8:39:50): [krb5_child[2271]] [main] (0x0400): [RID#79]
Will perform auth
* (2023-05-12 8:39:50): [krb5_child[2271]] [main] (0x0400): [RID#79]
Will perform online auth
* (2023-05-12 8:39:50): [krb5_child[2271]] [tgt_req_child] (0x1000):
[RID#79] Attempting to get a TGT
* (2023-05-12 8:39:50): [krb5_child[2271]] [get_and_save_tgt]
(0x0400): [RID#79] Attempting kinit for realm [EXAMPLE.COM]
* (2023-05-12 8:39:50): [krb5_child[2271]] [sss_krb5_responder]
(0x4000): [RID#79] Got question [otp].
* (2023-05-12 8:39:50): [krb5_child[2271]] [get_and_save_tgt]
(0x0020): [RID#79] 2009: [-1765328324][Generic error (see e-text)]
********************** BACKTRACE DUMP ENDS HERE
*********************************
(2023-05-12 8:39:50): [krb5_child[2271]] [map_krb5_error] (0x0020):
[RID#79] 2138: [-1765328324][Generic error (see e-text)]
/var/log/krb5kdc.log gives me a "No such file or directory" error:
May 12 08:41:31 ipa6.example.com krb5kdc[1575](info): AS_REQ (4 etypes
{aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), aes128-cts-hmac-sha1-96(17)}) 192.168.0.6:
NEEDED_PREAUTH: u...@example.com for krbtgt/example....@example.com, Additional
pre-authentication required
May 12 08:41:31 ipa6.example.com krb5kdc[1575](info): closing down fd 11
May 12 08:41:31 ipa6.example.com krb5kdc[1575](info): AS_REQ (4 etypes
{aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), aes128-cts-hmac-sha1-96(17)}) 192.168.0.6:
NEEDED_PREAUTH: u...@example.com for krbtgt/example....@example.com, Additional
pre-authentication required
May 12 08:41:31 ipa6.example.com krb5kdc[1575](info): closing down fd 11
May 12 08:41:42 ipa6.example.com krb5kdc[1575](info): AS_REQ (4 etypes
{aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), aes128-cts-hmac-sha1-96(17)}) 192.168.0.6:
NEEDED_PREAUTH: u...@example.com for krbtgt/example....@example.com, Additional
pre-authentication required
May 12 08:41:42 ipa6.example.com krb5kdc[1575](info): closing down fd 11
May 12 08:41:42 ipa6.example.com krb5kdc[1573](info): AS_REQ (4 etypes
{aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), aes128-cts-hmac-sha1-96(17)}) 192.168.0.6:
NEEDED_PREAUTH: u...@example.com for krbtgt/example....@example.com, Additional
pre-authentication required
May 12 08:41:42 ipa6.example.com krb5kdc[1573](info): closing down fd 11
May 12 08:41:42 ipa6.example.com krb5kdc[1573](info): AS_REQ :
handle_authdata (2)
May 12 08:41:42 ipa6.example.com krb5kdc[1573](info): AS_REQ (4 etypes
{aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20),
aes128-cts-hmac-sha256-128(19), aes128-cts-hmac-sha1-96(17)}) 192.168.0.6:
HANDLE_AUTHDATA: u...@example.com for krbtgt/example....@example.com, No such
file or directory
May 12 08:41:42 ipa6.example.com krb5kdc[1573](info): closing down fd 11
There's no instance of this 'No such file or directory' message in
krb5kdc.log before this morning, and I did the RHEL 9.2 upgrade on 9th
May, just a couple of days ago. So it's possible that this is a problem
introduced by the upgrade a couple of days ago, that has been noticed
today (perhaps IPA clients were talking to other servers until this
morning).
Other IPA servers log an ISSUE message at the same point, so I guess the
problem is with krb5kdc, I just don't know what to check next.
Here's the relevant code (I think) in krb5kdc:
<https://github.com/krb5/krb5/blob/e806d1223329fe4b6d9738237893dda27b616bb6/src/kdc/do_as_req.c#L270>.
The user is able to log in to the directory server with a simple bind:
# ldapwhoami -H ldapi://%2frun%2fslapd-EXAMPLE-COM.socket -D
uid=user,cn=users,cn=accounts,dc=ipa,dc=example,dc=com -W
Enter LDAP Password:
dn: uid=user,cn=users,cn=accounts,dc=ipa,dc=example,dc=com
... so dirsrv seems to be working fine.
'ipactl status' reports all services are running. ipa-healthcheck is
giving me one failure, I don't think it's relevant to the krb5kdc errors
but it's something I'll look into after:
{
"source": "pki.server.healthcheck.clones.connectivity_and_data",
"check": "ClonesConnectivyAndDataCheck",
"result": "ERROR",
"uuid": "eb35c2fd-d292-4426-a1ad-8d1adfc5349a",
"when": "20230512084503Z",
"duration": "10.003213",
"kw": {
"status": "ERROR: pki-tomcat : Unable to reach KRA at
https://ipa6.example.com:443: Request timed out"
}
},
I am able to run 'kinit -k', e.g,. get a TGT as host/ipa6.example.com,
so it's not like krb5kdc is totally busted. It just doesn't work for
users any more!
As always I'd be grateful for any assistance. :)
--
Sam Morris <https://robots.org.uk/>
PGP: rsa4096/CAAA AA1A CA69 A83A 892B 1855 D20B 4202 5CDA 27B9
_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-le...@lists.fedorahosted.org
Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives:
https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org
Do not reply to spam, report it:
https://pagure.io/fedora-infrastructure/new_issue
