Bug 805729 - sssd_nss dies and does not get restarted properly
sssd_nss dies and does not get restarted properly
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: sssd (Show other bugs)
6.2
x86_64 Linux
unspecified Severity high
: rc
: ---
Assigned To: Stephen Gallagher
IDM QE LIST
:
Depends On:
Blocks: 950156
  Show dependency treegraph
 
Reported: 2012-03-21 18:45 EDT by Johann Agnarsson
Modified: 2013-04-09 14:36 EDT (History)
4 users (show)

See Also:
Fixed In Version: sssd-1.8.0-12.el6
Doc Type: Bug Fix
Doc Text:
No documentation required
Story Points: ---
Clone Of:
: 950156 (view as bug list)
Environment:
Last Closed: 2012-06-20 07:56:25 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Johann Agnarsson 2012-03-21 18:45:38 EDT
Description of problem:
When under heavy load, sssd experiences a timeout and nss doesn't start back up properly.

Version-Release number of selected component (if applicable):
1.5.1-66.el6_2.3

How reproducible:
Eventually, always.

Steps to Reproduce:
1. Set a low timeout in domain (timeout = 1)
2. Introduce a high amount of load on machine (disk IO/CPU)
3. Keep doing user lookups until sssd_nss dies
  
Actual results:
sssd_nss doesn't get restarted properly and eventually the sssd and sssd_pam processes die off.
getent passwd does not list any AD users.

Expected results:
sssd_nss gets restarted properly and sssd continues to function.
getent passwd lists our AD users.

Additional info:

While trying to reproduce the bug, I've seen a couple of different error messages:
(/var/log/sssd/sssd_nss.log)
(Wed Mar 21 15:04:01 2012) [sssd[nss]] [sss_dp_send_acct_req_create] (0): D-BUS send failed.
(Wed Mar 21 15:04:15 2012) [sssd[nss]] [nss_dp_reconnect_init] (0): Could not reconnect to my.domain.com provider.

and 
(/var/log/sssd/sssd_nss.log)
(Wed Mar 21 13:01:39 2012) [sssd[nss]] [set_unix_socket] (0): Unable to bind on socket '/var/lib/sss/pipes/nss'
(Wed Mar 21 13:01:39 2012) [sssd[nss]] [sss_process_init] (0): fatal error initializing socket

(/var/log/sssd/sssd.log)
(Wed Mar 21 13:01:40 2012) [sssd] [global_checks_handler] (0): Unknown child (457) did exit
(Wed Mar 21 13:01:41 2012) [sssd] [global_checks_handler] (0): Unknown child (7567) did exit
(Wed Mar 21 13:01:42 2012) [sssd] [global_checks_handler] (0): Unknown child (7921) did exit
(Wed Mar 21 14:54:45 2012) [sssd] [monitor_quit] (0): Monitor received Terminated: terminating children
(Wed Mar 21 14:58:29 2012) [sssd] [global_checks_handler] (0): Unknown child (14474) did exit
(Wed Mar 21 14:58:46 2012) [sssd] [global_checks_handler] (0): Unknown child (5079) did exit
(Wed Mar 21 15:04:02 2012) [sssd] [global_checks_handler] (0): Unknown child (6042) did exit
(Wed Mar 21 15:04:44 2012) [sssd] [global_checks_handler] (0): Unknown child (27162) did exit
(Wed Mar 21 15:05:01 2012) [sssd] [global_checks_handler] (0): Unknown child (27675) did exit
(Wed Mar 21 15:05:18 2012) [sssd] [global_checks_handler] (0): Unknown child (27764) did exit
(Wed Mar 21 15:05:36 2012) [sssd] [svc_try_restart] (0): Process [my.domain.com], definitely stopped!

(/var/log/sssd/sssd_my.domain.com.log)

(Wed Mar 21 15:05:33 2012) [sssd[be[my.domain.com]]] [server_setup] (3): CONFDB: /var/lib/sss/db/config.ldb
(Wed Mar 21 15:05:33 2012) [sssd[be[my.domain.com]]] [recreate_ares_channel] (4): Initializing new c-ares channel
(Wed Mar 21 15:05:33 2012) [sssd[be[my.domain.com]]] [be_fo_get_options] (7): Lookup order: ipv4_first
(Wed Mar 21 15:05:33 2012) [sssd[be[my.domain.com]]] [fo_context_init] (3): Created new fail over context, retry timeout is 30
(Wed Mar 21 15:05:33 2012) [sssd[be[my.domain.com]]] [sysdb_domain_init_internal] (5): DB File for my.domain.com: /var/lib/sss/db/cache_my.domain.com.ldb
(Wed Mar 21 15:06:46 2012) [sssd[be[my.domain.com]]] [ldb] (9): commit ldb transaction (nesting: 0)
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1612b40
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1612bf0
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Destroying timer event 0x1612bf0 "ltdb_timeout"
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Ending timer event 0x1612b40 "ltdb_callback"
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): trying to load memberof from /usr/lib64/ldb/memberof.so
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (6): asq: Unable to register control with rootdse!
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1626510

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1610b00

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Destroying timer event 0x1610b00 "ltdb_timeout"

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Ending timer event 0x1626510 "ltdb_callback"

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0x1611f30

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0x1612050

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Destroying timer event 0x1612050 "ltdb_timeout"

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [ldb] (9): tevent: Ending timer event 0x1611f30 "ltdb_callback"

(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sbus_new_connection] (1): Failed to open connection: name=org.freedesktop.DBus.Error.NoServer, message=Failed to connect to socket /var/lib/sss/pipes/private/sbus-monitor: Connection refused
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [mon_cli_init] (0): Failed to connect to monitor services.
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [be_process_init] (0): fatal error setting up monitor bus
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [main] (0): Could not initialize backend [5]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_users_process] (9): Saving 332 Users - Done
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [enum_users_op_done] (4): Users higher USN value: [56263675]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (6): calling ldap_search_ext with [(&(objectclass=group)(Name=*)(&(gidNumber=*)(!(gidNumber=0))))][OU=Groups,OU=Development,DC=my,DC=domain,DC=com].
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [objectClass]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [Name]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [userPassword]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [gidNumber]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [member]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [nsUniqueId]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [modifyTimestamp]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (7): Requesting attrs: [uSNChanged]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_get_generic_step] (8): ldap_search_ext called, msgid = 4
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [remove_krb5_info_files] (5): Could not remove [/var/lib/sss/pubconf/kdcinfo.MY.DOMAIN.COM], [2][No such file or directory]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [remove_krb5_info_files] (5): Could not remove [/var/lib/sss/pubconf/kpasswdinfo.MY.DOMAIN.COM], [2][No such file or directory]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_id_op_destroy] (9): releasing operation connection
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sdap_handle_release] (8): Trace: sh[0x1cfd210], connected[1], ops[(nil)], ldap[0x1cfd310], destructor_lock[0], release_memory[0]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [remove_connection_callback] (9): Successfully removed connection callback.
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [sbus_remove_watch] (8): 0x1ced800/0x1ced9a0
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [remove_socket_symlink] (9): The symlink points to [/var/lib/sss/pipes/private/sbus-dp_my.domain.com.27892]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [remove_socket_symlink] (9): The path including our pid is [/var/lib/sss/pipes/private/sbus-dp_my.domain.com.27892]
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [remove_socket_symlink] (9): Removed the symlink
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [be_client_destructor] (4): Removed PAM client
(Wed Mar 21 15:06:59 2012) [sssd[be[my.domain.com]]] [be_client_destructor] (4): Removed NSS client

(/var/log/messages)
Mar 21 15:04:01 IRV6A-407 sssd[be[my.domain.com]]: Shutting down
Mar 21 15:04:21 IRV6A-407 sssd[be[my.domain.com]]: Starting up
Mar 21 15:04:42 IRV6A-407 sssd[be[my.domain.com]]: Starting up
Mar 21 15:04:43 IRV6A-407 sssd[be[my.domain.com]]: Shutting down
Mar 21 15:04:59 IRV6A-407 sssd[be[my.domain.com]]: Starting up
Mar 21 15:05:00 IRV6A-407 sssd[be[my.domain.com]]: Shutting down
Mar 21 15:05:17 IRV6A-407 sssd[be[my.domain.com]]: Starting up
Mar 21 15:05:17 IRV6A-407 sssd[be[my.domain.com]]: Shutting down
Mar 21 15:05:33 IRV6A-407 sssd[be[my.domain.com]]: Starting up
Mar 21 15:05:37 IRV6A-407 sssd[nss]: Shutting down
Mar 21 15:05:37 IRV6A-407 sssd[pam]: Shutting down
Mar 21 15:06:59 IRV6A-407 sssd[be[my.domain.com]]: Shutting down

I realize this is very very similar to another bug (https://bugzilla.redhat.com/show_bug.cgi?id=740501)

bhis only happens on 6.2 with sssd-1.5.1-66 and sssd-1.5.1-66_2_3, 
but it does not happen on our 6.1 machines with sssd-1.5.1-34.

I will gladly provide any additional logs and info if needed.
Comment 2 Stephen Gallagher 2012-03-22 08:11:03 EDT
The monitor code was rewritten in SSSD 1.8, which is going to be included in RHEL 6.3. This issue should go away then.

Please test this when the RHEL 6.3 beta becomes available.
Comment 4 Kaushik Banerjee 2012-05-07 06:16:02 EDT
Verified with sssd-1.8.0-25


Tested with the following scenarios:
1. Introduce a high amount of load + set timeout=1 + keep doing user lookups.
sssd backend got restarted and I was still able to lookup users after the restart.

2. Manually killing sssd_nss process.
The process started back again and I was able to enumerate/lookup users again.
Comment 5 Stephen Gallagher 2012-06-12 09:47:44 EDT
    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:
No documentation required
Comment 7 errata-xmlrpc 2012-06-20 07:56:25 EDT
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-2012-0747.html

Note You need to log in before you can comment on or make changes to this bug.