You are not logged in.
Copied from https://pagure.io/SSSD/sssd/issue/4018
as I do not know if this is a problem of sssd, krb5 or arch.
Thanks for any input on how to debug this further or other pointers.
I am using sssd 2.1.0 and since updating krb5 from 1.16.1 to 1.16.2 I can't login using KEYRING:persistent:uid anymore. Switching back to FILE ccache or downgrading krb5 fixes this. Manual kinit works with KEYRING though. This is using kernel 5.1.4-arch1-1-ARCH.
///////////////////////////////////////////////////////////////////////////////¬
// journalctl¬
///////////////////////////////////////////////////////////////////////////////¬
May 25 23:48:23 arch01.ipa.mydomain.com audit[11873]: ANOM_ABEND auid=4294967295 uid=1387800001 gid=1387800001 ses=4294967295 pid=11873 comm="krb5_child" exe="/usr/lib/sssd/sssd/krb5_child" sig=11 res=1¬
May 25 23:48:23 arch01.ipa.mydomain.com sssctl[11866]: pam_sss(system-auth:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost= user=username¬
May 25 23:48:23 arch01.ipa.mydomain.com sssctl[11866]: pam_sss(system-auth:auth): received for user username: 4 (System error)¬
May 25 23:48:23 arch01.ipa.mydomain.com sudo[11865]: pam_unix(sudo:session): session closed for user root¬
May 25 23:48:23 arch01.ipa.mydomain.com kernel: traps: krb5_child[11873] general protection fault ip:7f2bd3a44eab sp:7ffc657b5a70 error:0 in libkrb5.so.3.3[7f2bd3a21000+6c000]¬
May 25 23:48:23 arch01.ipa.mydomain.com kernel: audit: type=1701 audit(1558820903.033:82): auid=4294967295 uid=1387800001 gid=1387800001 ses=4294967295 pid=11873 comm="krb5_child" exe="/usr/lib/sssd/sssd/krb5_child" sig=11 res=1///////////////////////////////////////////////////////////////////////////////¬
// krb5_child.log¬
///////////////////////////////////////////////////////////////////////////////¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [main] (0x0400): krb5_child started.¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [unpack_buffer] (0x1000): total buffer size: [190]¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [unpack_buffer] (0x0100): cmd [241] uid [1387800001] gid [1387800001] validate [true] enterprise principal [false] offline [false] UPN [username@IPA.mydomain.com]¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1387800001] old_ccname: [KEYRING:persistent:1387800001] keytab: [/etc/krb5. keytab]¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [switch_creds] (0x0200): Switch user to [1387800001][1387800001].¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [sss_krb5_cc_verify_ccache] (0x2000): TGT not found or expired.¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [switch_creds] (0x0200): Switch user to [0][0].¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:1387800001] and is active and TGT is valid.¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/arch01.ipa.mydomain.com@IPA.mydomain.com]¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/arch01.ipa.mydomain.com@IPA.mydomain.com in keytab.¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [match_principal] (0x1000): Principal matched to the sample (host/arch01.ipa.mydomain.com@IPA.mydomain.com).¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid.¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [become_user] (0x0200): Trying to become user [1387800001][1387800001].¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [main] (0x2000): Running as [1387800001][1387800001].¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [sss_child_set_krb5_tracing] (0x0100): krb5 tracing is not available¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [main] (0x0400): Will perform online auth¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [tgt_req_child] (0x1000): Attempting to get a TGT¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [IPA.mydomain.com]¬
(Sat May 25 23:48:22 2019) [[sssd[krb5_child[11873]]]] [sss_krb5_responder] (0x4000): Got question [password].¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [587095897]¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [validate_tgt] (0x2000): Found keytab entry with the realm of the credential.¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [validate_tgt] (0x0400): TGT verified using key for [host/arch01.ipa.mydomain.com@IPA.mydomain.com].¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [get_and_save_tgt] (0x2000): Running as [1387800001][1387800001].¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [sss_get_ccache_name_for_principal] (0x4000): Location: [KEYRING:persistent:1387800001]¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [sss_get_ccache_name_for_principal] (0x2000): krb5_cc_cache_match failed: [-1765328243][Can't find client principal username@IPA. mydomain.com in cache collection]¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [create_ccache] (0x4000): Initializing ccache of type [KEYRING]¬
(Sat May 25 23:48:23 2019) [[sssd[krb5_child[11873]]]] [create_ccache] (0x4000): CC supports switch///////////////////////////////////////////////////////////////////////////////¬
//sssd_pam.log¬
///////////////////////////////////////////////////////////////////////////////¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #3: This request type does not support filtering result by negative cache¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #3: Returning updated object [username@ipa.mydomain.com]¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #3: Found 8 entries in domain ipa.mydomain.com¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #3: Finished: Success¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is username@ipa.mydomain.com¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_initgr_cache_set] (0x2000): [username] added to PAM initgroup cache¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data:¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: ipa.mydomain.com¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): user: username@ipa.mydomain.com¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): service: system-auth¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: not set¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: not set¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11866¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: username¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_print_data] (0x0100): flags: 2¬
(Sat May 25 23:48:22 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching.¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [pam_dp_send_req_done] (0x0200): received: [4 (System error)][ipa.mydomain.com]¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error.¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal.¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 33¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x55a66f30fdc0][20]¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!¬
(Sat May 25 23:48:23 2019) [sssd[pam]] [client_close_fn] (0x2000): Terminated client [0x55a66f312a10][19]¬
(Sat May 25 23:48:27 2019) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [username] removed from PAM initgroup cache///////////////////////////////////////////////////////////////////////////////¬
//sssd_ipa.mydomain.com.log¬
///////////////////////////////////////////////////////////////////////////////¬
(Sat May 25 23:48:22 2019) [sssd[be[ipa.mydomain.com]]] [sss_domain_get_state] (0x1000): Domain ipa.mydomain.com is Active¬
(Sat May 25 23:48:22 2019) [sssd[be[ipa.mydomain.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [11873]¬
(Sat May 25 23:48:22 2019) [sssd[be[ipa.mydomain.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [11873]¬
(Sat May 25 23:48:22 2019) [sssd[be[ipa.mydomain.com]]] [write_pipe_handler] (0x0400): All data has been sent!¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [read_pipe_handler] (0x0400): EOF received, client finished¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [parse_krb5_child_response] (0x0020): message too short.¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [krb5_auth_done] (0x0040): Could not parse child response [22]: Invalid argument¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [check_wait_queue] (0x1000): Wait queue for user [username@ipa.mydomain.com] is empty.¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [krb5_auth_queue_done] (0x0040): krb5_auth_recv failed with: 22¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [ipa_pam_auth_handler_krb5_done] (0x0040): KRB5 auth failed [22]: Invalid argument¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #25]: Request handler finished [0]: Success¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #25]: Receiving request data.¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #25]: Request removed.¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.pamHandler: Success¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [child_sig_handler] (0x1000): Waiting for child [11873].¬
(Sat May 25 23:48:23 2019) [sssd[be[ipa.mydomain.com]]] [child_sig_handler] (0x0020): child [11873] was terminated by signal [11].Last edited by ppascher (2019-05-27 19:08:53)
Offline
RESOLVED: As recommended on the pagure.io thread I build version 1.16.3 of krb5 which includes a fix for this issue. I will ask the package maintainer to update if he gets a chance.
Offline