Alexey,
Of course. Added below.

-- lawrence

-----

[root@acad-cnode006 ~]# sssctl logs-remove

Truncating log files...

-----

[root@acad-cnode006 ~]# sssctl debug-level

sssd                      0x0070
nss                       0x0070
pam                       0x0070
domain/adldap1.augusta.edu 0x0070

[root@acad-cnode006 ~]# sssctl debug-level 9

[root@acad-cnode006 ~]# sssctl debug-level

sssd                      0x2f7f0
nss                       0x2f7f0
pam                       0x2f7f0
domain/adldap1.augusta.edu 0x2f7f0

-----

[root@acad-cnode006 ~]# ll /home/lck

total 12
drwxr-xr-x 3 28244723 28433522 4096 Jan 28 14:19 Documents
drwxr-xr-x 8 28244723 28433522 4096 Feb  6 12:25 apps
drwxr-xr-x 4 28244723 28433522 4096 Feb 12 15:36 scripts

-----

[root@acad-cnode006 ~]# cat /var/log/sssd/sssd_nss.log

(2025-02-15 19:29:55): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-15 19:29:55): [nss] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
(2025-02-15 19:29:55): [nss] [sbus_name_owner_changed] (0x4000): Name of owner :1.8 has changed from [] to [:1.8]
(2025-02-15 19:29:55): [nss] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
(2025-02-15 19:29:55): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-15 19:29:55): [nss] [sbus_method_handler] (0x2000): Received D-Bus method org.freedesktop.DBus.Properties.Get on /sssd
(2025-02-15 19:29:55): [nss] [sbus_senders_lookup] (0x2000): Looking for identity of sender [:1.8]
(2025-02-15 19:29:55): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-15 19:29:55): [nss] [sbus_senders_lookup] (0x2000): Looking for identity of sender [:1.8]
(2025-02-15 19:29:55): [nss] [sbus_senders_add] (0x2000): Inserting identity of sender [:1.8]: 0
(2025-02-15 19:29:55): [nss] [sbus_properties_get_send] (0x4000): Requesting property: sssd.service.debug_level of /sssd
(2025-02-15 19:29:55): [nss] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.Properties.Get: Success
(2025-02-15 19:29:55): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-15 19:29:55): [nss] [sbus_signal_handler] (0x2000): Received D-Bus signal org.freedesktop.DBus.NameOwnerChanged on /org/freedesktop/DBus
(2025-02-15 19:29:55): [nss] [sbus_name_owner_changed] (0x4000): Name of owner :1.8 has changed from [:1.8] to []
(2025-02-15 19:29:55): [nss] [sbus_senders_delete] (0x2000): Removing identity of sender [:1.8]
(2025-02-15 19:29:55): [nss] [sbus_issue_request_done] (0x0400): org.freedesktop.DBus.NameOwnerChanged: Success
(2025-02-15 19:30:29): [nss] [get_client_cred] (0x4000): Client [0x55cf53509b00][22] creds: euid[0] egid[0] pid[84709] cmd_line['ls'].
(2025-02-15 19:30:29): [nss] [setup_client_idle_timer] (0x4000): Idle timer re-set for client [0x55cf53509b00][22]
(2025-02-15 19:30:29): [nss] [accept_fd_handler] (0x0400): [CID#451] Client [cmd ls][uid 0][0x55cf53509b00][22] connected!
(2025-02-15 19:30:29): [nss] [sss_cmd_get_version] (0x0200): [CID#451] Received client version [1].
(2025-02-15 19:30:29): [nss] [sss_cmd_get_version] (0x0200): [CID#451] Offered version [1].
(2025-02-15 19:30:29): [nss] [sss_nss_getby_id] (0x0400): [CID#451] Input ID: 28244723 (looking up 'POSIX data')
(2025-02-15 19:30:29): [nss] [cache_req_set_plugin] (0x2000): [CID#451] CR #969: Setting "User by ID" plugin
(2025-02-15 19:30:29): [nss] [cache_req_send] (0x0400): [CID#451] CR #969: REQ_TRACE: New request [CID #451] 'User by ID'
(2025-02-15 19:30:29): [nss] [cache_req_select_domains] (0x0400): [CID#451] CR #969: Performing a multi-domain search
(2025-02-15 19:30:29): [nss] [cache_req_search_domains] (0x0400): [CID#451] CR #969: Search will check the cache and check the data provider
(2025-02-15 19:30:29): [nss] [cache_req_validate_domain_type] (0x2000): [CID#451] Request type POSIX-only for domain adldap1.augusta.edu type POSIX is valid
(2025-02-15 19:30:29): [nss] [cache_req_set_domain] (0x0400): [CID#451] CR #969: Using domain [adldap1.augusta.edu]
(2025-02-15 19:30:29): [nss] [cache_req_search_send] (0x0400): [CID#451] CR #969: Looking up UID:28244723@adldap1.augusta.edu
(2025-02-15 19:30:29): [nss] [cache_req_search_ncache] (0x0400): [CID#451] CR #969: Checking negative cache for [UID:28244723@adldap1.augusta.edu]
(2025-02-15 19:30:29): [nss] [sss_ncache_check_str] (0x2000): [CID#451] Checking negative cache for [NCE/UID/adldap1.augusta.edu/28244723]
(2025-02-15 19:30:29): [nss] [sss_ncache_check_str] (0x2000): [CID#451] Checking negative cache for [NCE/UID/28244723]
(2025-02-15 19:30:29): [nss] [cache_req_search_ncache] (0x0400): [CID#451] CR #969: [UID:28244723@adldap1.augusta.edu] is not present in negative cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #969: Looking up [UID:28244723@adldap1.augusta.edu] in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #969: Object [UID:28244723@adldap1.augusta.edu] was not found in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_dp] (0x0400): [CID#451] CR #969: Looking up [UID:28244723@adldap1.augusta.edu] in data provider
(2025-02-15 19:30:29): [nss] [sss_dp_get_account_send] (0x0400): [CID#451] Creating request for [adldap1.augusta.edu][0x1][BE_REQ_USER][idnumber=28244723:-]
(2025-02-15 19:30:29): [nss] [sss_nss_get_object_send] (0x0400): [CID#451] Client [0x55cf53509b00][22]: sent cache request #969
(2025-02-15 19:30:29): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-15 19:30:29): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#451] CR #969: Data Provider Error: 3, 0, Success
(2025-02-15 19:30:29): [nss] [cache_req_common_process_dp_reply] (0x0400): [CID#451] CR #969: Due to an error we will return cached data
(2025-02-15 19:30:29): [nss] [sss_domain_get_state] (0x1000): [CID#451] Domain adldap1.augusta.edu is Active
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #969: Looking up [UID:28244723@adldap1.augusta.edu] in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #969: Object [UID:28244723@adldap1.augusta.edu] was not found in cache
(2025-02-15 19:30:29): [nss] [cache_req_process_result] (0x0400): [CID#451] CR #969: Finished: Not found
(2025-02-15 19:30:29): [nss] [sss_nss_protocol_done] (0x4000): [CID#451] Sending reply: not found
(2025-02-15 19:30:29): [nss] [sss_nss_getby_id] (0x0400): [CID#451] Input ID: 28433522 (looking up 'POSIX data')
(2025-02-15 19:30:29): [nss] [cache_req_set_plugin] (0x2000): [CID#451] CR #970: Setting "Group by ID" plugin
(2025-02-15 19:30:29): [nss] [cache_req_send] (0x0400): [CID#451] CR #970: REQ_TRACE: New request [CID #451] 'Group by ID'
(2025-02-15 19:30:29): [nss] [cache_req_select_domains] (0x0400): [CID#451] CR #970: Performing a multi-domain search
(2025-02-15 19:30:29): [nss] [cache_req_search_domains] (0x0400): [CID#451] CR #970: Search will check the cache and check the data provider
(2025-02-15 19:30:29): [nss] [cache_req_validate_domain_type] (0x2000): [CID#451] Request type POSIX-only for domain adldap1.augusta.edu type POSIX is valid
(2025-02-15 19:30:29): [nss] [cache_req_set_domain] (0x0400): [CID#451] CR #970: Using domain [adldap1.augusta.edu]
(2025-02-15 19:30:29): [nss] [cache_req_search_send] (0x0400): [CID#451] CR #970: Looking up GID:28433522@adldap1.augusta.edu
(2025-02-15 19:30:29): [nss] [cache_req_search_ncache] (0x0400): [CID#451] CR #970: Checking negative cache for [GID:28433522@adldap1.augusta.edu]
(2025-02-15 19:30:29): [nss] [sss_ncache_check_str] (0x2000): [CID#451] Checking negative cache for [NCE/GID/adldap1.augusta.edu/28433522]
(2025-02-15 19:30:29): [nss] [sss_ncache_check_str] (0x2000): [CID#451] Checking negative cache for [NCE/GID/28433522]
(2025-02-15 19:30:29): [nss] [cache_req_search_ncache] (0x0400): [CID#451] CR #970: [GID:28433522@adldap1.augusta.edu] is not present in negative cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #970: Looking up [GID:28433522@adldap1.augusta.edu] in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #970: Object [GID:28433522@adldap1.augusta.edu] was not found in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_dp] (0x0400): [CID#451] CR #970: Looking up [GID:28433522@adldap1.augusta.edu] in data provider
(2025-02-15 19:30:29): [nss] [sss_dp_get_account_send] (0x0400): [CID#451] Creating request for [adldap1.augusta.edu][0x2][BE_REQ_GROUP][idnumber=28433522:-]
(2025-02-15 19:30:29): [nss] [sss_nss_get_object_send] (0x0400): [CID#451] Client [0x55cf53509b00][22]: sent cache request #970
(2025-02-15 19:30:29): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-15 19:30:29): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#451] CR #970: Data Provider Error: 3, 0, Success
(2025-02-15 19:30:29): [nss] [cache_req_common_process_dp_reply] (0x0400): [CID#451] CR #970: Due to an error we will return cached data
(2025-02-15 19:30:29): [nss] [sss_domain_get_state] (0x1000): [CID#451] Domain adldap1.augusta.edu is Active
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #970: Looking up [GID:28433522@adldap1.augusta.edu] in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #970: Object [GID:28433522@adldap1.augusta.edu] was not found in cache
(2025-02-15 19:30:29): [nss] [cache_req_process_result] (0x0400): [CID#451] CR #970: Finished: Not found
(2025-02-15 19:30:29): [nss] [sss_nss_protocol_done] (0x4000): [CID#451] Sending reply: not found
(2025-02-15 19:30:29): [nss] [sss_nss_getby_id] (0x0400): [CID#451] Input ID: 28433522 (looking up 'POSIX data')
(2025-02-15 19:30:29): [nss] [cache_req_set_plugin] (0x2000): [CID#451] CR #971: Setting "Group by ID" plugin
(2025-02-15 19:30:29): [nss] [cache_req_send] (0x0400): [CID#451] CR #971: REQ_TRACE: New request [CID #451] 'Group by ID'
(2025-02-15 19:30:29): [nss] [cache_req_select_domains] (0x0400): [CID#451] CR #971: Performing a multi-domain search
(2025-02-15 19:30:29): [nss] [cache_req_search_domains] (0x0400): [CID#451] CR #971: Search will check the cache and check the data provider
(2025-02-15 19:30:29): [nss] [cache_req_validate_domain_type] (0x2000): [CID#451] Request type POSIX-only for domain adldap1.augusta.edu type POSIX is valid
(2025-02-15 19:30:29): [nss] [cache_req_set_domain] (0x0400): [CID#451] CR #971: Using domain [adldap1.augusta.edu]
(2025-02-15 19:30:29): [nss] [cache_req_search_send] (0x0400): [CID#451] CR #971: Looking up GID:28433522@adldap1.augusta.edu
(2025-02-15 19:30:29): [nss] [cache_req_search_ncache] (0x0400): [CID#451] CR #971: Checking negative cache for [GID:28433522@adldap1.augusta.edu]
(2025-02-15 19:30:29): [nss] [sss_ncache_check_str] (0x2000): [CID#451] Checking negative cache for [NCE/GID/adldap1.augusta.edu/28433522]
(2025-02-15 19:30:29): [nss] [sss_ncache_check_str] (0x2000): [CID#451] Checking negative cache for [NCE/GID/28433522]
(2025-02-15 19:30:29): [nss] [cache_req_search_ncache] (0x0400): [CID#451] CR #971: [GID:28433522@adldap1.augusta.edu] is not present in negative cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #971: Looking up [GID:28433522@adldap1.augusta.edu] in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #971: Object [GID:28433522@adldap1.augusta.edu] was not found in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_dp] (0x0400): [CID#451] CR #971: Looking up [GID:28433522@adldap1.augusta.edu] in data provider
(2025-02-15 19:30:29): [nss] [sss_dp_get_account_send] (0x0400): [CID#451] Creating request for [adldap1.augusta.edu][0x2][BE_REQ_GROUP][idnumber=28433522:-]
(2025-02-15 19:30:29): [nss] [sss_nss_get_object_send] (0x0400): [CID#451] Client [0x55cf53509b00][22]: sent cache request #971
(2025-02-15 19:30:29): [nss] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-15 19:30:29): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#451] CR #971: Data Provider Error: 3, 0, Success
(2025-02-15 19:30:29): [nss] [cache_req_common_process_dp_reply] (0x0400): [CID#451] CR #971: Due to an error we will return cached data
(2025-02-15 19:30:29): [nss] [sss_domain_get_state] (0x1000): [CID#451] Domain adldap1.augusta.edu is Active
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #971: Looking up [GID:28433522@adldap1.augusta.edu] in cache
(2025-02-15 19:30:29): [nss] [cache_req_search_cache] (0x0400): [CID#451] CR #971: Object [GID:28433522@adldap1.augusta.edu] was not found in cache
(2025-02-15 19:30:29): [nss] [cache_req_process_result] (0x0400): [CID#451] CR #971: Finished: Not found
(2025-02-15 19:30:29): [nss] [sss_nss_protocol_done] (0x4000): [CID#451] Sending reply: not found
(2025-02-15 19:30:29): [nss] [client_recv] (0x0200): [CID#451] Client disconnected!
(2025-02-15 19:30:29): [nss] [client_close_fn] (0x2000): [CID#451] Terminated client [0x55cf53509b00][22]

----------

From Alexey:

Huh... apparently I parsed strace wrongly because sssd_nss.log says a correct UID is being looked up:
```
(2025-02-15 19:30:29): [nss] [cache_req_search_send] (0x0400): [CID#451] CR #969: Looking up UID:28244723@adldap1.augusta.edu
(2025-02-15 19:30:29): [nss] [sss_dp_get_account_send] (0x0400): [CID#451] Creating request for [adldap1.augusta.edu][0x1][BE_REQ_USER][idnumber=28244723:-]
(2025-02-15 19:30:29): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#451] CR #969: Data Provider Error: 3, 0, Success
```
Well, that's good, no mystery on the sss_client library side.
Then the next thing we need to check 'sssd_$domain.log' with debug_level=9 that covers processing of this request, that results in "Data Provider Error"

----------



Alexey,

Thank you again, included below:

[root@acad-cnode006 ~]# sssctl debug-level 9

[root@acad-cnode006 ~]# sssctl debug-level

sssd                      0x2f7f0
nss                       0x2f7f0
pam                       0x2f7f0
domain/adldap1.augusta.edu 0x2f7f0

[root@acad-cnode006 ~]# sssctl logs-remove

Truncating log files...

[root@acad-cnode006 ~]# ll /home/lck

-----

total 12
drwxr-xr-x 3 28244723 28433522 4096 Jan 28 14:19 Documents
drwxr-xr-x 8 28244723 28433522 4096 Feb  6 12:25 apps
drwxr-xr-x 4 28244723 28433522 4096 Feb 12 15:36 scripts

-----

[root@acad-cnode006 ~]# cat /var/log/sssd/sssd_adldap1.augusta.edu.log

(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x4000): inotify name: chrony.conf
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x0400): Not interested in chrony.conf
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x4000): inotify name: group
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x0400): Not interested in group
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x4000): inotify name: hosts
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x0400): Not interested in hosts
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [snotify_internal_cb] (0x2000): All inotify events processed
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x4000): inotify name: passwd
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x0400): Not interested in passwd
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_file_event] (0x0400): received notification for watched file /etc/resolv.conf
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [create_dispatcher] (0x0400): Running a timer with delay 1.0
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [dispatch_event] (0x0400): Dispatched an event with combined flags 0x400
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_file_event] (0x0400): Will reopen moved or deleted file /etc/resolv.conf
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x4000): inotify name: resolv.conf
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x0400): received notification for watched file [resolv.conf] under /etc
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [get_dispatcher] (0x2000): Reusing existing dispatcher
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [dispatch_event] (0x0400): Dispatched an event with combined flags 0x500
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x4000): inotify name: shadow
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [process_dir_event] (0x0400): Not interested in shadow
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [snotify_internal_cb] (0x2000): All inotify events processed
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [watch_ctx_destructor] (0x2000): Closing inotify fd 20
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [snotify_watch] (0x2000): Opened inotify fd 20
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [snotify_watch] (0x2000): Opened file watch 1
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [snotify_watch] (0x2000): Opened directory watch 2
(2025-02-17 13:32:14): [be[adldap1.augusta.edu]] [snotify_rewatch] (0x0400): Recreated watch
(2025-02-17 13:32:15): [be[adldap1.augusta.edu]] [watched_file_inotify_cb] (0x1000): Received inotify notification for /etc/resolv.conf
(2025-02-17 13:32:15): [be[adldap1.augusta.edu]] [watch_update_resolv] (0x0400): Reloading /etc/resolv.conf.
(2025-02-17 13:32:15): [be[adldap1.augusta.edu]] [recreate_ares_channel] (0x0100): Initializing new c-ares channel
(2025-02-17 13:32:15): [be[adldap1.augusta.edu]] [recreate_ares_channel] (0x0100): Destroying the old c-ares channel
(2025-02-17 13:32:15): [be[adldap1.augusta.edu]] [check_if_online] (0x2000): Schedule check_if_online_delayed in 1s.
(2025-02-17 13:32:16): [be[adldap1.augusta.edu]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
(2025-02-17 13:32:16): [be[adldap1.augusta.edu]] [check_if_online_delayed] (0x2000): Backend is already online, nothing to do.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_get_account_info_send] (0x0200): Got request for [0x1][BE_REQ_USER][idnumber=28244723]
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_attach_req] (0x0400): [RID#79] DP Request [Account #79]: REQ_TRACE: New request. [sssd.nss CID #496] Flags [0x0001].
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_attach_req] (0x0400): [RID#79] Number of active DP request: 1
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sss_domain_get_state] (0x1000): [RID#79] Domain adldap1.augusta.edu is Active
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [users_get_send] (0x0080): [RID#79] [28244723] did not match any configured ID mapping domain
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sysdb_search_user_by_uid] (0x0400): [RID#79] No such entry
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sysdb_delete_user] (0x0400): [RID#79] Error: 2 (No such file or directory)
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_done] (0x0400): [RID#79] DP Request [Account #79]: Request handler finished [0]: Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_done] (0x20000): [RID#79] DP Request [Account #79]: Handling request took [0.142] milliseconds.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [_dp_req_recv] (0x0400): [RID#79] DP Request [Account #79]: Receiving request data.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_destructor] (0x0400): [RID#79] DP Request [Account #79]: Request removed.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_destructor] (0x0400): [RID#79] Number of active DP request: 0
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_reply_std] (0x1000): [RID#79] DP Request [Account #79]: Returning [Internal Error]: 3,0,Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_get_account_info_send] (0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=28433522]
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_attach_req] (0x0400): [RID#80] DP Request [Account #80]: REQ_TRACE: New request. [sssd.nss CID #496] Flags [0x0001].
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_attach_req] (0x0400): [RID#80] Number of active DP request: 1
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sss_domain_get_state] (0x1000): [RID#80] Domain adldap1.augusta.edu is Active
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [groups_get_send] (0x0080): [RID#80] [28433522] did not match any configured ID mapping domain
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sysdb_search_group_by_id] (0x0400): [RID#80] No such entry
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sysdb_delete_group] (0x0400): [RID#80] Error: 2 (No such file or directory)
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_done] (0x0400): [RID#80] DP Request [Account #80]: Request handler finished [0]: Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_done] (0x20000): [RID#80] DP Request [Account #80]: Handling request took [0.142] milliseconds.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [_dp_req_recv] (0x0400): [RID#80] DP Request [Account #80]: Receiving request data.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_destructor] (0x0400): [RID#80] DP Request [Account #80]: Request removed.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_destructor] (0x0400): [RID#80] Number of active DP request: 0
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_reply_std] (0x1000): [RID#80] DP Request [Account #80]: Returning [Internal Error]: 3,0,Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_get_account_info_send] (0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=28433522]
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_attach_req] (0x0400): [RID#81] DP Request [Account #81]: REQ_TRACE: New request. [sssd.nss CID #496] Flags [0x0001].
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_attach_req] (0x0400): [RID#81] Number of active DP request: 1
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sss_domain_get_state] (0x1000): [RID#81] Domain adldap1.augusta.edu is Active
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [groups_get_send] (0x0080): [RID#81] [28433522] did not match any configured ID mapping domain
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sysdb_search_group_by_id] (0x0400): [RID#81] No such entry
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sysdb_delete_group] (0x0400): [RID#81] Error: 2 (No such file or directory)
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_done] (0x0400): [RID#81] DP Request [Account #81]: Request handler finished [0]: Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_done] (0x20000): [RID#81] DP Request [Account #81]: Handling request took [0.158] milliseconds.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [_dp_req_recv] (0x0400): [RID#81] DP Request [Account #81]: Receiving request data.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_destructor] (0x0400): [RID#81] DP Request [Account #81]: Request removed.
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_destructor] (0x0400): [RID#81] Number of active DP request: 0
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [dp_req_reply_std] (0x1000): [RID#81] DP Request [Account #81]: Returning [Internal Error]: 3,0,Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
(2025-02-17 13:32:22): [be[adldap1.augusta.edu]] [sbus_dispatch] (0x4000): Dispatching.sssd                      0x2f7f0


---------

From Alexey:

Ok, we are getting closer to the root cause:
```
(13:32:22): [dp_get_account_info_send] (0x0200): Got request for [0x1][BE_REQ_USER][idnumber=28244723]
(13:32:22): [sss_domain_get_state] (0x1000): [RID#79] Domain adldap1.augusta.edu is Active
(13:32:22): [users_get_send] (0x0080): [RID#79] [28244723] did not match any configured ID mapping domain
```

What are:
1) actual backend - AD?
2) id_provider user in sssd.conf?
3) value of 'ldap_id_mapping' sssd.conf::domain option?


----------


Alexey,
Good morning! sanitized conf file included below:

- Yes, back end is native AD
- Included sanitized conf file details other settings (group names, certs, dn's, modified, password omitted)

-----

[sssd]
config_file_version = 2
services = nss,pam
domains = adldap1.example.edu

[nss]
filter_users = root
filter_groups = root

[pam]

[domain/adldap1.example.edu]
id_provider = ldap

enumerate = False
cache_credentials = True
case_sensitive = false

ignore_group_members = True

ldap_schema = ad
ldap_uri = ldaps://root.example.edu
ldap_backup_uri = ldaps://root2.example.edu

ldap_user_search_base = dc=example,dc=edu
ldap_referrals = False

ldap_tls_cacert = /etc/openldap/certs/root.crt
ldap_tls_reqcert = never

ldap_use_tokengroups = True
ldap_id_mapping = True
ldap_idmap_range_size = 2000000

override_homedir = /home/%u
default_shell = /bin/bash
override_gid = 28433520

ldap_access_order = filter,expire
ldap_account_expire_policy = ad
ldap_access_filter = (|(memberOf=cn=prod_admins_group,ou=hpc,dc=example,dc=edu)(memberOf=cn=prod_users_group,ou=hpc,dc=example,dc=edu))

ldap_default_bind_dn = CN="Service, LDAP_Auth",OU=ServiceAccounts,DC=example,DC=edu
ldap_default_authtok_type = password


----------

Alexey,
Thank you for the effort thus far and the feedback, but I'd like to offer a few points.

- As referenced, these systems are ephemeral, so joining them to AD to use the AD provider isn't sustainable.
- We have other systems configured exactly the same way, across many different versions of the daemon and RHEL OS's, and have never seen this issue.
- Correct, as soon as I do a lookup by name, any valid name, everything resolves as expected.

Being able to use the LDAP ID provider and the AD schema, provided by an SSSD configuration directive, suggests we're not doing anything radical.

What is different is these OS instances are Rocky 9.5 Linux containers deployed as stateless systems.

So, given that my question becomes what is different? Is there something the daemon is missing in a stateless configuration? I know that's pretty open ended, I've done this quite a bit, but I don't have the developer insight or experience of where else to look next.

I'll test with the recommendations given and perhaps the results may provide additional breadcrumbs.


Stay tuned and thank you,


-- Lawrence



----------


Alexey,

I tried using both the `ldap_idmap_default_domain_sid` and `ldap_idmap_default_domain` directives, but the same result.


-- lawrence

On Mon, Feb 17, 2025 at 12:39 PM Alexey Tikhonov <atikhono@redhat.com> wrote:
Hi.

The reason is that 'id_provider = ldap' is used against AD.

Normally 'subdomain_provider' reads required data and sets up id-mapping at startup, but ldap provider doesn't have 'subdomain_provider', so when first lookup is by-id it can't convert id to SID:
```
[users_get_send] (0x0080): [RID#79] [28244723] did not match any configured ID mapping domain
```
and can't handle a request.

You wrote: "until I manually run a "getent" or "id" on any user or group" - I guess those lookups are by-name?
I guess this triggers a connection to AD, rootDSE is read and id-mapping is set up.

You can try to set `ldap_idmap_default_domain_sid` and `ldap_idmap_default_domain` to the SID and name of your domain. Hopefully this will create a static mapping at startup.

But in general it's recommended to use 'id_provider = ad' against AD.