Am Fri, Feb 17, 2023 at 08:51:03AM +0100 schrieb Ronald Wimmer:
On 16.02.23 12:18, Sumit Bose wrote:
> Am Thu, Feb 16, 2023 at 12:14:02PM +0100 schrieb Ronald Wimmer via FreeIPA-users:
> > We do face the problem that we disabled a domain we do not need and that
> > this particular domain fills up sssd logs on the client side. Especially
> > sssd_nss.log. How could we possibly avoid this behavior?
>
> Hi,
>
> are you using the default debug level or did you set debug_level
> explicitly in sssd.conf?
>
> Can you give some examples of the debug message?
I raised the debug level. sssd_nss.log fills up with
(2023-02-17 8:44:52): [nss] [sss_dp_get_account_msg] (0x0400): Creating
request for [tk.MYDOMAIN.at][0x1][BE_REQ_USER][idnumber=1000:-]
(2023-02-17 8:44:52): [nss] [sbus_add_timeout] (0x2000): 0x5610c6661c90
(2023-02-17 8:44:52): [nss] [sss_dp_internal_get_send] (0x0400): Entering
request [0x5610c5282a80:1:1000@tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sbus_remove_timeout] (0x2000): 0x5610c6661c90
(2023-02-17 8:44:52): [nss] [sbus_dispatch] (0x4000): dbus conn:
0x5610c6660820
(2023-02-17 8:44:52): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2023-02-17 8:44:52): [nss] [sss_dp_get_reply] (0x0010): The Data Provider
returned an error [org.freedesktop.sssd.Error.DataProvider.Fatal]
(2023-02-17 8:44:52): [nss] [cache_req_common_dp_recv] (0x0040): CR #18:
Data Provider Error: 3, 5, Failed to get reply from Data Provider
(2023-02-17 8:44:52): [nss] [cache_req_common_dp_recv] (0x0400): CR #18:
Due to an error we will return cached data
(2023-02-17 8:44:52): [nss] [cache_req_search_cache] (0x0400): CR #18:
Looking up [UID:1000@tk.MYDOMAIN.at] in cache
(2023-02-17 8:44:52): [nss] [cache_req_search_cache] (0x0400): CR #18:
Object [UID:1000@tk.MYDOMAIN.at] was not found in cache
(2023-02-17 8:44:52): [nss] [cache_req_process_result] (0x0400): CR #18:
Finished: Not found
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
buero.MYDOMAIN.at is Active
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
MYDOMAIN.at is Active
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
org.MYDOMAIN.at is Active
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
tk.MYDOMAIN.at is Disabled
(2023-02-17 8:44:52): [nss] [nss_protocol_done] (0x4000): Sending reply:
not found
(2023-02-17 8:44:52): [nss] [sss_dp_req_destructor] (0x0400): Deleting
request: [0x5610c5282a80:1:1000@tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [nss_getby_id] (0x0400): Input ID: 1000
(2023-02-17 8:44:52): [nss] [cache_req_set_plugin] (0x2000): CR #19:
Setting "User by ID" plugin
(2023-02-17 8:44:52): [nss] [cache_req_send] (0x0400): CR #19: New request
'User by ID'
(2023-02-17 8:44:52): [nss] [cache_req_select_domains] (0x0400): CR #19:
Performing a multi-domain search
(2023-02-17 8:44:52): [nss] [cache_req_search_domains] (0x0400): CR #19:
Search will check the cache and check the data provider
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain org.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #19: Using
domain [org.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #19:
Looking up UID:1000@org.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
Checking negative cache for [UID:1000@org.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/org.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
[UID:1000@org.MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain linux.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #19: Using
domain [linux.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #19:
Looking up UID:1000@linux.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
Checking negative cache for [UID:1000@linux.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/linux.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
[UID:1000@linux.MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain buero.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #19: Using
domain [buero.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #19:
Looking up UID:1000@buero.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
Checking negative cache for [UID:1000@buero.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/buero.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
[UID:1000@buero.MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #19: Using
domain [MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #19:
Looking up UID:1000@MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
Checking negative cache for [UID:1000@MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
[UID:1000@MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain tk.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #19: Using
domain [tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #19:
Looking up UID:1000@tk.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
Checking negative cache for [UID:1000@tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/tk.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #19:
[UID:1000@tk.MYDOMAIN.at] is not present in negative cache
(2023-02-17 8:44:52): [nss] [cache_req_search_cache] (0x0400): CR #19:
Looking up [UID:1000@tk.MYDOMAIN.at] in cache
(2023-02-17 8:44:52): [nss] [cache_req_search_cache] (0x0400): CR #19:
Object [UID:1000@tk.MYDOMAIN.at] was not found in cache
(2023-02-17 8:44:52): [nss] [cache_req_search_dp] (0x0400): CR #19: Looking
up [UID:1000@tk.MYDOMAIN.at] in data provider
(2023-02-17 8:44:52): [nss] [sss_dp_issue_request] (0x0400): Issuing
request for [0x5610c5282a80:1:1000@tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_dp_get_account_msg] (0x0400): Creating
request for [tk.MYDOMAIN.at][0x1][BE_REQ_USER][idnumber=1000:-]
(2023-02-17 8:44:52): [nss] [sbus_add_timeout] (0x2000): 0x5610c6661c90
(2023-02-17 8:44:52): [nss] [sss_dp_internal_get_send] (0x0400): Entering
request [0x5610c5282a80:1:1000@tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sbus_remove_timeout] (0x2000): 0x5610c6661c90
(2023-02-17 8:44:52): [nss] [sbus_dispatch] (0x4000): dbus conn:
0x5610c6660820
(2023-02-17 8:44:52): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2023-02-17 8:44:52): [nss] [sss_dp_get_reply] (0x0010): The Data Provider
returned an error [org.freedesktop.sssd.Error.DataProvider.Fatal]
(2023-02-17 8:44:52): [nss] [cache_req_common_dp_recv] (0x0040): CR #19:
Data Provider Error: 3, 5, Failed to get reply from Data Provider
(2023-02-17 8:44:52): [nss] [cache_req_common_dp_recv] (0x0400): CR #19:
Due to an error we will return cached data
(2023-02-17 8:44:52): [nss] [cache_req_search_cache] (0x0400): CR #19:
Looking up [UID:1000@tk.MYDOMAIN.at] in cache
(2023-02-17 8:44:52): [nss] [cache_req_search_cache] (0x0400): CR #19:
Object [UID:1000@tk.MYDOMAIN.at] was not found in cache
(2023-02-17 8:44:52): [nss] [cache_req_process_result] (0x0400): CR #19:
Finished: Not found
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
buero.MYDOMAIN.at is Active
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
MYDOMAIN.at is Active
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
org.MYDOMAIN.at is Active
(2023-02-17 8:44:52): [nss] [sss_domain_get_state] (0x1000): Domain
tk.MYDOMAIN.at is Disabled
Hi,
thanks for the details.
Pavel, do you think it would make sense to skip disabled domains in
cache_req's multi-domain search? It looks like for single-domain search
they are already skipped via cache_req_domain_get_domain_by_name().
bye,
Sumit
(2023-02-17 8:44:52): [nss] [nss_protocol_done] (0x4000): Sending
reply:
not found
(2023-02-17 8:44:52): [nss] [sss_dp_req_destructor] (0x0400): Deleting
request: [0x5610c5282a80:1:1000@tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [nss_getby_id] (0x0400): Input ID: 1000
(2023-02-17 8:44:52): [nss] [cache_req_set_plugin] (0x2000): CR #20:
Setting "User by ID" plugin
(2023-02-17 8:44:52): [nss] [cache_req_send] (0x0400): CR #20: New request
'User by ID'
(2023-02-17 8:44:52): [nss] [cache_req_select_domains] (0x0400): CR #20:
Performing a multi-domain search
(2023-02-17 8:44:52): [nss] [cache_req_search_domains] (0x0400): CR #20:
Search will check the cache and check the data provider
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/DOM_LOCATE_TYPE/linux.MYDOMAIN.at/User by ID]
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain org.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #20: Using
domain [org.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #20:
Looking up UID:1000@org.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
Checking negative cache for [UID:1000@org.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/org.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
[UID:1000@org.MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain linux.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #20: Using
domain [linux.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #20:
Looking up UID:1000@linux.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
Checking negative cache for [UID:1000@linux.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/linux.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
[UID:1000@linux.MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain buero.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #20: Using
domain [buero.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #20:
Looking up UID:1000@buero.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
Checking negative cache for [UID:1000@buero.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/buero.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
[UID:1000@buero.MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #20: Using
domain [MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #20:
Looking up UID:1000@MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
Checking negative cache for [UID:1000@MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
[UID:1000@MYDOMAIN.at] does not exist (negative cache)
(2023-02-17 8:44:52): [nss] [cache_req_validate_domain_type] (0x2000):
Request type POSIX-only for domain tk.MYDOMAIN.at type POSIX is valid
(2023-02-17 8:44:52): [nss] [cache_req_set_domain] (0x0400): CR #20: Using
domain [tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [cache_req_search_send] (0x0400): CR #20:
Looking up UID:1000@tk.MYDOMAIN.at
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
Checking negative cache for [UID:1000@tk.MYDOMAIN.at]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/tk.MYDOMAIN.at/1000]
(2023-02-17 8:44:52): [nss] [sss_ncache_check_str] (0x2000): Checking
negative cache for [NCE/UID/1000]
(2023-02-17 8:44:52): [nss] [cache_req_search_ncache] (0x0400): CR #20:
[UID:1000@tk.MYDOMAIN.at] is not present in negative cache
As it is very hard for me to read the logfile with that debug_level I hope
this snippet is sufficient... Pls let me know if not.
Cheers,
Ronald