On Fri, Sep 01, 2023 at 01:59:00PM -0400, Rob Crittenden via FreeIPA-users
wrote:
> Sam Morris via FreeIPA-users wrote:
> > Hi folks, I've got a machine where certmonger is unable to renew a
> > certificate request:
> >
> > # 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 (Credential cache is empty)).
> > stuck: no
> > key pair storage:
> > type=FILE,location='/etc/cockpit/ws-certs.d/51-xoanon.key'
> > certificate:
> > type=FILE,location='/etc/cockpit/ws-certs.d/51-xoanon.crt'
> > CA: IPA
> > issuer: CN=Certificate Authority,O=IPA.EXAMPLE.COM
> > subject: CN=xoanon.ipa.example.com,O=IPA.EXAMPLE.COM
> > issued: 2023-06-21 07:49:49 UTC
> > expires: 2023-09-19 07:49:49 UTC
> > dns: xoanon.ipa.example.com
> > principal name: host/[email protected]
> > key usage:
> > digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
> > eku: id-kp-serverAuth,id-kp-clientAuth
> > pre-save command:
> > post-save command:
> > track: yes
> > auto-renew: yes
> >
> > I'm manually attempting to renew the certificate with:
> >
> > [root@xoanon ~]# getcert resubmit -w -v -i 20220519165212
> > Resubmitting "20220519165212" to "IPA".
> > State GENERATING_CSR, stuck: no.
> > State SUBMITTING, stuck: no.
> > State MONITORING, stuck: no.
> >
> > On the server side, I'm unable to find any errors being logged anywhere.
> > Even after I set 'debug = true' in /etc/ipa/default.conf & restarted
> > httpd.service, the only log messages are:
> >
> > ==> /var/log/httpd/error_log <==
> > [Wed Aug 23 10:59:50.765980 2023] [wsgi:error] [pid 124570:tid
> > 140295030843136] [remote 192.168.88.3:52224] ipa: DEBUG: WSGI
> > wsgi_dispatch.__call__:
> > [Wed Aug 23 10:59:50.766232 2023] [wsgi:error] [pid 124570:tid
> > 140295030843136] [remote 192.168.88.3:52224] ipa: DEBUG: WSGI
> > jsonserver.__call__:
> > [Wed Aug 23 10:59:50.766352 2023] [wsgi:error] [pid 124570:tid
> > 140295030843136] [remote 192.168.88.3:52224] ipa: DEBUG:
> > KerberosWSGIExecutioner.__call__:
> >
> > ==> /var/log/httpd/access_log <==
> > 192.168.88.3 - host/[email protected]
> > [23/Aug/2023:10:59:50 +0000] "POST /ipa/json HTTP/1.1" 200 526
> >
> > ... which show that the API call was successful. On the other hand,
> > according to 'ipa cert-find --subject=xoanon.ipa.example.com', no
> > certificates have been issued.
> >
> > It looks like the API isn't calling out to PKI/Dogtag, since nothing is
> > logged to /var/log/pki/pki-tomcat/localhost_access_log.*.txt or
> > /var/log/pki/pki-tomcat/ca/debug.*.log.
> >
> > I also looked for AVC denials and didn't see anything in /var/log/audit.
> >
> > So, back to the client. certmonger logs the following:
> >
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_REQ_SUBJECT" to
> > "CN=xoanon.ipa.example.com" for child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_REQ_HOSTNAME" to
> > "xoanon.ipa.example.com" for child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_REQ_PRINCIPAL" to
> > "host/[email protected]" for child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_OPERATION" to "SUBMIT"
> > for child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_CSR" to "-----BEGIN
> > CERTIFICATE REQUEST-----
> > MIIEpzCCAw8CAQAwIzEhMB8GA1UEAxMYeG9hbm9uLmlwYS5yb2JvdHMub3JnLnVr
> > [...]
> > 4d6BlUMScGAgCAxfxEb1eXymTxVm/Do/liHaOqnHGVIr+1OjZNftrUODFQ==
> > -----END CERTIFICATE REQUEST-----
> > " for child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_SPKAC" to "[...]" for
> > child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_SPKI" to "[...]" for
> > child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_LOCAL_CA_DIR" to
> > "/var/lib/certmonger/local" for child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_KEY_TYPE" to "RSA" for
> > child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_CA_NICKNAME" to "IPA"
> > for child.
> > 2023-08-23 11:15:50 [836073] Setting "CERTMONGER_CERTIFICATE" to
> > "-----BEGIN CERTIFICATE-----
> > MIIFajCCBFKgAwIBAgIET/8AJDANBgkqhkiG9w0BAQsFADA8MRowGAYDVQQKDBFJ
> > [...]
> > dF6L+2tIIpjYylCxKQISWaexKkv1jVQaIPB1foIKyLGaf9YtyaIwyoM9G80UaQ==
> > -----END CERTIFICATE-----
> > " for child.
> > 2023-08-23 11:15:50 [836073] Redirecting stdin to /dev/null, leaving
> > stdout and stderr open for child "/usr/libexec/certmonger/ipa-submit".
> > 2023-08-23 11:15:50 [836073] Running enrollment helper
> > "/usr/libexec/certmonger/ipa-submit".
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> > Submitting request to "https://ipa5.ipa.example.com/ipa/json";.
> > JSON-RPC error: 2100: Insufficient access: SASL(-1): generic failure:
> > GSSAPI Error: Unspecified GSS failure. Minor code may provide more
> > information (Credential cache is empty)
> > 2023-08-23 11:15:50 [834693] Certificate submission still ongoing.
> > 2023-08-23 11:15:50 [834693] Certificate submission attempt complete.
> > 2023-08-23 11:15:50 [834693] Child status = 2.
> > 2023-08-23 11:15:50 [834693] 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 empty)).
> > "
> > 2023-08-23 11:15:50 [834693] 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
> > empty)).
> > 2023-08-23 11:15:50 [834693] Certificate not (yet?) issued.
> > 2023-08-23 11:15:50 [834693] Wrote to
> > /var/lib/certmonger/requests/20220519165212
> >
> > I found that I could add 'OPTS=-d9' to /etc/sysconfig/certmonger &
> > restart certmonger.service, which does cause it to log more, but it
> > doesn't give any further insight into the messages exchanged with the
> > server.
> >
> > Does anyone know where I can look next?
>
> I'd look at the httpd error log again. It's returning a 2100 error which
> is an ACIError which means that the request has been received and
> processed. Particularly in debug mode you should have a dozen or more
> log entries.
Thanks rob. I think debug mode is correctly enabled because when I
restart httpd I see a lot of messages as the API server loads plugins,
etc. But when submitting the signing request the only log lines are:
==> /var/log/httpd/error_log <==
[Mon Sep 04 09:46:17.942879 2023] [wsgi:error] [pid 220090:tid
140379473487616] [remote 192.168.88.3:47188] ipa: DEBUG: WSGI
wsgi_dispatch.__call__:
[Mon Sep 04 09:46:17.943152 2023] [wsgi:error] [pid 220090:tid
140379473487616] [remote 192.168.88.3:47188] ipa: DEBUG: WSGI
jsonserver.__call__:
[Mon Sep 04 09:46:17.943276 2023] [wsgi:error] [pid 220090:tid
140379473487616] [remote 192.168.88.3:47188] ipa: DEBUG:
KerberosWSGIExecutioner.__call__:
I've made some slight progress. I noticed that at the same time, the KDC
logs these messages:
==> /var/log/krb5kdc.log <==
Sep 04 09:46:17 ipa5.ipa.example.com krb5kdc[183962](info): TGS_REQ :
handle_authdata (-1765328371)
Sep 04 09:46:17 ipa5.ipa.example.com krb5kdc[183962](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.88.5:
HANDLE_AUTHDATA: authtime 1693820777, etypes {rep=UNSUPPORTED:(0)}
HTTP/[email protected] for
ldap/[email protected], KDC can't fulfill requested option
Sep 04 09:46:17 ipa5.ipa.example.com krb5kdc[183962](info): ...
CONSTRAINED-DELEGATION s4u-client=host/[email protected]
Sep 04 09:46:17 ipa5.ipa.example.com krb5kdc[183962](info): closing down fd
12
I guess this is showing that HTTP/ipa5.ipa.example.com (the IPA API
server) is trying to obtain a ticket to LDAP/ipa5.ipa.example.com on
behalf of host/xoanon.ipa.example.com but the KDC is rejecting the
request.
If that's right then I guess I need to figure out why that might be.
Unfortunately setting 'debug = true' in /etc/krb5.conf's [logging]
section doesn't cause any more detailed messages to be logged.
If I run gssproxy with --debug-level=2 I can see it logging some stuff
but I guess it's just showing the calls that result in the kdc logging
the above...
-- Logs begin at Sun 2022-08-28 20:23:46 UTC. --
Sep 04 10:55:49 gssproxy[221575]: [2023/09/04 10:55:49]: Client [2023/09/04
10:55:49]: (/usr/sbin/httpd) [2023/09/04 10:55:49]: connected (fd =
15)[2023/09/04 10:55:49]: (pid = 220686) (uid = 48) (gid = 48)[2023/09/04
10:55:49]: (context = system_u:system_r:httpd_t:s0)[2023/09/04 10:55:49]:
Sep 04 10:55:49 gssproxy[221575]: [CID 15][2023/09/04 10:55:49]: Connection
matched service ipa-httpd
Sep 04 10:55:49 gssproxy[221575]: [CID 15][2023/09/04 10:55:49]:
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "ipa-httpd", euid:
48,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_ACQUIRE_CRED( call_ctx: { ""
[ ] } input_cred_handle: { "HTTP/[email protected]" [ {
"HTTP/[email protected]" { 1 2 840 113554 1 2 2 } BOTH 84028
84028 } ] [ .I...b1Z........... ] 0 } add_cred: 0 desired_name: <Null>
time_req: 4294967295 desired_mechs: { { 1 2 840 113554 1 2 2 } } cred_usage:
BOTH initiator_time_req: 0 acceptor_time_req: 0 )
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_ACQUIRE_CRED( status: { 0 {
1 2 840 113554 1 2 2 } 0 "" "" [ ] } output_cred_handle: {
"HTTP/[email protected]" [ {
"HTTP/[email protected]" { 1 2 840 113554 1 2 2 } BOTH 84028
84028 } ] [ .I...b1Z........... ] 0 } )
Sep 04 10:55:49 gssproxy[221575]: [CID 15][2023/09/04 10:55:49]: Connection
matched service ipa-httpd
Sep 04 10:55:49 gssproxy[221575]: [CID 15][2023/09/04 10:55:49]:
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "ipa-httpd", euid:
48,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_ACQUIRE_CRED( call_ctx: { ""
[ ] } input_cred_handle: { "HTTP/[email protected]" [ {
"HTTP/[email protected]" { 1 2 840 113554 1 2 2 } BOTH 84028
84028 } ] [ .I...b1Z........... ] 0 } add_cred: 0 desired_name: <Null>
time_req: 4294967295 desired_mechs: { { 1 2 840 113554 1 2 2 } } cred_usage:
BOTH initiator_time_req: 0 acceptor_time_req: 0 )
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_ACQUIRE_CRED( status: { 0 {
1 2 840 113554 1 2 2 } 0 "" "" [ ] } output_cred_handle: {
"HTTP/[email protected]" [ {
"HTTP/[email protected]" { 1 2 840 113554 1 2 2 } BOTH 84028
84028 } ] [ .I...b1Z........... ] 0 } )
Sep 04 10:55:49 gssproxy[221575]: [CID 15][2023/09/04 10:55:49]: Connection
matched service ipa-httpd
Sep 04 10:55:49 gssproxy[221575]: [CID 15][2023/09/04 10:55:49]:
gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CONTEXT) for service "ipa-httpd",
euid: 48,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_ACCEPT_SEC_CONTEXT(
call_ctx: { "" [ ] } context_handle: <Null> cred_handle: {
"HTTP/[email protected]" [ {
"HTTP/[email protected]" { 1 2 840 113554 1 2 2 } BOTH 84028
84028 } ] [ .I...b1Z........... ] 0 } input_token: [ ........H.......... ]
input_cb: <Null> ret_deleg_cred: 1 )
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_ACCEPT_SEC_CONTEXT( status:
{ 0 { 1 2 840 113554 1 2 2 } 0 "" "" [ ] } context_handle: { [
......H............ ] [ ] 0 { 1 2 840 113554 1 2 2 }
"host/[email protected]"
"HTTP/[email protected]" 84387 439 0 1 } output_token: [
.......H........... ] delegated_cred_handle: {
"host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } )
Sep 04 10:55:49 gssproxy[221575]: [2023/09/04 10:55:49]: Client [2023/09/04
10:55:49]: (/usr/sbin/httpd) [2023/09/04 10:55:49]: connected (fd =
16)[2023/09/04 10:55:49]: (pid = 220685) (uid = 988) (gid = 983)[2023/09/04
10:55:49]: (context = system_u:system_r:httpd_t:s0)[2023/09/04 10:55:49]:
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]: Connection
matched service ipa-api
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]:
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "ipa-api", euid:
988,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_ACQUIRE_CRED( call_ctx: { ""
[ ] } input_cred_handle: { "host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } add_cred: 0 desired_name: <Null>
time_req: 4294967295 desired_mechs: { { 1 2 840 113554 1 2 2 } } cred_usage:
INITIATE initiator_time_req: 0 acceptor_time_req: 0 )
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_ACQUIRE_CRED( status: { 0 {
1 2 840 113554 1 2 2 } 0 "" "" [ ] } output_cred_handle: {
"host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } )
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]: Connection
matched service ipa-api
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]:
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "ipa-api", euid:
988,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_ACQUIRE_CRED( call_ctx: { ""
[ ] } input_cred_handle: { "host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } add_cred: 0 desired_name: <Null>
time_req: 4294967295 desired_mechs: { { 1 2 840 113554 1 2 2 } } cred_usage:
INITIATE initiator_time_req: 0 acceptor_time_req: 0 )
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_ACQUIRE_CRED( status: { 0 {
1 2 840 113554 1 2 2 } 0 "" "" [ ] } output_cred_handle: {
"host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } )
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]: Connection
matched service ipa-api
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]:
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "ipa-api", euid:
988,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_ACQUIRE_CRED( call_ctx: { ""
[ ] } input_cred_handle: { "host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } add_cred: 0 desired_name: <Null>
time_req: 4294967295 desired_mechs: { { 1 2 840 113554 1 2 2 } } cred_usage:
INITIATE initiator_time_req: 0 acceptor_time_req: 0 )
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_ACQUIRE_CRED( status: { 0 {
1 2 840 113554 1 2 2 } 0 "" "" [ ] } output_cred_handle: {
"host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } )
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]: Connection
matched service ipa-api
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]:
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "ipa-api", euid:
988,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_ACQUIRE_CRED( call_ctx: { ""
[ ] } input_cred_handle: { "host/[email protected]" [ {
"host/[email protected]" { 0 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } add_cred: 0 desired_name: <Null>
time_req: 0 desired_mechs: { } cred_usage: INITIATE initiator_time_req: 0
acceptor_time_req: 0 )
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_ACQUIRE_CRED( status: { 0 {
1 2 840 113554 1 2 2 } 0 "" "" [ ] } output_cred_handle: {
"host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } )
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]: Connection
matched service ipa-api
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]:
gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "ipa-api",
euid: 988,socket: (null)
Sep 04 10:55:49 gssproxy[221575]: GSSX_ARG_INIT_SEC_CONTEXT( call_ctx:
{ "" [ ] } context_handle: <Null> cred_handle: {
"host/[email protected]" [ {
"host/[email protected]" { 1 2 840 113554 1 2 2 } INITIATE
84087 0 } ] [ ................... ] 0 } target_name:
"[email protected]" mech_type: { 1 2 840 113554 1 2 2 } req_flags: 58
time_req: 0 input_cb: <Null> input_token: <Null> [ { [ sync.modified.cr... ] [
64656661756c740 ] } ] )
Sep 04 10:55:49 gssproxy[221575]: [CID 16][2023/09/04 10:55:49]:
Credentials allowed by configuration
Sep 04 10:55:49 gssproxy[221575]: GSSX_RES_INIT_SEC_CONTEXT( status: {
851968 { 1 2 840 113554 1 2 2 } 2529638925 "Unspecified GSS failure. Minor
code may provide more information" "KDC can't fulfill requested option" [ ] }
context_handle: <Null> output_token: <Null> )
The delegation rule looks normal to me:
$ ipa servicedelegationrule-show ipa-http-delegation
Delegation name: ipa-http-delegation
Allowed Target: ipa-ldap-delegation-targets, ipa-cifs-delegation-targets
Member principals: HTTP/[email protected],
HTTP/[email protected],
HTTP/[email protected]
$ ipa servicedelegationtarget-show ipa-ldap-delegation-targets
Delegation name: ipa-ldap-delegation-targets
Member principals: ldap/[email protected],
ldap/[email protected],
ldap/[email protected]
Looking through the krb5 source code, "KDC can't fulfill requested
option" corresponds to the error code KRB5KDC_ERR_BADOPTION, which can
be returned by krb5_ldap_check_allowed_to_delegate. But it could also be
returned in a couple of other places, and I haven't figured out where
it's coming from yet.
--
Sam Morris <https://robots.org.uk/>
PGP: rsa4096/CAAA AA1A CA69 A83A 892B 1855 D20B 4202 5CDA 27B9
_______________________________________________
FreeIPA-users mailing list -- [email protected]
To unsubscribe send an email to [email protected]
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/[email protected]
Do not reply to spam, report it:
https://pagure.io/fedora-infrastructure/new_issue
