[Freeipa-users] krb5_child always reports going offline when trying to login

Hi All. I have a small test installation of IPA (RHEL7, ipa-server-4.6.4-10.el7_6.3.x86_64) in a sync arrangement with our local AD (passwords sync’d via Passsync). When trying to login to the IPA server as myself (rns) or other IPA user, sssd seems to report going offline in krb5_child.log after initially being online (log level = 9 here) and the login attempt fails: (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [unpack_buffer] (0x0100): cmd [249] uid [10846] gid [10000] validate [true] enterprise principal [false] offline [false] UPN [rns@LOCALREALM] (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [unpack_buffer] (0x2000): No old ccache (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:10846] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/ipa-server.localdomain@LOCALREALM] (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/ipa-server.localdomain@LOCALREALM in keytab. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [match_principal] (0x1000): Principal matched to the sample (host/ipa-server.localdomain@LOCALREALM). (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [get_tgt_times] (0x1000): FAST ccache must be recreated (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4192]]]] [become_user] (0x0200): Trying to become user [0][0]. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4192]]]] [become_user] (0x0200): Already user [0]. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4192]]]] [check_fast_ccache] (0x2000): Running as [0][0]. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4192]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true] (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4192]]]] [create_ccache] (0x4000): Initializing ccache of type [FILE] (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4192]]]] [create_ccache] (0x4000): returning: 0 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [check_fast_ccache] (0x0200): FAST TGT was successfully recreated! (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [become_user] (0x0200): Trying to become user [10846][10000]. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [main] (0x2000): Running as [10846][10000]. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [k5c_setup] (0x2000): Running as [10846][10000]. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true] (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [main] (0x0400): Will perform pre-auth (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [LOCALREALM] (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205507: Getting initial credentials for rns@LOCALREALM (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205508: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_LOCALREALM (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205509: Retrieving host/ipa-server.localdomain@LOCALREALM -> krb5_ccache_conf_data/fast_avail/krbtgt\/LOCALREALM\@LOCALREALM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_LOCALREALM with result: -1765328243/Matching credential not found (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205511: Sending unauthenticated request (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205512: Sending request (189 bytes) to LOCALREALM (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205513: Initiating TCP connection to stream 172.22.6.6:88 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205514: Sending TCP request to stream 172.22.6.6:88 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205515: Received answer (327 bytes) from stream 172.22.6.6:88 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205516: Terminating TCP connection to stream 172.22.6.6:88 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205517: Response was from master KDC (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205518: Received error from KDC: -1765328359/Additional pre-authentication required (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205519: Upgrading to FAST due to presence of PA_FX_FAST in reply (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205520: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_LOCALREALM (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205521: Retrieving host/ipa-server.localdomain@LOCALREALM -> krb5_ccache_conf_data/fast_avail/krbtgt\/LOCALREALM\@LOCALREALM@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_LOCALREALM with result: -1765328243/Matching credential not found (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205522: Getting credentials host/ipa-server.localdomain@LOCALREALM -> krbtgt/LOCALREALM@LOCALREALM using ccache MEMORY:/var/lib/sss/db/fast_ccache_LOCALREALM (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205523: Retrieving host/ipa-server.localdomain@LOCALREALM -> krbtgt/LOCALREALM@LOCALREALM from MEMORY:/var/lib/sss/db/fast_ccache_LOCALREALM with result: 0/Success (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205524: Armor ccache sesion key: aes256-cts/F8B1 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205526: Creating authenticator for host/ipa-server.localdomain@LOCALREALM -> krbtgt/LOCALREALM@LOCALREALM, seqnum 0, subkey aes256-cts/D6BB, session key aes256-cts/F8B1 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205528: FAST armor key: aes256-cts/B572 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205530: Sending unauthenticated request (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205531: Encoding request body and padata into FAST request (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205532: Sending request (1793 bytes) to LOCALREALM (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205533: Initiating TCP connection to stream 172.22.6.6:88 (Thu Jun 6 13:47:02 2019) [[sssd[krb5_child[4191]]]] [sss_child_krb5_trace_cb] (0x4000): [4191] 1559792822.205534: Sending TCP request to stream 172.22.6.6:88 (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [main] (0x0400): krb5_child started. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [unpack_buffer] (0x1000): total buffer size: [130] (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [unpack_buffer] (0x0100): cmd [241] uid [10846] gid [10000] validate [true] enterprise principal [false] offline [true] UPN [rns@LOCALREALM] (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [unpack_buffer] (0x2000): No old ccache (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:10846] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [become_user] (0x0200): Trying to become user [10846][10000]. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [main] (0x2000): Running as [10846][10000]. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [become_user] (0x0200): Trying to become user [10846][10000]. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [become_user] (0x0200): Already user [10846]. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [k5c_setup] (0x2000): Running as [10846][10000]. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Thu Jun 6 13:47:11 2019) [[sssd[krb5_child[4218]]]] [main] (0x0400): Will perform offline auth Can someone with more knowledge of IPA provide some pointers as to what I should look for to help debug this issue? A plain old ‘kinit rns@LOCALDOMAIN’ works fine, FWIW. Regards, Robert.