11:47 a.m.
I'm having an issue with sssd failing to look up user or group names from an AD
provider. The error occurs on both modern Fedora and Centos 7 systems joined to AD via
realm commands. On Centos 7, the version of SSSD is 1.16.0, and that is the version on
which I am reporting.
The systems will work perfectly for a long time (up to months) and then suddenly start
failing. The most noticeable failure is that "ls -l" of files will give UID/GID
numbers, not names, and also ssh into the system will report the error "/usr/bin/id:
cannot find name for group ID".
The failure can be temporarily cured with commands such as:
getent passwd username
getent group "domain users"
but after a short period of time the failure resumes. Clearing the cache via
"sss_cache -E" also causes the problem to immediately manifest.
I ran some tests with logging enabled. NSS debug level set to 6. The test is to issue the
command:
ls -ld dpotterv
When things are working, I see:
drwx------. 19 dpotterv domain users 29 Jun 1 10:08 dpotterv
When things are failing, I see:
drwx------. 19 900209170 900200513 29 Jun 1 10:08 dpotterv
Here are the entries from the nss log for FAILURE:
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected!
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client
version [1].
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version
[1].
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 900209170
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_send] (0x0400): CR #21: New request
'User by ID'
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #21:
Performing a multi-domain search
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #21: Search
will check the cache and check the data provider
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #21: Using
domain [local]
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_send] (0x0400): CR #21: Looking
up UID:900209170@local
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21:
Checking negative cache for [UID:900209170@local]
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #21:
[UID:900209170@local] is not present in negative cache
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #21: Looking
up [UID:900209170@local] in cache
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_idminmax_check] (0x0200): id exceeds
min/max boundaries
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #21: ID
[UID:900209170@local] was filtered out
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_locate_dom_cache_done] (0x0040):
cache_req_search_recv returned [1432158300]: ID is outside the allowed range
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_process_result] (0x0400): CR #21:
Finished: Error 1432158300: ID is outside the allowed range
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected!
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client
version [1].
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version
[1].
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 900200513
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_send] (0x0400): CR #22: New request
'Group by ID'
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #22:
Performing a multi-domain search
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #22: Search
will check the cache and check the data provider
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #22: Using
domain [local]
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_send] (0x0400): CR #22: Looking
up GID:900200513@local
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #22:
Checking negative cache for [GID:900200513@local]
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #22:
[GID:900200513@local] is not present in negative cache
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #22: Looking
up [GID:900200513@local] in cache
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_idminmax_check] (0x0200): id exceeds
min/max boundaries
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #22: ID
[GID:900200513@local] was filtered out
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_locate_dom_cache_done] (0x0040):
cache_req_search_recv returned [1432158300]: ID is outside the allowed range
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [cache_req_process_result] (0x0400): CR #22:
Finished: Error 1432158300: ID is outside the allowed range
(Fri Jun 1 11:17:59 2018) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
I should note that in the sssd config file, I have:
[domain/local]
min_id = 3000
max_id = 199999
id_provider = local
access_provider = permit
remove_homedir = false
[domain/anl]
min_id = 200000
ldap_idmap_range_size = 100000000
cache_credentials = false
id_provider = ad
access_provider = ad
auth_provider = ad
chpass_provider = ad
ldap_schema = ad
ldap_id_mapping = true
(Yes, we have a very large range size. Currently, about 0.75 million SIDs in the AD
forest, and someone wanted room for growth.)
Looking at the log entries, I see what looks like normal flow of events. A multi-domain
search is initiated, and the first domain searched is the local one.
It correctly determines that the ID is outside the range that is valid for this domain,
and it returns.
What is not happening is a subsequent search of the ANL domain where the ID is valid!
The following is the NSS log when I do "getent passwd dpotterv", which
succeeds:
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected!
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client
version [1].
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version
[1].
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [nss_getby_name] (0x0400): Input name: dpotterv
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_send] (0x0400): CR #27: New request
'User by name'
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_process_input] (0x0400): CR #27: Parsing
input name [dpotterv]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name
'dpotterv' matched without domain, user is dpotterv
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_set_name] (0x0400): CR #27: Setting name
[dpotterv]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #27:
Performing a multi-domain search
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #27: Search
will check the cache and check the data provider
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #27: Using
domain [local]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #27:
Preparing input data for domain [local] rules
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_send] (0x0400): CR #27: Looking
up dpotterv@local
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #27:
Checking negative cache for [dpotterv@local]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #27:
[dpotterv@local] is not present in negative cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #27: Looking
up [dpotterv@local] in cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #27: Object
[dpotterv@local] was not found in cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #27: Looking up
[dpotterv@local] in data provider
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #27: Looking
up [dpotterv@local] in cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #27: Object
[dpotterv@local] was not found in cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_ncache_add_to_domain] (0x0400):
CR #27: Adding [dpotterv@local] to negative cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding
[NCE/USER/local/dpotterv@local] to negative cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #27: Using
domain [anl]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #27:
Preparing input data for domain [anl] rules
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_send] (0x0400): CR #27: Looking
up dpotterv@anl
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #27:
Checking negative cache for [dpotterv@anl]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #27:
[dpotterv@anl] is not present in negative cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #27: Looking
up [dpotterv@anl] in cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_send] (0x0400): CR #27: Object
found, but needs to be refreshed.
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #27: Looking up
[dpotterv@anl] in data provider
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request
for [0x5560f40e6b50:1:dpotterv@anl@anl]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request
for [anl][0x1][BE_REQ_USER][name=dpotterv@anl:-]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering
request [0x5560f40e6b50:1:dpotterv@anl@anl]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #27: Looking
up [dpotterv@anl] in cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #27:
This request type does not support filtering result by negative cache
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_search_done] (0x0400): CR #27: Returning
updated object [dpotterv@anl]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #27:
Found 1 entries in domain anl
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request:
[0x5560f40e6b50:1:dpotterv@anl@anl]
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [cache_req_done] (0x0400): CR #27: Finished:
Success
(Fri Jun 1 11:34:14 2018) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
This looks like a completely routine multi-domain search by name, first searching the
local domain, and then searching the ANL domain, where it queries and receives an answer
from the AD data provider.
So, is there a bug in sssd wherein it is failing to continue multi-domain searches by ID
when an ID is out of range for local? Or is there something I'm doing wrong in the
sssd config? I'm happy to do further debugging. What logs (and level) might be
useful?
Our needs are fairly simple. ID's below 200000 are local, everything else is divided
into large slices for AD domain(s), and we are joined to one large AD domain.
Thanks for any insight!