Hide Forgot
Description of problem: Multiple "renew_all_tgts" and "renew_handlers" are being called as seen from sssd_DOMAIN.log. Version-Release number of selected component (if applicable): sssd-1.5.1-34.el6 How reproducible: Occasionally Steps to Reproduce: 1. Configure sssd as shown in the Additional Info section. 2. Auth as puser1: # ssh -l puser1 localhost puser1@localhost's password: Last login: Thu May 26 10:31:13 2011 from localhost Could not chdir to home directory /export/puser1: No such file or directory -sh-4.1$ 3. TGT renewals happen appropriately as per /var/log/sssd/sssd_default.log 4. Now, stop KDC. 5. Wait till the backend goes offline. 6. Run the command "gentent -s sss passwd kau1" (kau1 user doesn't exist in cache) 7. Start the KDC. 8. Run the command "gentent -s sss passwd kau1" or Auth as puser1. 9. The line "[renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at" keeps coming multiple times at the same instance of time. <snip> (Thu May 26 12:09:16 2011) [sssd[be[default]]] [safe_remove_old_ccache_file] (7): New and old ccache file are the same, no one will be deleted. (Thu May 26 12:09:16 2011) [sssd[be[default]]] [krb5_save_ccname] (9): Save ccname [FILE:/tmp/krb5_cache/krb5cc_puser1] for user [puser1]. (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 0) (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): start ldb transaction (nesting: 1) (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x8bd8340 (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x8be3b10 (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): tevent: Destroying timer event 0x8be3b10 "ltdb_timeout" (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): tevent: Ending timer event 0x8bd8340 "ltdb_callback" (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): commit ldb transaction (nesting: 1) (Thu May 26 12:09:16 2011) [sssd[be[default]]] [ldb] (9): commit ldb transaction (nesting: 0) (Thu May 26 12:09:16 2011) [sssd[be[default]]] [krb5_child_done] (7): Adding [FILE:/tmp/krb5_cache/krb5cc_puser1] for automatic renewal. (Thu May 26 12:09:16 2011) [sssd[be[default]]] [add_tgt_to_renew_table] (7): Added [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:16 2011) [sssd[be[default]]] [renew_tgt_done] (4): Successfully renewed TGT for user [puser1]. (Thu May 26 12:09:16 2011) [sssd[be[default]]] [child_sig_handler] (7): Waiting for child [22518]. (Thu May 26 12:09:16 2011) [sssd[be[default]]] [child_sig_handler] (4): child [22518] finished successfully. (Thu May 26 12:09:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 8BCC550 (Thu May 26 12:09:25 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching. (Thu May 26 12:09:25 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [ping] (Thu May 26 12:09:26 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:26 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. (Thu May 26 12:09:26 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:26 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. (Thu May 26 12:09:35 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 8BCC550 (Thu May 26 12:09:35 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching. (Thu May 26 12:09:35 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [ping] (Thu May 26 12:09:37 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:37 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. (Thu May 26 12:09:37 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:37 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. (Thu May 26 12:09:45 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 8BCC550 (Thu May 26 12:09:45 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching. (Thu May 26 12:09:45 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [ping] (Thu May 26 12:09:48 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:48 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. (Thu May 26 12:09:48 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:48 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. (Thu May 26 12:09:55 2011) [sssd[be[default]]] [sbus_dispatch] (9): dbus conn: 8BCC550 (Thu May 26 12:09:55 2011) [sssd[be[default]]] [sbus_dispatch] (9): Dispatching. (Thu May 26 12:09:55 2011) [sssd[be[default]]] [sbus_message_handler] (9): Received SBUS method [ping] (Thu May 26 12:09:59 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:59 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. (Thu May 26 12:09:59 2011) [sssd[be[default]]] [renew_all_tgts] (9): Checking [FILE:/tmp/krb5_cache/krb5cc_puser1] for renewal at [Thu May 26 12:11:13 2011]. (Thu May 26 12:09:59 2011) [sssd[be[default]]] [renew_handler] (7): Adding new renew timer. </snip> Actual results: Multiple "renew_handler" & "renew_all_tgts" are being called at the same instance of time as seen in the logs. Expected results: Multiple "renew_handler" & "renew_all_tgts" shouldn't be called. Additional info: 1. # cat /etc/sssd/sssd.conf [sssd] config_file_version = 2 reconnection_retries = 3 sbus_timeout = 30 services = nss, pam domains = default [nss] filter_groups = root filter_users = root reconnection_retries = 3 debug_level = 9 [pam] reconnection_retries = 3 [domain/default] debug_level = 9 id_provider = ldap ldap_uri = ldap://<LDAP SERVER> ldap_search_base = dc=example,dc=com auth_provider = krb5 krb5_server = <KDC> krb5_realm = EXAMPLE.COM krb5_lifetime = 120 krb5_renew_interval = 10 krb5_renewable_lifetime = 150m krb5_ccname_template = FILE:%d/krb5cc_%u krb5_ccachedir = /tmp/krb5_cache
Steps to verify: 1. Configure sssd for auto renewal and start sssd. 2. Login as a user to get a renewable ticket. 3. Stop KDC. 4. Wait for provider to go offline. 5. Start KDC. 6. Check log for "[renew_all_tgts] (9): Checking [FILE:/tmp/krb5cc_XXXX_XXXXX] for renewal at [Tue Sep 27 22:18:40 2011]" messages. Repeat steps 2-6 for about 3 cycles. "renew_all_tgts" and "renew_handler" messages no longer appear multiple times. Verified in version: # rpm -qi sssd | head Name : sssd Relocations: (not relocatable) Version : 1.5.1 Vendor: Red Hat, Inc. Release : 52.el6 Build Date: Tue 20 Sep 2011 09:11:03 PM IST Install Date: Mon 26 Sep 2011 05:56:30 PM IST Build Host: x86-010.build.bos.redhat.com Group : Applications/System Source RPM: sssd-1.5.1-52.el6.src.rpm Size : 3550647 License: GPLv3+ Signature : (none) Packager : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla> URL : http://fedorahosted.org/sssd/ Summary : System Security Services Daemon
Technical note added. If any revisions are required, please edit the "Technical Notes" field accordingly. All revisions will be proofread by the Engineering Content Services team. New Contents: Cause: The Kerberos ticket renewal timer tasks were issued every time a back end detected it was online Consequence: Bigger load on KDC servers and potentially confusing log messages Fix: The code that starts the renewal tasks was fixed to only issue them as configured Result: The ticket renewal tasks are only issued as per the krb5_renew_interval parameter
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. http://rhn.redhat.com/errata/RHBA-2011-1529.html