SSSD / sssd

#4018 KEYRING ccache not working with krb5 1.16.2
Closed: Fixed by xenu. Opened by xenu.

Closed: Fixed
Reopen Issue

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].

Hi,

do you have a chance to update to krb5-1.16.3? This might be related to http://krbdev.mit.edu/rt/Ticket/Display.html?id=8771.

HTH

bye,
Sumit

Metadata Update from @xenu:
- Issue close_status updated to: Fixed
- Issue status updated to: Closed (was: Open)

Hello Sumit,

that was it. I build 1.16.3 and am able to use the KEYRING ccache again.
Closing this as fixed. I will ask the package maintainer for arch to update if he gets a chance.

Thanks a lot.

SSSD is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in SSSD's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/SSSD/sssd/issues/4989

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.
Metadata
None
None
None
None
High
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.