This issue was first noticed when a RHEL 8.7 system was upgraded to RHEL 8.8, sssd package version went from:
sssd-2.7.3-4.el8_7.3.x86_64 -> sssd-2.8.2-2.el8.x86_64
It seems the sss enumeration logic took a substantial performance hit. It takes upwards of 15 seconds for the backend to be queried and cached after an NSS client calls into it while the prior 2.7.3 version would call the backend and cache within a second or shortly after daemon service startup. NSS clients prior never had much delay, but now we see services stall waiting on the NSS layer to respond, sometimes receiving truncated output from only what's in /etc/{passwd,group}.
>=2.8.0 for our environment:
- Seems to have the 15ish second delay/hang when the enum_cache_timeout expires (120 seconds by default) while the 2.7.3 version didn't show this hang & performance hit.
- While hanging, tends to return only the stub
/etc/{passwd,group} content without the actual LDAP backend contents at random times; this could be hours/days after the sssd service has started but I feel mainly has to do with NSS call frequency or lack thereof.
I think I tracked down the issue to this specific commit: acfe3b2
In particular, this section of changes in the sysdb_enum_dn_filter() function: acfe3b2?diff=unified#diff-0b9b42f46a763c002e786cfd038fbb3522844978d73bf6ae03beb7f1d3b99896L796-R820
Comparing debug output between 2.7.3 and 2.8.2 when these hangs happen, this change is observed:
debug_level = 7 added to the [sssd], [nss] and [domain/LDAP] sections of /etc/sssd/sssd.conf.
version 2.7.3 /var/log/sssd/sssd_nss.log (no delay)
(2023-09-22 11:55:20): [nss] [cache_req_search_dp] (0x0400): [CID#123] CR #6: Looking up [Users enumeration] in data provider
(2023-09-22 11:55:20): [nss] [sss_dp_get_account_send] (0x0400): [CID#123] Creating request for [LDAP][0x1][BE_REQ_USER][*:-]
(2023-09-22 11:55:20): [nss] [sss_domain_get_state] (0x1000): [CID#123] Domain LDAP is Active
(2023-09-22 11:55:20): [nss] [cache_req_search_cache] (0x0400): [CID#123] CR #6: Looking up [Users enumeration] in cache
(2023-09-22 11:55:20): [nss] [sysdb_enumpwent_filter] (0x1000): [CID#123] Searching timestamp cache with [(objectCategory=user)]
(2023-09-22 11:55:20): [nss] [sysdb_enumpwent_filter] (0x1000): [CID#123] Searching cache with [(objectCategory=user)]
(2023-09-22 11:55:20): [nss] [cache_req_search_ncache_filter] (0x0400): [CID#123] CR #6: Filtering out results by negative cache
(2023-09-22 11:55:20): [nss] [cache_req_search_done] (0x0400): [CID#123] CR #6: Returning updated object [Users enumeration]
(2023-09-22 11:55:20): [nss] [cache_req_create_and_add_result] (0x0400): [CID#123] CR #6: Found 5274 entries in domain LDAP
(2023-09-22 11:55:20): [nss] [cache_req_done] (0x0400): [CID#123] CR #6: Finished: Success
version 2.8.2 /var/log/sssd/sssd_nss.log (delay and/or truncated NSS response)
(2023-09-22 10:34:36): [nss] [cache_req_search_dp] (0x0400): [CID#120] CR #1: Looking up [Users enumeration] in data provider
(2023-09-22 10:34:36): [nss] [sss_dp_get_account_send] (0x0400): [CID#120] Creating request for [LDAP][0x1][BE_REQ_USER][*:-]
(2023-09-22 10:34:36): [nss] [sss_domain_get_state] (0x1000): [CID#120] Domain LDAP is Active
(2023-09-22 10:34:36): [nss] [cache_req_search_cache] (0x0400): [CID#120] CR #1: Looking up [Users enumeration] in cache
(2023-09-22 10:34:36): [nss] [sysdb_enumpwent_filter] (0x1000): [CID#120] Searching timestamp cache with [(objectCategory=user)]
(2023-09-22 10:34:36): [nss] [sysdb_enumpwent_filter] (0x1000): [CID#120] Searching timestamp entries with [(|(dn=name=LDAPUser@ldap,cn=users,cn=LDAP,cn=sysdb),x5000 more accounts...
<note time gap>
(2023-09-22 10:34:53): [nss] [sysdb_enumpwent_filter] (0x1000): [CID#120] Searching cache with [(objectCategory=user)]
(2023-09-22 10:34:54): [nss] [cache_req_search_ncache_filter] (0x0400): [CID#120] CR #1: Filtering out results by negative cache
(2023-09-22 10:34:54): [nss] [cache_req_search_done] (0x0400): [CID#120] CR #1: Returning updated object [Users enumeration]
(2023-09-22 10:34:54): [nss] [cache_req_create_and_add_result] (0x0400): [CID#120] CR #1: Found 5274 entries in domain LDAP
(2023-09-22 10:34:54): [nss] [cache_req_done] (0x0400): [CID#120] CR #1: Finished: Success
The ~15 second hang has been verified with hacked/modified source build to time the function call.
The change to the filter from (&(name=(null))(|(dn=name= to (|(dn=name= appears to be the cause for the unresponsive/truncated NSS response.
I built, installed & tested sssd with the following commits, the one that I suspect added the issue and the prior from the commit history:
acfe3b2 DBUS: Add ListByAttr(attr, filter, limit)
5ea1ed2 CACHE: implement get_domain for SID lookup
5ea1ed2 acts like 2.7.3 with my tests, never returning truncated output and always very responsive.
acfe3b2 shows the same issues I see with the RHEL 8.8 build. I've also tried the CentOS Stream build, 2.9.1-2.el8, it also shows the truncation & hang issues.
In the attached archive file is 2 shell scripts along with log output for both of the mentioned commits to show the hang to NSS clients and the truncated output.
logs.tar.gz
This issue was first noticed when a RHEL 8.7 system was upgraded to RHEL 8.8, sssd package version went from:
sssd-2.7.3-4.el8_7.3.x86_64 -> sssd-2.8.2-2.el8.x86_64
It seems the sss enumeration logic took a substantial performance hit. It takes upwards of 15 seconds for the backend to be queried and cached after an NSS client calls into it while the prior 2.7.3 version would call the backend and cache within a second or shortly after daemon service startup. NSS clients prior never had much delay, but now we see services stall waiting on the NSS layer to respond, sometimes receiving truncated output from only what's in
/etc/{passwd,group}.>=2.8.0 for our environment:
/etc/{passwd,group}content without the actual LDAP backend contents at random times; this could be hours/days after the sssd service has started but I feel mainly has to do with NSS call frequency or lack thereof.I think I tracked down the issue to this specific commit: acfe3b2
In particular, this section of changes in the
sysdb_enum_dn_filter()function: acfe3b2?diff=unified#diff-0b9b42f46a763c002e786cfd038fbb3522844978d73bf6ae03beb7f1d3b99896L796-R820Comparing debug output between 2.7.3 and 2.8.2 when these hangs happen, this change is observed:
debug_level = 7added to the[sssd],[nss]and[domain/LDAP]sections of/etc/sssd/sssd.conf.version 2.7.3
/var/log/sssd/sssd_nss.log(no delay)version 2.8.2
/var/log/sssd/sssd_nss.log(delay and/or truncated NSS response)The ~15 second hang has been verified with hacked/modified source build to time the function call.
The change to the filter from
(&(name=(null))(|(dn=name=to(|(dn=name=appears to be the cause for the unresponsive/truncated NSS response.I built, installed & tested sssd with the following commits, the one that I suspect added the issue and the prior from the commit history:
acfe3b2 DBUS: Add ListByAttr(attr, filter, limit)
5ea1ed2 CACHE: implement get_domain for SID lookup
5ea1ed2 acts like 2.7.3 with my tests, never returning truncated output and always very responsive.
acfe3b2 shows the same issues I see with the RHEL 8.8 build. I've also tried the CentOS Stream build, 2.9.1-2.el8, it also shows the truncation & hang issues.
In the attached archive file is 2 shell scripts along with log output for both of the mentioned commits to show the hang to NSS clients and the truncated output.
logs.tar.gz