When Samba 4.23 release candidate builds landed in Fedora rawhide, we started seeing FreeIPA tests that attempt to establish trust with Active Directory to fail. In particular, the following error is visible in the logs where FreeIPA uses Samba Python bindings to perform client-side DCE RPC calls: ``` Using binding ncacn_np:master.ipa.test[,print,smb2] s4_tevent: Added timed event "dcerpc_connect_timeout_handler": 0x7f6e8802ddd0 s4_tevent: Added timed event "composite_trigger": 0x7f6e8802e340 s4_tevent: Added timed event "composite_trigger": 0x7f6e8802e510 s4_tevent: Running timer event 0x7f6e8802e340 "composite_trigger" s4_tevent: Destroying timer event 0x7f6e8802e510 "composite_trigger" s4_tevent: Destroying timer event 0x7f6e8802e340 "composite_trigger" Mapped to DCERPC endpoint \pipe\lsarpc added interface ens4 ip=192.168.121.195 bcast=192.168.121.255 netmask=255.255.255.0 added interface ens4 ip=192.168.121.195 bcast=192.168.121.255 netmask=255.255.255.0 resolve_lmhosts: Attempting lmhosts lookup for name master.ipa.test<0x20> getlmhostsent: lmhost entry: 127.0.0.1 localhost s4_tevent: Added timed event "composite_trigger": 0x7f6e8802e510 s4_tevent: Running timer event 0x7f6e8802e510 "composite_trigger" s4_tevent: Destroying timer event 0x7f6e8802e510 "composite_trigger" s4_tevent: Added timed event "tevent_req_timedout": 0x7f6e88030ba0 Connecting to 192.168.121.195 at port 445 s4_tevent: Added timed event "tevent_req_timedout": 0x7f6e880327b0 s4_tevent: Destroying timer event 0x7f6e88030ba0 "tevent_req_timedout" socket options: SO_KEEPALIVE=0, SO_REUSEADDR=0, SO_BROADCAST=0, TCP_NODELAY=0, TCP_KEEPCNT=9, TCP_KEEPIDLE=7200, TCP_KEEPINTVL=75, IPTOS_LOWDELAY=0, IPTOS_THROUGHPUT=0, SO_REUSEPORT=0, SO_SNDBUF=2626560, SO_RCVBUF=131072, SO_SNDLOWAT=1, SO_RCVLOWAT=1, SO_SNDTIMEO=0, SO_RCVTIMEO=0, TCP_QUICKACK=1, TCP_DEFER_ACCEPT=0, TCP_USER_TIMEOUT=0 s4_tevent: Destroying timer event 0x7f6e880327b0 "tevent_req_timedout" s4_tevent: Added timed event "tevent_req_timedout": 0x7f6e8802e510 s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f6e88032f70 s4_tevent: Cancel immediate event 0x7f6e88032f70 "tevent_req_trigger" s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f6e88032f70 s4_tevent: Run immediate event "tevent_req_trigger": 0x7f6e88032f70 s4_tevent: Destroying timer event 0x7f6e8802e510 "tevent_req_timedout" s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f6e88031910 s4_tevent: Run immediate event "tevent_req_trigger": 0x7f6e88031910 s4_tevent: Added timed event "tevent_req_timedout": 0x7f6e8802f5b0 Starting GENSEC mechanism spnego Starting GENSEC submechanism gssapi_krb5 Failed to get kerberos credentials (kerberos required): The credential cache is invalid Cannot obtain client GSS credentials we need to contact (null) : The credential cache is invalid s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f6e88031ec0 gensec_update_send: gssapi_krb5[0x7f6e88034150]: subreq: 0x7f6e88031db0 gensec_update_send: spnego[0x7f6e88010b40]: subreq: 0x7f6e880338b0 s4_tevent: Run immediate event "tevent_req_trigger": 0x7f6e88031ec0 gensec_update_done: gssapi_krb5[0x7f6e88034150]: NT_STATUS_INVALID_PARAMETER tevent_req[0x7f6e88031db0/../../source4/auth/gensec/gensec_gssapi.c:1120]: state[3] error[-7963671676338569203 (0x917B5ACDC000000D)] state[struct gensec_gssapi_update_state (0x7f6e88031f90)] timer[(nil)] finish[../../source4/auth/gensec/gensec_gssapi.c:1134] gensec_spnego_client_negTokenInit_step: gssapi_krb5: creating NEG_TOKEN_INIT for cifs/master.ipa.test failed (next[(null)]): NT_STATUS_INVALID_PARAMETER gensec_update_done: spnego[0x7f6e88010b40]: NT_STATUS_INVALID_PARAMETER tevent_req[0x7f6e880338b0/../../auth/gensec/spnego.c:1614]: state[3] error[-7963671676338569203 (0x917B5ACDC000000D)] state[struct gensec_spnego_update_state (0x7f6e88033a90)] timer[(nil)] finish[../../auth/gensec/spnego.c:2032] s4_tevent: Destroying timer event 0x7f6e8802f5b0 "tevent_req_timedout" s4_tevent: Destroying timer event 0x7f6e8802ddd0 "dcerpc_connect_timeout_handler" [Mon Sep 01 15:22:29.630351 2025] [wsgi:error] [pid 32924:tid 33396] [remote 192.168.121.195:34770] ipa: INFO: [jsonserver_kerb] admin@IPA.TEST: trust_add/1('ad.test', trust_type='ad', realm_admin='Administrator@ad.test', realm_passwd='********', version='2.254'): RemoteRetrieveError [Mon Sep 01 15:22:33.029004 2025] [:warn] [pid 32928:tid 33046] [client 192.168.121.195:48636] failed to set perms (3140) on file (/run/ipa/ccaches/admin@IPA.TEST-hRDU7V)!, referer: https://master.ipa.test/ipa/xml ``` FreeIPA uses extensively GSSProxy to handle Kerberos credentials and relies on Samba doing only GSSAPI calls because GSSProxy interopser only supported over GSSAPI. Samba code in 4.23rc1+ does direct checks on the content of a credential cache available and interprets it as 'invalid' or missing. GSSProxy stores an encrypted credential as a special service principal with timestamp 0 (beginning of UNIX time): ``` # klist -c /run/ipa/ccaches/admin@MINIMAL.TEST-3CmDCQ Ticket cache: FILE:/run/ipa/ccaches/admin@MINIMAL.TEST-3CmDCQ Default principal: admin@MINIMAL.TEST Valid starting Expires Service principal 01/01/1970 00:00:00 01/01/1970 00:00:00 Encrypted/Credentials/v1@X-GSSPROXY: ``` The credential gets decrypted by the GSSProxy in its process and direct access to it through the raw Kerberos API is not possible. In 4.23rc1+ we have the following commit which added an interpretation of the expiration time of this credential to treat the ccache as invalid: ``` commit 6085b737ba702582765840e21cc88d6007dacecf Author: Andreas Schneider <asn@samba.org> Date: Fri Apr 11 13:49:22 2025 +0200 auth:creds: Do a kinit if we have a password and the ccache is empty This implements the same behaviour for s4 clients as we have with s3 clients. ``` The code needs to be extended to identify that we are dealing with GSSProxy-encrypted credentials and don't assume their expiration time.
in smb_krb5_cc_get_lifetime() we already do skip config entries via krb5_is_config_principal(), we could detect GSSProxy entry the same way. However, it would leave us with a ccache that would have no other entries and we would treat it as empty in cli_credentials_get_named_ccache(). I guess we need to expand the logic to understand we are dealing with a GSSProxy-enabled credential and simply assume we don't need to do a kinit (kinit_required=false).
Heimdal (which provides krb5_cc_get_lifetime()) has no support for GSSAPI interposer API and thus has no support for GSSProxy. MIT Kerberos has no support for krb5_cc_get_lifetime(), so it gets replaced by smb_krb5_cc_get_lifetime() implementation which we can affect. Ideally, we need to know whether the lifetime was from a valid credential or from an encrypted one where we do not know the real state. We can theoretically indicate that via a return code by choosing a return code that is different from KRB5_CC_END (no creds in a ccache but ccache exists) or 0 (there is at least one credential in the ccache, lifetime was returned).
I think we can return KRB5_PLUGIN_NO_HANDLE from smb_krb5_cc_get_lifetime() if we detect it is GSSProxy-handled ccache. This will need to be handled in two places we are using smb_krb5_cc_get_lifetime(), both in auth/credentials/credentials_krb5.c.
Merge request: https://gitlab.com/samba-team/samba/-/merge_requests/4197
We ran the same FreeIPA test against a Samba build with the proposed fixes and it succeeded. Relevant logs are in http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/a74e107e-87f2-11f0-be6c-fa163e929191/test_integration-test_ipahealthcheck.py-TestIpaHealthCheckWithADtrust-install/master.ipa.test/var/log/httpd/error_log.gz ... Using binding ncacn_np:master.ipa.test[,print,smb2] s4_tevent: Added timed event "dcerpc_connect_timeout_handler": 0x7f944002ddd0 s4_tevent: Added timed event "composite_trigger": 0x7f944002e340 s4_tevent: Added timed event "composite_trigger": 0x7f944002e510 s4_tevent: Running timer event 0x7f944002e340 "composite_trigger" s4_tevent: Destroying timer event 0x7f944002e510 "composite_trigger" s4_tevent: Destroying timer event 0x7f944002e340 "composite_trigger" Mapped to DCERPC endpoint \pipe\lsarpc added interface ens4 ip=192.168.121.149 bcast=192.168.121.255 netmask=255.255.255.0 added interface ens4 ip=192.168.121.149 bcast=192.168.121.255 netmask=255.255.255.0 resolve_lmhosts: Attempting lmhosts lookup for name master.ipa.test<0x20> getlmhostsent: lmhost entry: 127.0.0.1 localhost s4_tevent: Added timed event "composite_trigger": 0x7f944002e510 s4_tevent: Running timer event 0x7f944002e510 "composite_trigger" s4_tevent: Destroying timer event 0x7f944002e510 "composite_trigger" s4_tevent: Added timed event "tevent_req_timedout": 0x7f9440030ba0 Connecting to 192.168.121.149 at port 445 s4_tevent: Added timed event "tevent_req_timedout": 0x7f94400327b0 s4_tevent: Destroying timer event 0x7f9440030ba0 "tevent_req_timedout" socket options: SO_KEEPALIVE=0, SO_REUSEADDR=0, SO_BROADCAST=0, TCP_NODELAY=0, TCP_KEEPCNT=9, TCP_KEEPIDLE=7200, TCP_KEEPINTVL=75, IPTOS_LOWDELAY=0, IPTOS_THROUGHPUT=0, SO_REUSEPORT=0, SO_SNDBUF=2626560, SO_RCVBUF=131072, SO_SNDLOWAT=1, SO_RCVLOWAT=1, SO_SNDTIMEO=0, SO_RCVTIMEO=0, TCP_QUICKACK=1, TCP_DEFER_ACCEPT=0, TCP_USER_TIMEOUT=0 s4_tevent: Destroying timer event 0x7f94400327b0 "tevent_req_timedout" s4_tevent: Added timed event "tevent_req_timedout": 0x7f944002e510 s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f9440032f70 s4_tevent: Cancel immediate event 0x7f9440032f70 "tevent_req_trigger" s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f9440032f70 s4_tevent: Run immediate event "tevent_req_trigger": 0x7f9440032f70 s4_tevent: Destroying timer event 0x7f944002e510 "tevent_req_timedout" s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f9440031910 s4_tevent: Run immediate event "tevent_req_trigger": 0x7f9440031910 s4_tevent: Added timed event "tevent_req_timedout": 0x7f944002f5b0 Starting GENSEC mechanism spnego Starting GENSEC submechanism gssapi_krb5 s4_tevent: Schedule immediate event "tevent_req_trigger": 0x7f9440031ec0 gensec_update_send: gssapi_krb5[0x7f9440034150]: subreq: 0x7f9440031db0 gensec_update_send: spnego[0x7f9440010b40]: subreq: 0x7f94400338b0 s4_tevent: Run immediate event "tevent_req_trigger": 0x7f9440031ec0 gensec_update_done: gssapi_krb5[0x7f9440034150]: NT_STATUS_MORE_PROCESSING_REQUIRED tevent_req[0x7f9440031db0/../../source4/auth/gensec/gensec_gssapi.c:1120]: state[2] error[0 (0x0)] state[struct gensec_gssapi_update_state (0x7f9440031f90)] timer[(nil)] finish[../../source4/auth/gensec/gensec_gssapi.c:1131] gensec_update_done: spnego[0x7f9440010b40]: NT_STATUS_MORE_PROCESSING_REQUIRED tevent_req[0x7f94400338b0/../../auth/gensec/spnego.c:1614]: state[2] error[0 (0x0)] state[struct gensec_spnego_update_state (0x7f9440033a90)] timer[(nil)] finish[../../auth/gensec/spnego.c:2109] s4_tevent: Added timed event "tevent_req_timedout": 0x7f944002e340 ....
The overally test run report is http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/a74e107e-87f2-11f0-be6c-fa163e929191/report.html?sort=result, if you'd remove 'report.html' part, then you'll see all logged data.
This bug was referenced in samba master: c00b98ad840706cda222bb610d0d4860b98c72d4
Created attachment 18701 [details] backport to v.4.23 Backport to v4.23
Jule please backport to 4.23
Pushed to autobuild-v4-23-test.
This bug was referenced in samba v4-23-test: e4581ccfe7b11c5f884d3757b393bf1e26a49d4b
Closing out bug report. Thanks!
This bug was referenced in samba v4-23-stable (Release samba-4.23.0rc4): e4581ccfe7b11c5f884d3757b393bf1e26a49d4b