Test failure: ssh with OTP login in IPA environment

[flo-renaud]

FreeIPA detected a regression using the @sssd/nightly copr repository in its tests performing ssh with an OTP token.

Reproducer:

1. Enable the copr repositories for freeipa and sssd, install IPA on a Fedora 43 machine

dnf copr enable -y @freeipa/freeipa-master-nightly
dnf copr enable -y @sssd/nightly
dnf update -y && dnf install -y freeipa-server-dns

2. Install IPA server

 ipa-server-install --domain ipa.test --realm IPA.TEST --setup-dns --forwarder 10.11.5.160 -a Secret123 -p Secret123 -U

3. Create a user

echo Secret123 | kinit admin
echo Secret123 | ipa user-add sshuser1 --first otp --last user --password

4. Set the password for the user

kdestroy -A; kinit sshuser1

5. Configure OTP for the user

echo Secret123 | kinit admin
ipa user-mod sshuser1 --user-auth-type otp
ipa otptoken-add --owner sshuser1

6. From another machine, try to ssh to the IPA server with the otp user:

ssh sshuser1@server.ipa.test
(sshuser1@server.ipa.test) Password: 
Received disconnect from 10.0.184.7 port 22:2: Too many authentication failures
Disconnected from 10.0.184.7 port 22

The same scenario works with sssd-client-2.11.1-4.fc43.x86_64 but fails with the version shipped in the copr repo sssd-client-2.12.0-0.251205.163524.gitbe5df3412.fc43.x86_64.
Note that the test was green last week with sssd-client-2.12.0-0.251127.142214.git637b7bcb7.fc43.x86_64.

Logs are available in our internal artifacts server:
https://$ARTIFACTS_SERVER/idm-ci/freeipa_upstream_nightly/Nightly-latest-sssd/master/2025-12-06_15-55/sssd/test_otp/1/report.html?sort=result

Extract from krb5_child.log:

(2025-12-06 16:14:05): [krb5_child[35964]] [tgt_req_child] (0x1000): [RID#6] Attempting to get a TGT
(2025-12-06 16:14:05): [krb5_child[35964]] [get_and_save_tgt] (0x0400): [RID#6] Attempting kinit for realm [UFREEIPA.TEST]
(2025-12-06 16:14:05): [krb5_child[35964]] [k5c_send_data] (0x0200): [RID#6] Received error code 0
(2025-12-06 16:14:05): [krb5_child[35966]] [sss_log_process_caps] (0x0100): [RID#8] Starting under ruid=994, euid=994, suid=994 : rgid=994, egid=994, sgid=994
(2025-12-06 16:14:05): [krb5_child[35966]] [sss_log_process_caps] (0x0100): [RID#8] With following capabilities:
         CAP_DAC_READ_SEARCH: effective =  0 , permitted = *1*, inheritable =  0 , bounding = *1*
                  CAP_SETGID: effective =  0 , permitted = *1*, inheritable =  0 , bounding = *1*
                  CAP_SETUID: effective =  0 , permitted = *1*, inheritable =  0 , bounding = *1*
(2025-12-06 16:14:05): [krb5_child[35966]] [unpack_buffer] (0x1000): [RID#8] total buffer size: [98]
(2025-12-06 16:14:05): [krb5_child[35966]] [unpack_buffer] (0x0100): [RID#8] cmd [249 (pre-auth)] uid [1210600004] gid [1210600004] validate [true] enterprise principal [false] offline [false] UPN [sshuser1@UFREEIPA.TEST]
(2025-12-06 16:14:05): [krb5_child[35966]] [unpack_buffer] (0x0100): [RID#8] ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(2025-12-06 16:14:05): [krb5_child[35966]] [k5c_setup_fast] (0x0100): [RID#8] Fast principal is set to [host/master.ufreeipa.test@UFREEIPA.TEST]
(2025-12-06 16:14:05): [krb5_child[35966]] [match_principal] (0x1000): [RID#8] Principal matched to the sample (host/master.ufreeipa.test@UFREEIPA.TEST).
(2025-12-06 16:14:05): [krb5_child[35966]] [check_fast_ccache] (0x0200): [RID#8] FAST TGT is still valid.
(2025-12-06 16:14:05): [krb5_child[35966]] [sss_log_process_caps] (0x0100): [RID#8] Running under ruid=1210600004, euid=1210600004, suid=994 : rgid=1210600004, egid=1210600004, sgid=994
(2025-12-06 16:14:05): [krb5_child[35966]] [sss_log_process_caps] (0x0100): [RID#8] With following capabilities:
   (nothing)
(2025-12-06 16:14:05): [krb5_child[35966]] [set_lifetime_options] (0x0100): [RID#8] No specific renewable lifetime requested.
(2025-12-06 16:14:05): [krb5_child[35966]] [set_lifetime_options] (0x0100): [RID#8] No specific lifetime requested.
(2025-12-06 16:14:05): [krb5_child[35966]] [set_canonicalize_option] (0x0100): [RID#8] Canonicalization is set to [true]
(2025-12-06 16:14:05): [krb5_child[35966]] [main] (0x0400): [RID#8] Will perform pre-auth
(2025-12-06 16:14:05): [krb5_child[35966]] [tgt_req_child] (0x1000): [RID#8] Attempting to get a TGT
(2025-12-06 16:14:05): [krb5_child[35966]] [get_and_save_tgt] (0x0400): [RID#8] Attempting kinit for realm [UFREEIPA.TEST]
(2025-12-06 16:14:05): [krb5_child[35966]] [k5c_send_data] (0x0200): [RID#8] Received error code 0
(2025-12-06 16:14:06): [krb5_child[35964]] [unpack_buffer] (0x1000): [RID#6] total buffer size: [121]
(2025-12-06 16:14:06): [krb5_child[35964]] [unpack_buffer] (0x0100): [RID#6] cmd [241 (auth)] uid [1210600004] gid [1210600004] validate [true] enterprise principal [false] offline [false] UPN [sshuser1@UFREEIPA.TEST]
(2025-12-06 16:14:06): [krb5_child[35964]] [unpack_buffer] (0x0100): [RID#6] ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
(2025-12-06 16:14:06): [krb5_child[35964]] [answer_otp] (0x0080): [RID#6] Unexpected authentication token type [Password]
(2025-12-06 16:14:06): [krb5_child[35964]] [get_and_save_tgt] (0x0020): [RID#6] 2463: [1432158313][Unknown code UUz 105]
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [sss_log_process_caps] (0x0100): [RID#6] Starting under ruid=994, euid=994, suid=994 : rgid=994, egid=994, sgid=994
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [sss_log_process_caps] (0x0100): [RID#6] With following capabilities:
         CAP_DAC_READ_SEARCH: effective =  0 , permitted = *1*, inheritable =  0 , bounding = *1*
                  CAP_SETGID: effective =  0 , permitted = *1*, inheritable =  0 , bounding = *1*
                  CAP_SETUID: effective =  0 , permitted = *1*, inheritable =  0 , bounding = *1*
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [unpack_buffer] (0x1000): [RID#6] total buffer size: [98]
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [unpack_buffer] (0x0100): [RID#6] cmd [249 (pre-auth)] uid [1210600004] gid [1210600004] validate [true] enterprise principal [false] offline [false] UPN [sshuser1@UFREEIPA.TEST]
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [unpack_buffer] (0x0100): [RID#6] ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [k5c_setup_fast] (0x0100): [RID#6] Fast principal is set to [host/master.ufreeipa.test@UFREEIPA.TEST]
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [find_principal_in_keytab] (0x4000): [RID#6] Trying to find principal host/master.ufreeipa.test@UFREEIPA.TEST in keytab.
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [match_principal] (0x1000): [RID#6] Principal matched to the sample (host/master.ufreeipa.test@UFREEIPA.TEST).
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [get_tgt_times] (0x1000): [RID#6] FAST ccache must be recreated
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [check_fast_ccache] (0x0200): [RID#6] FAST TGT was successfully recreated!
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [sss_log_process_caps] (0x0100): [RID#6] Running under ruid=1210600004, euid=1210600004, suid=994 : rgid=1210600004, egid=1210600004, sgid=994
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [sss_log_process_caps] (0x0100): [RID#6] With following capabilities:
   (nothing)
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [set_lifetime_options] (0x0100): [RID#6] No specific renewable lifetime requested.
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [set_lifetime_options] (0x0100): [RID#6] No specific lifetime requested.
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [set_canonicalize_option] (0x0100): [RID#6] Canonicalization is set to [true]
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [main] (0x0400): [RID#6] Will perform pre-auth
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [tgt_req_child] (0x1000): [RID#6] Attempting to get a TGT
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [get_and_save_tgt] (0x0400): [RID#6] Attempting kinit for realm [UFREEIPA.TEST]
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [sss_krb5_auth_methods_request] (0x4000): [RID#6] Got request [otp].
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [request_otp] (0x4000): [RID#6] [0] Vendor [(null)].
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [request_otp] (0x4000): [RID#6] [0] Token-ID [(null)].
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [request_otp] (0x4000): [RID#6] [0] Challenge [(null)].
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [request_otp] (0x4000): [RID#6] [0] Flags [1].
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [request_otp] (0x4000): [RID#6] Setting otp prompting.
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [sss_krb5_auth_methods_request] (0x4000): [RID#6] Request found for otp
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [k5c_send_data] (0x0200): [RID#6] Received error code 0
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [pack_response_packet] (0x2000): [RID#6] response packet size: [16]
   *  (2025-12-06 16:14:05): [krb5_child[35964]] [k5c_send_data] (0x4000): [RID#6] Response sent.
   *  (2025-12-06 16:14:06): [krb5_child[35964]] [unpack_buffer] (0x1000): [RID#6] total buffer size: [121]
   *  (2025-12-06 16:14:06): [krb5_child[35964]] [unpack_buffer] (0x0100): [RID#6] cmd [241 (auth)] uid [1210600004] gid [1210600004] validate [true] enterprise principal [false] offline [false] UPN [sshuser1@UFREEIPA.TEST]
   *  (2025-12-06 16:14:06): [krb5_child[35964]] [unpack_buffer] (0x0100): [RID#6] ccname: [KCM:] old_ccname: [not set] keytab: [/etc/krb5.keytab]
   *  (2025-12-06 16:14:06): [krb5_child[35964]] [sss_krb5_auth_methods_answer] (0x4000): [RID#6] Got question [otp].
   *  (2025-12-06 16:14:06): [krb5_child[35964]] [answer_otp] (0x0080): [RID#6] Unexpected authentication token type [Password]
   *  (2025-12-06 16:14:06): [krb5_child[35964]] [sss_krb5_auth_methods_answer] (0x4000): [RID#6] Auth type [otp] could not be handled by answer function, continuing to next question.
   *  (2025-12-06 16:14:06): [krb5_child[35964]] [get_and_save_tgt] (0x0020): [RID#6] 2463: [1432158313][Unknown code UUz 105]
********************** BACKTRACE DUMP ENDS HERE *********************************

The test source is available here

[flo-renaud]

The following commits happened between the 2 sssd versions:

be5df3412 (authtok: Set Kerberos passkey PIN to NULL when UV is false, 2025-11-10)
879d07315 (passkey: Remove SYSDB_PASSKEY_USER_VERIFICATION, 2025-11-05)
304f298c9 (pam: Skip passkey_local() in Kerberos auth flow, 2025-11-05)
e9216fc1e (pam: Remove PAM_PASSKEY_VERIFICATION_OMIT mode, 2025-11-05)
50527dc96 (ipa: improve unknown trust type error return, 2025-12-02)
f2e8e51a4 (ipa: Fix typo in trust type conditional, 2025-12-02)
407104127 (IPA: remove 'ipa_enable_dns_sites' option, 2025-12-03)
a0574f78d (Tests: Rectify the docstring n testcode, 2025-12-02)
502391658 (intg: remove test_session_recording.py, 2025-11-26)
cc1b9e029 (krb5: port pre-authentication retry logic, 2025-11-20)
811ecc1f9 (man: clarify and fix `pam_json_services` compilation, 2025-11-18)
aa2ac83f9 (Responder: change authentication mechanism detection, 2025-11-13)
784982265 (sss_client: prevent JSON auth during password change preauth, 2025-11-12)
6b40318a8 (Responder: add `gdm-switchable-auth` to `pam_p11_allowed_services` defaults, 2025-11-07)
bc1460c3d (Responder: fix passkey auth when user-verification is off, 2025-10-28)
4cb99a248 (krb5_child: advertise authentication methods, 2025-03-27)
3cbf1aaa8 (Responder: parse reply for passkey, 2024-09-17)
efaa9c1de (util: implement function to set passkey PIN, 2024-09-17)
7e9e18e9f (Responder: generate JSON message for passkey, 2024-09-10)
be9164f28 (Responder: make `decode_pam_passkey_msg()` public, 2025-02-12)
78ec10f28 (Responder: extend smartcard JSON reply message, 2025-01-29)
18dd52646 (Responder: extend smartcard JSON request message, 2025-01-29)
6011466b0 (Responder: refactor JSON functions to reduce args, 2024-09-06)
0640200f0 (Responder: parse reply for smartcard, 2024-04-10)
b4699ddbe (Responder: generate JSON message for smartcard, 2024-04-09)
5f2fc24c1 (util: implement pam_get_response_data_all_same_type(), 2024-06-12)
6c38800b6 (sss_client: modify smartcard in prompt_config structure, 2024-06-04)
7c70f1dc1 (Responder: update JSON message format, 2025-09-22)
8d24366e5 (Responder: check return value for json_string(), 2024-06-13)
e327f0d74 (Test: adapt test_pam_srv to JSON message, 2024-03-05)
48381a3f0 (Responder: parse GUI reply, 2024-01-30)
123252183 (SSS_CLIENT: forward available auth JSON message, 2024-01-22)
c5af066c0 (Responder: call JSON message generation, 2024-01-22)
b3dc37aaf (Responder: new option `pam_json_services`, 2024-02-20)
2fda8e081 (Responder: check PAM service file for JSON protocol, 2024-03-06)
b04803459 (Responder: unpack JSON reply from GUI, 2024-01-30)
316579af7 (Responder: generate JSON message for GUI, 2024-01-19)
af9459e10 (Responder: tune prompts in the GUI, 2024-05-08)
bc4bfcd9e (sss_client: add EIdP to prompt_config structure, 2024-05-08)
fb4d5ad23 (util: implement pam_get_response_data(), 2024-01-18)
00547f67a (tests: filter_groups by name and lookup by id with expired cache, 2025-11-14)
816eb1e20 (cache_req: allow cache_first mode only if there is more than one domain, 2025-11-14)
d6ea55552 (sbus: defer notification callbacks, 2025-11-14)
9a776480a (check_file-tests: Ensure correct group ownership on the created file, 2025-11-22)
47b38f178 (sss_unique_file: Ensure correct group ownership on the created file, 2025-11-22)
2a1048b59 (CONFIG: disable 'session_provider' by default, 2025-11-28)
ec3e97470 (PAM/P11: debug message fixed, 2025-11-26)
2ad8cbf97 (PROXY: use `sss_child_handle_timeout()`, 2025-11-26)
ed230fc93 (PROXY: delete unused define, 2025-11-26)
10f9eb290 (PROXY: provide 'dumpable' and 'backtrace' args to child process, 2025-11-26)
55c63c3d3 (DYNDNS: use sss_child_handle_timeout(), 2025-11-25)
87b8e5066 (DYNDNS: use a proper 'timeout_handler', 2025-11-12)
a326df494 (OIDC_CHILD: use sss_child_handle_timeout(), 2025-11-25)
bee133590 (KRB5_CHILD: use sss_child_handle_timeout(), 2025-11-25)
7f3e0dccc (CHILD HELPERS: let generic timeout handler set 'io->in_use', 2025-11-25)
d97d14f27 (PAM/PASSKEY: use sss_child_handle_timeout(), 2025-11-25)
1019f9a8c (PAM/P11: use sss_child_handle_timeout(), 2025-11-25)
d57290a08 (PAM/P11: get rid of unused 'pam_check_cert_state::child_status', 2025-11-25)
863673729 (ad_machine_pw_renewal: use sss_child_handle_timeout(), 2025-11-12)
b384d1f15 (ad_machine_pw_renewal: remove unused variables, 2025-11-12)
4f3b98a8f (CHILD HANDLERS: add standard timeout handler, 2025-11-11)
407eda3e9 (IFP: use correct error code for timeout, 2025-11-11)
d865ac345 (ipa: check for empty trusts in ipa_get_trust_type(), 2025-12-02)
b0af250cf (config/cfg_rules.ini: Make regexp's more POSIX compliant, 2025-11-23)
95994dd91 (SUBID: trusted subdomains aren't currently supported, 2025-10-10)
f255e37fa (SUBID: sanitize range owner dn, 2025-09-16)
79028efff (SUBID: resolve owner DN instead of guessing, 2025-08-15)
0edeb89c3 (DEBUG: lower debug level of several messages, 2025-09-12)
9014ced63 (man: document subid LDAP attributes, 2025-08-13)
7a516505d (SUBID: don't require search bases to be set in advance, 2025-08-12)
ae98d8e38 (LDAP: add subid ranges support, 2025-08-01)
9901ed36c (SUBID: deprecate `ipa_subid_ranges_search_base`, 2025-08-04)
6fcf7c3a8 (SUBID:IPA: correct OC, 2025-09-16)
fcbf23d46 (MAN: fix missing `with_subid` condition, 2025-08-01)
1d488d53c (CONTRIB:fedconfig: enable '--with-subid', 2025-08-01)
637b7bcb7 (test: check temporary address exclusion, 2025-10-31)

[sumit-bose]

Hi,

thank you for the report. Would it be possible to re-run the test with debug_level = 9 in all sections of sssd.conf, especially [pam] and [domain/...]?

bye,
Sumit

[flo-renaud]

Hi @sumit-bose

I launched the tests with debug_level=9 in this PR: freeipa/freeipa#8053

You can find all the logs here, and especially the first test failure there

[sumit-bose]

Hi @flo-renaud ,

I opened #8296 with a fix and created freeipa/freeipa#8055 to run the FreeIPA tests and it looks like "sssd-fedora/test_otp" is passing now, but there are other failures. Can you check if the results from freeipa/freeipa#8055 are as expected and #8296 fixes the issue?

Thanks.

bye,
Sumit

[flo-renaud]

There were failures in AzureCI (which is flaky) and a test timeout. I relaunched the failed tests, let's see the next run.