"Credential cache is empty" error preventing certmonger from renewing a host's certificate
I've got an IPA client on which certmonger is unable to renew a certificate.
Here are the log messages from certmonger...
2023-06-20 08:24:49 [622035] Certificate submission attempt complete. 2023-06-20 08:24:49 [622035] Child status = 2. 2023-06-20 08:24:49 [622035] Child output: "Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Credential cache is > " 2023-06-20 08:24:49 [622035] Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more infor>
Here's the tracking request, nothing looks out of the ordinary to me...
# getcert list -i 20220519165212 Number of certificates and requests being tracked: 2. Request ID '20220519165212': status: MONITORING ca-error: Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Cre. stuck: no key pair storage: type=FILE,location='/etc/cockpit/ws-certs.d/51-myhost.key' certificate: type=FILE,location='/etc/cockpit/ws-certs.d/51-myhost.crt' CA: IPA issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM subject: CN=myhost.ipa.example.com,O=IPA.EXAMPLE.COM issued: 2023-03-25 16:52:45 UTC expires: 2023-06-23 16:52:45 UTC dns: myhost.ipa.example.com principal name: host/myhost.ipa.example.com@IPA.EXAMPLE.COM key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment eku: id-kp-serverAuth,id-kp-clientAuth pre-save command: post-save command: track: yes auto-renew: yes
In order to rule out a problem with ipa5, I used 'ipactl' to stop everything on it, then re-ran 'getcert resubmit -i 20220519165212'. In the subsequent output of 'getcert list -i 20220519165212' I saw the same error message displayed but with the name of a different IPA server. So I don't think this is a problem with a particular IPA server.
Next I extracted the CSR data from '/var/lib/certmonger/requests/20220519165212' to a file, authenticated as host/myhost.ipa.example.com (with 'kinit -k') and then ran 'ipa cert-request host.req --principal=host/myhost.ipa.example.com', which worked!
So perhaps the problem is with certmonger, or with the way in which it interacts with the IPA server that differs from simply running 'ipa cert-request' as I did manually.
I also tried to look for logs on the server side, but I didn't find anything very useful. /var/log/httpd/access_log has:
192.168.0.4 - - [20/Jun/2023:13:21:53 +0000] "POST /ipa/json HTTP/1.1" 401 2719 192.168.0.4 - host/myhost.ipa.example.com@IPA.EXAMPLE.COM [20/Jun/2023:13:21:53 +0000] "POST /ipa/json HTTP/1.1" 200 526
So it looks like certmonger is having no problem authenticating to ipaapi. httpd is logging:
$ journalctl -u httpd -e Jun 20 13:21:56 [121899]: GSSAPI client step 1 Jun 20 13:21:56 [121899]: GSSAPI client step 1 Jun 20 13:21:57 [121899]: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Credential cache is empty)
So is looks like ipaapi might be having trouble using Kerberos as a client?
I added KRB5_TRACE=/var/lib/httpd/krb5.trace to httpd.service's Environment= and restarted it, then re-ran 'getcert resubmit' on the tracking request. I got these messages:
[124285] 1687270136.437160: Initializing FILE:/tmp/krb5cc-httpd with default princ HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM [124285] 1687270136.437161: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> Encrypted/Credentials/v1@X-GSSPROXY: in FILE:/tmp/krb5cc-httpd [124285] 1687270136.437163: Retrieving HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> Encrypted/Credentials/v1@X-GSSPROXY: from FILE:/tmp/krb5cc-httpd with result: 0/Success [124285] 1687270136.437165: Initializing FILE:/run/ipa/ccaches/host~myhost.ipa.example.com@IPA.EXAMPLE.COM-h3azdl with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124285] 1687270136.437166: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> Encrypted/Credentials/v1@X-GSSPROXY: in FILE:/run/ipa/ccaches/host~myhost.ipa.example.com@IPA.EXAMPLE.COM-h3azdl
No errors there either. I set KRB5_TRACE=/var/lib/gssproxy/krb5.trace in gssproxy.service's Environment= and got:
[124798] 1687270460.854044: Resolving unique ccache of type MEMORY [124798] 1687270460.854045: Initializing MEMORY:GJanRRF with default princ HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270460.854046: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:GJanRRF [124798] 1687270460.854047: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:GJanRRF [124798] 1687270460.854048: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:GJanRRF [124798] 1687270460.854049: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:GJanRRF [124798] 1687270460.854052: Destroying ccache MEMORY:GJanRRF [124798] 1687270460.854054: Resolving unique ccache of type MEMORY [124798] 1687270460.854055: Initializing MEMORY:Cn5E8Va with default princ HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270460.854056: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:Cn5E8Va [124798] 1687270460.854057: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:Cn5E8Va [124798] 1687270460.854058: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:Cn5E8Va [124798] 1687270460.854059: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:Cn5E8Va [124798] 1687270460.854062: Destroying ccache MEMORY:Cn5E8Va [124798] 1687270460.854064: Resolving unique ccache of type MEMORY [124798] 1687270460.854065: Initializing MEMORY:8e5DNHy with default princ HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270460.854066: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:8e5DNHy [124798] 1687270460.854067: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:8e5DNHy [124798] 1687270460.854068: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:8e5DNHy [124798] 1687270460.854069: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:8e5DNHy [124798] 1687270460.854071: Decrypted AP-REQ with server principal HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM: aes256-cts/E0A2 [124798] 1687270460.854072: AP-REQ ticket: host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM, session key aes256-cts/1952 [124798] 1687270460.854073: Negotiated enctype based on authenticator: aes256-cts [124798] 1687270460.854074: Authenticator contains subkey: aes256-cts/2098 [124798] 1687270460.854075: Resolving unique ccache of type MEMORY [124798] 1687270460.854076: Initializing MEMORY:FX6Yqgq with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270460.854077: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:FX6Yqgq [124798] 1687270460.854078: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:FX6Yqgq [124798] 1687270460.854079: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:FX6Yqgq [124798] 1687270460.854080: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:FX6Yqgq [124798] 1687270460.854081: Storing config in MEMORY:FX6Yqgq for : proxy_impersonator: HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270460.854082: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:FX6Yqgq [124798] 1687270460.854083: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM in MEMORY:FX6Yqgq [124798] 1687270460.854085: Creating AP-REP, time 1687270460.725581, subkey aes256-cts/BB66, seqnum 668121546 [124798] 1687270461.005570: Destroying ccache MEMORY:FX6Yqgq [124798] 1687270461.005573: Destroying ccache MEMORY:8e5DNHy [124798] 1687270461.005575: Resolving unique ccache of type MEMORY [124798] 1687270461.005576: Initializing MEMORY:NmnNwyD with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270461.005577: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM in MEMORY:NmnNwyD [124798] 1687270461.005578: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:NmnNwyD [124798] 1687270461.005579: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:NmnNwyD [124798] 1687270461.005580: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:NmnNwyD [124798] 1687270461.005581: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:NmnNwyD [124798] 1687270461.005582: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:NmnNwyD [124798] 1687270461.005585: Destroying ccache MEMORY:NmnNwyD [124798] 1687270461.005587: Resolving unique ccache of type MEMORY [124798] 1687270461.005588: Initializing MEMORY:gUnl8Xt with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270461.005589: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM in MEMORY:gUnl8Xt [124798] 1687270461.005590: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:gUnl8Xt [124798] 1687270461.005591: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:gUnl8Xt [124798] 1687270461.005592: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:gUnl8Xt [124798] 1687270461.005593: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:gUnl8Xt [124798] 1687270461.005594: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:gUnl8Xt [124798] 1687270461.005597: Destroying ccache MEMORY:gUnl8Xt [124798] 1687270461.005599: Resolving unique ccache of type MEMORY [124798] 1687270461.005600: Initializing MEMORY:wBGblf3 with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270461.005601: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM in MEMORY:wBGblf3 [124798] 1687270461.005602: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:wBGblf3 [124798] 1687270461.005603: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:wBGblf3 [124798] 1687270461.005604: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:wBGblf3 [124798] 1687270461.005605: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:wBGblf3 [124798] 1687270461.005606: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:wBGblf3 [124798] 1687270461.005609: Destroying ccache MEMORY:wBGblf3 [124798] 1687270461.005611: Resolving unique ccache of type MEMORY [124798] 1687270461.005612: Initializing MEMORY:4uHf47g with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270461.005613: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM in MEMORY:4uHf47g [124798] 1687270461.005614: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:4uHf47g [124798] 1687270461.005615: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:4uHf47g [124798] 1687270461.005616: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:4uHf47g [124798] 1687270461.005617: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:4uHf47g [124798] 1687270461.005618: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:4uHf47g [124798] 1687270461.005621: Destroying ccache MEMORY:4uHf47g [124798] 1687270461.005623: Resolving unique ccache of type MEMORY [124798] 1687270461.005624: Initializing MEMORY:9LUdBez with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270461.005625: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM in MEMORY:9LUdBez [124798] 1687270461.005626: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:9LUdBez [124798] 1687270461.005627: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:9LUdBez [124798] 1687270461.005628: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:9LUdBez [124798] 1687270461.005629: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:9LUdBez [124798] 1687270461.005630: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:9LUdBez [124798] 1687270461.005634: Initializing MEMORY:cred_allowed_0x7f85d9152380 with default princ host/myhost.ipa.example.com@IPA.EXAMPLE.COM [124798] 1687270461.005635: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in MEMORY:cred_allowed_0x7f85d9152380 [124798] 1687270461.005636: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:cred_allowed_0x7f85d9152380 [124798] 1687270461.005637: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM@X-CACHECONF: in MEMORY:cred_allowed_0x7f85d9152380 [124798] 1687270461.005638: Storing HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:cred_allowed_0x7f85d9152380 [124798] 1687270461.005639: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:cred_allowed_0x7f85d9152380 [124798] 1687270461.005640: Storing host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM in MEMORY:cred_allowed_0x7f85d9152380 [124798] 1687270461.005641: Destroying ccache MEMORY:cred_allowed_0x7f85d9152380 [124798] 1687270461.005644: Getting credentials host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> ldap/ipa5.ipa.example.com@ using ccache MEMORY:9LUdBez [124798] 1687270461.005645: Retrieving host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/start_realm@X-CACHECONF: from MEMORY:9LUdBez with result: -1765328243/Matching credential not found [124798] 1687270461.005646: Retrieving host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> ldap/ipa5.ipa.example.com@ from MEMORY:9LUdBez with result: -1765328243/Matching credential not found [124798] 1687270461.005647: Retrying host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> ldap/ipa5.ipa.example.com@IPA.EXAMPLE.COM with result: -1765328243/Matching credential not found [124798] 1687270461.005648: Retrieving host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM from MEMORY:9LUdBez with result: 0/Success [124798] 1687270461.005649: Getting credentials HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM using ccache MEMORY:9LUdBez [124798] 1687270461.005650: Retrieving host/myhost.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/start_realm@X-CACHECONF: from MEMORY:9LUdBez with result: -1765328243/Matching credential not found [124798] 1687270461.005651: Retrieving HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM from MEMORY:9LUdBez with result: 0/Success [124798] 1687270461.005652: Get cred via TGT krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM after requesting ldap/ipa5.ipa.example.com@IPA.EXAMPLE.COM (canonicalize on) [124798] 1687270461.005653: Generated subkey for TGS request: aes256-cts/FBB4 [124798] 1687270461.005654: etypes requested in TGS request: aes256-cts, aes256-sha2, camellia256-cts, aes128-cts, aes128-sha2, camellia128-cts [124798] 1687270461.005656: Encoding request body and padata into FAST request [124798] 1687270461.005657: Sending request (5335 bytes) to IPA.EXAMPLE.COM [124798] 1687270461.005658: Initiating TCP connection to stream 192.168.0.5:88 [124798] 1687270461.005659: Sending TCP request to stream 192.168.0.5:88 [124798] 1687270461.005660: Received answer (508 bytes) from stream 192.168.0.5:88 [124798] 1687270461.005661: Terminating TCP connection to stream 192.168.0.5:88 [124798] 1687270461.005662: Response was from master KDC [124798] 1687270461.005663: Decoding FAST response [124798] 1687270461.005664: Decoding FAST response [124798] 1687270461.005665: Got cred; -1765328371/KDC can't fulfill requested option [124798] 1687270461.005669: Destroying ccache MEMORY:9LUdBez
The only thing that looks like an error in that output is "KDC can't fulfill requested option".
The last place I can think of looking is in /var/log/krb5kdc.log:
Jun 20 14:17:34 ipa5.ipa.example.com krb5kdc[119948](info): TGS_REQ : handle_authdata (-1765328371) Jun 20 14:17:34 ipa5.ipa.example.com krb5kdc[119948](info): TGS_REQ (6 etypes {aes256-cts-hmac-sha1-96(18), aes256-cts-hmac-sha384-192(20), camellia256-cts-cmac(26), aes128-cts-hmac-sha1-96(17), aes128-cts-hmac-sha256-128(19), camellia128-cts-cmac(25)}) 192.168.0.5: HANDLE_AUTHDATA: authtime 1687270653, etypes {rep=UNSUPPORTED:(0)} HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM for ldap/ipa5.ipa.example.com@IPA.EXAMPLE.COM, KDC can't fulfill requested option Jun 20 14:17:34 ipa5.ipa.example.com krb5kdc[119948](info): ... CONSTRAINED-DELEGATION s4u-client=host/myhost.ipa.example.com@IPA.EXAMPLE.COM Jun 20 14:17:34 ipa5.ipa.example.com krb5kdc[119948](info): closing down fd 12
There's another instance of "KDC can't fulfill requested option".
My best guess is that there's something wrong with the constrained delegation setup that lets ipaapi access the directory on behalf of the client host? But this looks fine:
$ ipa servicedelegationrule-show ipa-http-delegation Delegation name: ipa-http-delegation Allowed Target: ipa-ldap-delegation-targets, ipa-cifs-delegation-targets Member principals: HTTP/ipa3.ipa.example.com@IPA.EXAMPLE.COM, HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM, HTTP/ipa6.ipa.example.com@IPA.EXAMPLE.COM
$ ipa servicedelegationtarget-show ipa-ldap-delegation-targets Delegation name: ipa-ldap-delegation-targets Member principals: ldap/ipa3.ipa.example.com@IPA.EXAMPLE.COM, ldap/ipa5.ipa.example.com@IPA.EXAMPLE.COM, ldap/ipa6.ipa.example.com@IPA.EXAMPLE.COM
... and in any case a simple 'ipa cert-request' as the host worked fine, it's only certmonger's attempts to request a certificate that are failing.
The IPA client has:
ipa-client-4.9.11-5.module+el8.8.0+18147+84fe6ec1.x86_64 certmonger-0.79.17-2.el8.x86_64
... and the server has:
ipa-server-4.9.11-5.module+el8.8.0+18146+a1d8660b.x86_64
Any troubleshooting help is really appreciated!
On 20/06/2023 15:34, Sam Morris via FreeIPA-users wrote:
I've got an IPA client on which certmonger is unable to renew a certificate.
Here are the log messages from certmonger...
2023-06-20 08:24:49 [622035] Certificate submission attempt complete. 2023-06-20 08:24:49 [622035] Child status = 2. 2023-06-20 08:24:49 [622035] Child output: "Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Credential cache is > " 2023-06-20 08:24:49 [622035] Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more infor>
Today I restarted certmonger (in order to increase its debug level) and the newly-started instance immediately resubmitted its request and was issued with a new certificate. So I guess the problem was on the client after all.
Sam Morris via FreeIPA-users wrote:
On 20/06/2023 15:34, Sam Morris via FreeIPA-users wrote:
I've got an IPA client on which certmonger is unable to renew a certificate.
Here are the log messages from certmonger...
2023-06-20 08:24:49 [622035] Certificate submission attempt complete. 2023-06-20 08:24:49 [622035] Child status = 2. 2023-06-20 08:24:49 [622035] Child output: "Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Credential cache is > " 2023-06-20 08:24:49 [622035] Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more infor>
Today I restarted certmonger (in order to increase its debug level) and the newly-started instance immediately resubmitted its request and was issued with a new certificate. So I guess the problem was on the client after all.
How old is certmonger? There was a file descriptor leak issue fixed within the last couple of years that would cause a problem like that IIRC.
rob
On 26/06/2023 16:05, Rob Crittenden via FreeIPA-users wrote:
Sam Morris via FreeIPA-users wrote:
On 20/06/2023 15:34, Sam Morris via FreeIPA-users wrote:
I've got an IPA client on which certmonger is unable to renew a certificate.
Here are the log messages from certmonger...
2023-06-20 08:24:49 [622035] Certificate submission attempt complete. 2023-06-20 08:24:49 [622035] Child status = 2. 2023-06-20 08:24:49 [622035] Child output: "Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Credential cache is > " 2023-06-20 08:24:49 [622035] Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more infor>
Today I restarted certmonger (in order to increase its debug level) and the newly-started instance immediately resubmitted its request and was issued with a new certificate. So I guess the problem was on the client after all.
How old is certmonger? There was a file descriptor leak issue fixed within the last couple of years that would cause a problem like that IIRC.
Thanks Rob
This was with certmonger-0.79.17-2.el8.x86_64
I didn't check to see how many open fds the process had before restarting it. The machine it was running on had been up for a couple of weeks at the time this happened.
Sam Morris via FreeIPA-users wrote:
On 26/06/2023 16:05, Rob Crittenden via FreeIPA-users wrote:
Sam Morris via FreeIPA-users wrote:
On 20/06/2023 15:34, Sam Morris via FreeIPA-users wrote:
I've got an IPA client on which certmonger is unable to renew a certificate.
Here are the log messages from certmonger...
2023-06-20 08:24:49 [622035] Certificate submission attempt complete. 2023-06-20 08:24:49 [622035] Child status = 2. 2023-06-20 08:24:49 [622035] Child output: "Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Credential cache is > " 2023-06-20 08:24:49 [622035] Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more infor>
Today I restarted certmonger (in order to increase its debug level) and the newly-started instance immediately resubmitted its request and was issued with a new certificate. So I guess the problem was on the client after all.
How old is certmonger? There was a file descriptor leak issue fixed within the last couple of years that would cause a problem like that IIRC.
Thanks Rob
This was with certmonger-0.79.17-2.el8.x86_64
I didn't check to see how many open fds the process had before restarting it. The machine it was running on had been up for a couple of weeks at the time this happened.
Ok, well the fix was done well before that. I suppose it could be another resource leak or simply unrelated but similar behavior.
rob
On 21/06/2023 09:02, Sam Morris via FreeIPA-users wrote:
On 20/06/2023 15:34, Sam Morris via FreeIPA-users wrote:
I've got an IPA client on which certmonger is unable to renew a certificate.
Here are the log messages from certmonger...
2023-06-20 08:24:49 [622035] Certificate submission attempt complete. 2023-06-20 08:24:49 [622035] Child status = 2. 2023-06-20 08:24:49 [622035] Child output: "Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Credential cache is > " 2023-06-20 08:24:49 [622035] Server at https://ipa5.ipa.example.com/ipa/json denied our request, giving up: 2100 (Insufficient access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more infor>
Today I restarted certmonger (in order to increase its debug level) and the newly-started instance immediately resubmitted its request and was issued with a new certificate. So I guess the problem was on the client after all.
(Posting to complete the thread)
With hindsight this must be the same issue I reported a couple of months later, https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/thread/FLZYF6YKRRU5DIJ6RCYLJKI6Y2MGRE4B/, which was ultimately fixed in https://pagure.io/freeipa/issue/9448.
freeipa-users@lists.fedorahosted.org
-
Rob Crittenden -
Sam Morris