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/xoanon.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
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/xoanon.ipa.example.com@IPA.EXAMPLE.COM [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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" 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/ipa5.ipa.example.com@IPA.EXAMPLE.COM for ldap/ipa5.ipa.example.com@IPA.EXAMPLE.COM, KDC can't fulfill requested option Sep 04 09:46:17 ipa5.ipa.example.com krb5kdc[183962](info): ... CONSTRAINED-DELEGATION s4u-client=host/xoanon.ipa.example.com@IPA.EXAMPLE.COM 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/ipa5.ipa.example.com@IPA.EXAMPLE.COM" [ { "HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM" { 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/ipa5.ipa.example.com@IPA.EXAMPLE.COM" [ { "HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM" { 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/ipa5.ipa.example.com@IPA.EXAMPLE.COM" [ { "HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM" { 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/ipa5.ipa.example.com@IPA.EXAMPLE.COM" [ { "HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM" { 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/ipa5.ipa.example.com@IPA.EXAMPLE.COM" [ { "HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" "HTTP/ipa5.ipa.example.com@IPA.EXAMPLE.COM" 84387 439 0 1 } output_token: [ .......H........... ] delegated_cred_handle: { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 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/xoanon.ipa.example.com@IPA.EXAMPLE.COM" [ { "host/xoanon.ipa.example.com@IPA.EXAMPLE.COM" { 1 2 840 113554 1 2 2 } INITIATE 84087 0 } ] [ ................... ] 0 } target_name: "ldap@ipa5.ipa.example.com" 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/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
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.