On Чцв, 15 лют 2024, Heidi Hough via FreeIPA-users wrote:
You are correct, debugging was only specified in the [domain/...]
section. I have enabled for nss and gathered logs again. The client and server times are
indeed in sync.
I initiated my login attempt at approximately 10:16:30. At approximately 10:17:10 I was
presented with a prompt to enter my password. After entering my password I was again
presented with a password prompt. After entering multiple times with no success I waited
and eventually the connection attempt timed out.
Server Logs for this attempt
https://privatebin.net/?74adb14729c459fc#EhqWm6x2LVgfnL7iAmLZDFh3TtXpwgsH...
Client Logs for this attempt
https://privatebin.net/?1d3532466812bef2#C6ECF2RnRMEXVi7HGLd8iYvhoSmEw2uR...
It seems like a considerable amount of time is spent searching the AD
groups a user is a member of. For testing purposes, an AD account was
created that is not a member of any groups. This user was able to
successfully log in. What additional steps should be taken to account
for AD's where users are members of many groups? To add to the
complexity, many of these groups are nested.
If time to resolve all groups is above 10 seconds, then you might want
to increase timeouts. There are three elements in a lookup:
- SSSD on the client to IPA server's LDAP server
- IPA server's LDAP server to local SSSD on the IPA server
- SSSD on the IPA server to AD DCs
The middle one (LDAP server plugin to local SSSD) should have a timeout
that covers time spent in resolving the most complex query issued to AD
DCs. SSSD on the client should be able to handle at least that timeout
too.
I've reviewed this document (
https://access.redhat.com/articles/2133801) and spent
time adjusting parameters with little success.
The sssd.conf on both client and server include the following in the [domain/...]
section:
subdomain_inherit = ignore_group_members
ignore_group_members = True
Should these be placed somewhere else instead? Are there other options
that should be set to account for large numbers of nested AD groups?
No, these should be OK. The only potential change you might want to do
is to bump a timeout used by the ipa-exdom-extop plugin when it talks to
the SSSD on the server side:
https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/9/...
It is 10 seconds by default but in your case it looks like the whole set
of operations to reverse resolve all those groups takes around 20-26
seconds. Notice the diffs between 'Looking up ...' and 'Object found,
but needs to be refreshed', most are within the same second but few are
requiring up to 5 seconds. These are actions to do 'initgroups'
operation which is typically run by the client side when you log in, to
build a list of secondary groups for your login process. I guess a first
login would require a lot time due to this information being not yet
available but consequent ones would take much lower time.
$ grep 'CID#8' sssd_nss.log |grep -E '(Looking up|but needs)'
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #31: Looking up
heidi-ad(a)ad.contoso.com
(2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #31: Looking up
[heidi-ad(a)ad.contoso.com] in cache
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #31: Object
found, but needs to be refreshed.
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #32: Looking up
heidi-ad(a)ad.contoso.com
(2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #32: Looking up
[heidi-ad(a)ad.contoso.com] in cache
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #32: Object
found, but needs to be refreshed.
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #33: Looking up
heidi-ad(a)ad.contoso.com
(2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #33: Looking up
[heidi-ad(a)ad.contoso.com] in cache
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #33: Object
found, but needs to be refreshed.
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #34: Looking up
GID:603892026@ad.contoso.com
(2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #34: Looking up
[GID:603892026@ad.contoso.com] in cache
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #34: Object
found, but needs to be refreshed.
(2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #35: Looking up
GID:602655731@ad.contoso.com
(2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #35: Looking up
[GID:602655731@ad.contoso.com] in cache
(2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #35: Object
found, but needs to be refreshed.
(2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #36: Looking up
GID:604961401@ad.contoso.com
(2024-02-14 10:16:31): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #36: Looking up
[GID:604961401@ad.contoso.com] in cache
(2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #36: Object
found, but needs to be refreshed.
(2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #37: Looking up
GID:602655735@ad.contoso.com
(2024-02-14 10:16:31): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #37: Looking up
[GID:602655735@ad.contoso.com] in cache
(2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #37: Object
found, but needs to be refreshed.
(2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #38: Looking up
GID:604859746@ad.contoso.com
(2024-02-14 10:16:31): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #38: Looking up
[GID:604859746@ad.contoso.com] in cache
(2024-02-14 10:16:34): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #38: Object
found, but needs to be refreshed.
(2024-02-14 10:16:34): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #39: Looking up
GID:604965529@ad.contoso.com
(2024-02-14 10:16:34): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #39: Looking up
[GID:604965529@ad.contoso.com] in cache
(2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #39: Object
found, but needs to be refreshed.
(2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #40: Looking up
GID:605125185@ad.contoso.com
(2024-02-14 10:16:39): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #40: Looking up
[GID:605125185@ad.contoso.com] in cache
(2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #40: Object
found, but needs to be refreshed.
(2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #41: Looking up
GID:601449600@ad.contoso.com
(2024-02-14 10:16:39): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #41: Looking up
[GID:601449600@ad.contoso.com] in cache
(2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #41: Object
found, but needs to be refreshed.
(2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #42: Looking up
GID:604750598@ad.contoso.com
(2024-02-14 10:16:39): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #42: Looking up
[GID:604750598@ad.contoso.com] in cache
(2024-02-14 10:16:40): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #42: Object
found, but needs to be refreshed.
(2024-02-14 10:16:40): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #43: Looking up
GID:605323973@ad.contoso.com
(2024-02-14 10:16:40): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #43: Looking up
[GID:605323973@ad.contoso.com] in cache
(2024-02-14 10:16:42): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #43: Object
found, but needs to be refreshed.
(2024-02-14 10:16:42): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #44: Looking up
GID:605323972@ad.contoso.com
(2024-02-14 10:16:42): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #44: Looking up
[GID:605323972@ad.contoso.com] in cache
(2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #44: Object
found, but needs to be refreshed.
(2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #46: Looking up
GID:604874522@ad.contoso.com
(2024-02-14 10:16:44): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #46: Looking up
[GID:604874522@ad.contoso.com] in cache
(2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #46: Object
found, but needs to be refreshed.
(2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #47: Looking up
GID:604954881@ad.contoso.com
(2024-02-14 10:16:44): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #47: Looking up
[GID:604954881@ad.contoso.com] in cache
(2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #47: Object
found, but needs to be refreshed.
(2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #49: Looking up
GID:604962564@ad.contoso.com
(2024-02-14 10:16:44): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #49: Looking up
[GID:604962564@ad.contoso.com] in cache
(2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #49: Object
found, but needs to be refreshed.
(2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #51: Looking up
GID:605156103@ad.contoso.com
(2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #51: Looking up
[GID:605156103@ad.contoso.com] in cache
(2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #51: Object
found, but needs to be refreshed.
(2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #53: Looking up
GID:605150943@ad.contoso.com
(2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #53: Looking up
[GID:605150943@ad.contoso.com] in cache
(2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #53: Object
found, but needs to be refreshed.
(2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #55: Looking up
GID:604144821@ad.contoso.com
(2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #55: Looking up
[GID:604144821@ad.contoso.com] in cache
(2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #55: Object
found, but needs to be refreshed.
(2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #57: Looking up
GID:605251188@ad.contoso.com
(2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #57: Looking up
[GID:605251188@ad.contoso.com] in cache
(2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #57: Object
found, but needs to be refreshed.
(2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #59: Looking up
GID:605131034@ad.contoso.com
(2024-02-14 10:16:46): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #59: Looking up
[GID:605131034@ad.contoso.com] in cache
(2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #59: Object
found, but needs to be refreshed.
(2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #61: Looking up
GID:604758004@ad.contoso.com
(2024-02-14 10:16:46): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #61: Looking up
[GID:604758004@ad.contoso.com] in cache
(2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #61: Object
found, but needs to be refreshed.
(2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #63: Looking up
GID:602656027@ad.contoso.com
(2024-02-14 10:16:46): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #63: Looking up
[GID:602656027@ad.contoso.com] in cache
(2024-02-14 10:16:52): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #63: Object
found, but needs to be refreshed.
--
/ Alexander Bokovoy
Sr. Principal Software Engineer
Security / Identity Management Engineering
Red Hat Limited, Finland