Bug 708009

Summary: "renew_all_tgts" and "renew_handlers" messages are being logged multiple times when the provider comes back online.
Product: Red Hat Enterprise Linux 6 Reporter: Kaushik Banerjee <kbanerje>
Component: sssdAssignee: Stephen Gallagher <sgallagh>
Status: CLOSED ERRATA QA Contact: Chandrasekar Kannan <ckannan>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 6.2CC: benl, dpal, grajaiya, jgalipea, jhrozek, prc
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: sssd-1.5.1-39.el6 Doc Type: Bug Fix
Doc Text:
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
 Story Points: ---
Clone Of:
: 708104 (view as bug list) Environment:
Last Closed: 2011-12-06 16:38:37 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 708104    

Description Kaushik Banerjee 2011-05-26 14:33:41 UTC 
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
Comment 5 Kaushik Banerjee 2011-09-27 16:53:16 UTC 
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
Comment 6 Jakub Hrozek 2011-10-26 16:48:29 UTC 
    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
Comment 7 errata-xmlrpc 2011-12-06 16:38:37 UTC 
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