Bug 740501

Summary: SSSD not functional after "self" reboot
Product: Red Hat Enterprise Linux 6 Reporter: Kemot1000 <kemot1000>
Component: sssdAssignee: Stephen Gallagher <sgallagh>
Status: CLOSED ERRATA QA Contact: IDM QE LIST <seceng-idm-qe-list>
Severity: high Docs Contact:
Priority: unspecified    
Version: 6.1CC: grajaiya, jgalipea, jhrozek, jzeleny, kbanerje, prc
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: sssd-1.5.1-53.el6 Doc Type: Bug Fix
Doc Text:
Cause: SSSD's NSS responder process uses an internal hash table. If SSSD backend is restarted and the NSS responder reconnects, the hash table is iterated over, but elements in it are not checked for initialization. Consequence: NSS responder can crash after it is restarted due to access to already freed memory. Fix: All elements from the hash table are copied first and iterated over afterwards. Result: The crash in NSS responder caused by possible access to freed memory doesn't occur any more.
Story Points: ---
Clone Of:
: 748818 (view as bug list) Environment:
Last Closed: 2011-12-06 16:40:13 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: 748818    

Description Kemot1000 2011-09-22 09:21:24 UTC
Description of problem:
Today morning SSSD for some reason rebooted itself. And after that there was strange behavour. I attached logs. 
1. This ended up in sssd.log at the time of failure:
(Thu Sep 22 06:41:03 2011) [sssd] [global_checks_handler] (0): Unknown child (1022) did exit
2. pam_sss stopped responding
Sep 22 06:40:33 MYSERVER db2ckpwd 0[3762]: pam_sss(db2:auth): authentication success; logname= uid=500 euid=0 tty= ruser= rhost= user=webusr
Sep 22 06:40:47 MYSERVER db2ckpwd 0[3763]: pam_unix(db2:auth): authentication failure; logname= uid=500 euid=0 tty= ruser= rhost=  user=webusr
Sep 22 06:40:51 MYSERVER db2ckpwd 0[3764]: pam_unix(db2:auth): authentication failure; logname= uid=500 euid=0 tty= ruser= rhost=  user=webusr
and
whole server froze or something because time sync job fired-up 1 min later then usually and had 4 sec time difference even though it is usually below 1 millisecond

Sep 22 06:35:01 MYSERVER ntpdate[20838]: adjust time server NTPSERVER offset 0.003414 sec
Sep 22 06:40:33 MYSERVER sssd[be[MYDOMAIN]]: Shutting down
Sep 22 06:40:58 MYSERVER sssd[be[MYDOMAIN]]: Starting up
Sep 22 06:41:03 MYSERVER ntpdate[21800]: step time server NTPSERVER offset 3.994776 sec
Sep 22 06:45:01 MYSERVER ntpdate[23106]: adjust time server NTPSERVER offset 0.001529 sec

and 
there was information that authentication succeeded event though user could not login.
Sep 22 07:36:26 MYSERVER db2ckpwd 0[3764]: pam_unix(db2:auth): authentication failure; logname= uid=500 euid=0 tty= ruser= rhost=  user=secuser
Sep 22 07:36:26 MYSERVER db2ckpwd 0[3764]: pam_sss(db2:auth): authentication success; logname= uid=500 euid=0 tty= ruser= rhost= user=secuser

we restarted SSSD service at 7.38 and it started to work. This is first time it happened. Please have a look on attached logs for more diagnostic information. 

My question is why only sssd_be process got restarted and not all (sssd_pam and sssd_nss). I think if all were restarted at crash (if this was crash) there would be no problems. 

Version-Release number of selected component (if applicable):
[root@MYSERVER ~]# rpm -qa |grep sssd
sssd-client-1.5.1-34.el6_1.3.x86_64
sssd-1.5.1-34.el6_1.3.x86_64

If you need any additional info please let me know.

Comment 2 Stephen Gallagher 2011-09-22 11:44:48 UTC
I suspect this is the same issue as https://fedorahosted.org/sssd/ticket/932 which we fixed in the master branch.

Backporting this fix should be fairly simple.

Comment 3 Jakub Hrozek 2011-09-22 20:18:03 UTC
FWIW, I just tested that the upstream commit 0e27817133b931dcbe9d196e9ed0d737164ba613 applies cleanly on both upstream 1.5 branch and the RHEL 6.2 code. No backport needed, just a cherry-pick.

Comment 6 Kemot1000 2011-10-11 08:48:37 UTC
I had this problem again. Do you have any update on when this patch will be available through RHN ?

Comment 7 Kemot1000 2011-10-11 09:00:11 UTC
logs from /var/log/messages:

Oct 11 10:05:01 MYSERVER  ntpdate[6114]: adjust time server MYTIMESERVER  offset -0.005464 sec
Oct 11 10:07:28 MYSERVER sssd[be[MYDOMAIN]]: Shutting down
Oct 11 10:07:28 MYSERVER  sssd[be[MYDOMAIN]]: Starting up
Oct 11 10:07:40 MYSERVER  sssd[nss]: Starting up
Oct 11 10:07:41 MYSERVER  sssd[nss]: Starting up
Oct 11 10:07:42 MYSERVER  sssd[nss]: Starting up
Oct 11 10:07:43 MYSERVER  sssd[nss]: Starting up
Oct 11 10:10:01 MYSERVER  ntpdate[11952]: adjust time server MYTIMESERVER offset -0.041573 sec

and after manual sssd restart:

Oct 11 10:40:12 MYSERVER  init: tty (/dev/tty1) main process ended, respawning
Oct 11 10:40:32 MYSERVER  sssd[be[MYDOMAIN]]: Shutting down
Oct 11 10:40:32 MYSERVER  sssd[pam]: Shutting down
Oct 11 10:40:32 MYSERVER  kernel: sssd_pam[1374]: segfault at ca92ac ip 0000000000ca92ac sp 00007fff58ded938 error 15
Oct 11 10:40:33 MYSERVER  sssd: Starting up
Oct 11 10:40:33 MYSERVER  sssd[be[MYDOMAIN]]: Starting up
Oct 11 10:40:33 MYSERVER  sssd[nss]: Starting up
Oct 11 10:40:33 MYSERVER  sssd[pam]: Starting up
Oct 11 10:41:44 MYSERVER  init: tty (/dev/tty1) main process ended, respawning

Comment 8 Jakub Hrozek 2011-10-11 09:29:29 UTC
The fix Stephen referenced will be available when RHEL6.2 comes out.

But the logs you posted indicate it might as well be a different issue (upstream #1038).

Did you manage to get a corefile?

Comment 9 Kemot1000 2011-10-11 12:05:01 UTC
Unfortunately no core file.

I found this in:

sssd.log
(Tue Oct 11 10:07:21 2011) [sssd] [ping_check] (0): A service PING returned an error [org.freedesktop.DBus.Error.NoReply], closing connection.
(Tue Oct 11 10:07:31 2011) [sssd] [global_checks_handler] (0): Unknown child (1369) did exit
(Tue Oct 11 10:07:44 2011) [sssd] [svc_try_restart] (0): Process [nss], definitely stopped!
(Tue Oct 11 10:40:32 2011) [sssd] [monitor_quit] (0): Monitor received Terminated: terminating children

sssd_nss.log
(Tue Oct 11 10:07:40 2011) [sssd[nss]] [sss_dp_init] (0): Failed to connect to monitor services.
(Tue Oct 11 10:07:40 2011) [sssd[nss]] [sss_process_init] (0): fatal error setting up backend connector
(Tue Oct 11 10:07:41 2011) [sssd[nss]] [sss_dp_init] (0): Failed to connect to monitor services.
(Tue Oct 11 10:07:41 2011) [sssd[nss]] [sss_process_init] (0): fatal error setting up backend connector
(Tue Oct 11 10:07:42 2011) [sssd[nss]] [sss_dp_init] (0): Failed to connect to monitor services.
(Tue Oct 11 10:07:42 2011) [sssd[nss]] [sss_process_init] (0): fatal error setting up backend connector
(Tue Oct 11 10:07:43 2011) [sssd[nss]] [sss_dp_init] (0): Failed to connect to monitor services.
(Tue Oct 11 10:07:43 2011) [sssd[nss]] [sss_process_init] (0): fatal error setting up backend connector


sssd_pam.log
(Tue Oct 11 10:07:44 2011) [sssd[pam]] [pam_dp_reconnect_init] (0): Could not reconnect to MYDOMAIN provider.
(Tue Oct 11 10:08:14 2011) [sssd[pam]] [pam_dp_reconnect_init] (0): Could not reconnect to MYDOMAIN provider.
....
(Tue Oct 11 10:39:45 2011) [sssd[pam]] [pam_dp_reconnect_init] (0): Could not reconnect to MYDOMAIN provider.
(Tue Oct 11 10:40:15 2011) [sssd[pam]] [pam_dp_reconnect_init] (0): Could not reconnect to MYDOMAIN provider.

Comment 10 Kemot1000 2011-10-11 12:08:13 UTC
You are right this looks like this bug:

https://fedorahosted.org/sssd/ticket/1038

Comment 11 Jenny Severance 2011-10-26 12:00:08 UTC
Can you please add clear steps to verify?

Comment 12 Jakub Hrozek 2011-10-26 13:57:09 UTC
This is how I'd just reproduced it with -53:

1) configure an SSSD domain with a very low timeout (timeout=1 worked for me). Start SSSD
2) trigger many logins with SSSD coming in rapidly. I used the "check_user" testcase that Kaushik is using. Wait until sssd stops responding.
3) shut down or restart SSSD

Comment 13 Jenny Severance 2011-10-26 14:15:14 UTC
Thanks!

Comment 14 Jan Zeleny 2011-10-27 12:06:07 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: SSSD's NSS responder process uses an internal hash table. If SSSD backend is restarted and the NSS responder reconnects, the hash table is iterated over, but elements in it are not checked for initialization.
Consequence: NSS responder can crash after it is restarted due to access to already freed memory.
Fix: All elements from the hash table are copied first and iterated over afterwards.
Result: The crash in NSS responder caused by possible access to freed memory doesn't occur any more.

Comment 15 Kaushik Banerjee 2011-11-02 07:46:08 UTC
Verified with timeout = 1 that sssd doesn't crash after the backend is restarted.

Enumeration and auth works even after the backend is restarted.


Verified in version:

# rpm -qi sssd | head
Name        : sssd                         Relocations: (not relocatable)
Version     : 1.5.1                             Vendor: Red Hat, Inc.
Release     : 66.el6                        Build Date: Tue 01 Nov 2011 02:05:40 AM IST
Install Date: Tue 01 Nov 2011 02:37:31 PM IST      Build Host: x86-003.build.bos.redhat.com
Group       : Applications/System           Source RPM: sssd-1.5.1-66.el6.src.rpm
Size        : 3628521                          License: GPLv3+
Signature   : (none)
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
URL         : http://fedorahosted.org/sssd/
Summary     : System Security Services Daemon

Comment 16 errata-xmlrpc 2011-12-06 16:40:13 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