9:34 a.m.
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(a)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(a)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(a)IPA.EXAMPLE.COM
[124285] 1687270136.437161: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
Encrypted/Credentials/v1@X-GSSPROXY: in FILE:/tmp/krb5cc-httpd
[124285] 1687270136.437163: Retrieving HTTP/ipa5.ipa.example.com(a)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(a)IPA.EXAMPLE.COM
[124285] 1687270136.437166: Storing host/myhost.ipa.example.com(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270460.854046: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:GJanRRF
[124798] 1687270460.854047: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:GJanRRF
[124798] 1687270460.854048: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:GJanRRF
[124798] 1687270460.854049: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270460.854056: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:Cn5E8Va
[124798] 1687270460.854057: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:Cn5E8Va
[124798] 1687270460.854058: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:Cn5E8Va
[124798] 1687270460.854059: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270460.854066: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:8e5DNHy
[124798] 1687270460.854067: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:8e5DNHy
[124798] 1687270460.854068: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:8e5DNHy
[124798] 1687270460.854069: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)IPA.EXAMPLE.COM in MEMORY:8e5DNHy
[124798] 1687270460.854071: Decrypted AP-REQ with server principal
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM: aes256-cts/E0A2
[124798] 1687270460.854072: AP-REQ ticket: host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM
-> HTTP/ipa5.ipa.example.com(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270460.854077: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)IPA.EXAMPLE.COM in MEMORY:FX6Yqgq
[124798] 1687270460.854078: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:FX6Yqgq
[124798] 1687270460.854079: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:FX6Yqgq
[124798] 1687270460.854080: Storing HTTP/ipa5.ipa.example.com(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270460.854082: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:FX6Yqgq
[124798] 1687270460.854083: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
HTTP/ipa5.ipa.example.com(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270461.005577: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM in MEMORY:NmnNwyD
[124798] 1687270461.005578: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:NmnNwyD
[124798] 1687270461.005579: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:NmnNwyD
[124798] 1687270461.005580: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:NmnNwyD
[124798] 1687270461.005581: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:NmnNwyD
[124798] 1687270461.005582: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270461.005589: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM in MEMORY:gUnl8Xt
[124798] 1687270461.005590: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:gUnl8Xt
[124798] 1687270461.005591: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:gUnl8Xt
[124798] 1687270461.005592: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:gUnl8Xt
[124798] 1687270461.005593: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:gUnl8Xt
[124798] 1687270461.005594: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270461.005601: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM in MEMORY:wBGblf3
[124798] 1687270461.005602: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:wBGblf3
[124798] 1687270461.005603: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:wBGblf3
[124798] 1687270461.005604: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:wBGblf3
[124798] 1687270461.005605: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:wBGblf3
[124798] 1687270461.005606: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270461.005613: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM in MEMORY:4uHf47g
[124798] 1687270461.005614: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:4uHf47g
[124798] 1687270461.005615: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:4uHf47g
[124798] 1687270461.005616: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:4uHf47g
[124798] 1687270461.005617: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:4uHf47g
[124798] 1687270461.005618: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)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(a)IPA.EXAMPLE.COM
[124798] 1687270461.005625: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM in MEMORY:9LUdBez
[124798] 1687270461.005626: Storing host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/proxy_impersonator@X-CACHECONF: in MEMORY:9LUdBez
[124798] 1687270461.005627: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/refresh_time@X-CACHECONF: in MEMORY:9LUdBez
[124798] 1687270461.005628: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:9LUdBez
[124798] 1687270461.005629: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:9LUdBez
[124798] 1687270461.005630: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)IPA.EXAMPLE.COM in MEMORY:9LUdBez
[124798] 1687270461.005634: Initializing MEMORY:cred_allowed_0x7f85d9152380 with
default princ host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM
[124798] 1687270461.005635: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)IPA.EXAMPLE.COM in MEMORY:cred_allowed_0x7f85d9152380
[124798] 1687270461.005636: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:cred_allowed_0x7f85d9152380
[124798] 1687270461.005637: Storing HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM ->
krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM(a)X-CACHECONF: in
MEMORY:cred_allowed_0x7f85d9152380
[124798] 1687270461.005638: Storing HTTP/ipa5.ipa.example.com(a)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(a)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(a)IPA.EXAMPLE.COM ->
HTTP/ipa5.ipa.example.com(a)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(a)IPA.EXAMPLE.COM -> ldap/ipa5.ipa.example.com@ using ccache
MEMORY:9LUdBez
[124798] 1687270461.005645: Retrieving host/myhost.ipa.example.com(a)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(a)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(a)IPA.EXAMPLE.COM ->
ldap/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM with result: -1765328243/Matching credential not
found
[124798] 1687270461.005648: Retrieving host/myhost.ipa.example.com(a)IPA.EXAMPLE.COM
-> HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM from MEMORY:9LUdBez with result:
0/Success
[124798] 1687270461.005649: Getting credentials
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM(a)IPA.EXAMPLE.COM
using ccache MEMORY:9LUdBez
[124798] 1687270461.005650: Retrieving host/myhost.ipa.example.com(a)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(a)IPA.EXAMPLE.COM ->
krbtgt/IPA.EXAMPLE.COM(a)IPA.EXAMPLE.COM from MEMORY:9LUdBez with result: 0/Success
[124798] 1687270461.005652: Get cred via TGT krbtgt/IPA.EXAMPLE.COM(a)IPA.EXAMPLE.COM
after requesting ldap/ipa5.ipa.example.com(a)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(a)IPA.EXAMPLE.COM for ldap/ipa5.ipa.example.com(a)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(a)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(a)IPA.EXAMPLE.COM,
HTTP/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM, HTTP/ipa6.ipa.example.com(a)IPA.EXAMPLE.COM
$ ipa servicedelegationtarget-show ipa-ldap-delegation-targets
Delegation name: ipa-ldap-delegation-targets
Member principals: ldap/ipa3.ipa.example.com(a)IPA.EXAMPLE.COM,
ldap/ipa5.ipa.example.com(a)IPA.EXAMPLE.COM, ldap/ipa6.ipa.example.com(a)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!
--
Sam Morris <https://robots.org.uk/>
PGP: rsa4096/CAAA AA1A CA69 A83A 892B 1855 D20B 4202 5CDA 27B9
3:02 a.m.
New subject: "Credential cache is empty" error preventing certmonger from renewing a host's certificate
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 <https://robots.org.uk/>
PGP: rsa4096/CAAA AA1A CA69 A83A 892B 1855 D20B 4202 5CDA 27B9
10:05 a.m.
New subject: "Credential cache is empty" error preventing certmonger from renewing a host's certificate
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
12:24 p.m.
New subject: "Credential cache is empty" error preventing certmonger from renewing a host's certificate
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 <https://robots.org.uk/>
PGP: rsa4096/CAAA AA1A CA69 A83A 892B 1855 D20B 4202 5CDA 27B9
1:21 p.m.
New subject: "Credential cache is empty" error preventing certmonger from renewing a host's certificate
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
9:23 a.m.
New subject: "Credential cache is empty" error preventing certmonger from renewing a host's certificate
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.fedoraho...;,
which was ultimately fixed in <https://pagure.io/freeipa/issue/9448>;.
--
Sam Morris <https://robots.org.uk/>
PGP: rsa4096/CAAA AA1A CA69 A83A 892B 1855 D20B 4202 5CDA 27B9
22
days inactive
318
days old
freeipa-users@lists.fedorahosted.org
5 comments
2 participants
participants (2)
-
Rob Crittenden -
Sam Morris