On Пан, 12 лют 2024, Heidi Hough via FreeIPA-users wrote:
I appreciate the feedback. I added the ldap_search_timeout to both
the server and client sssd.conf files. I experimented with different values with no
additional success. Please find sanitized client and server sssd logs from my login
attempt with ldap_search_timeout = 30.
Client
https://privatebin.net/?8b3b376c2cf445ac#DwWqNUD96mcHqBYoNi7u97n9ZZ6ZNYeV...
Server
https://privatebin.net/?f8a35b7c92fae546#DT3sHCD9kY7h3UZrRSBX8VbBkmccRCVk...
Hi,
it looks like you have restarted the server during the time when a
client request was issued. As a result, not only the server logs contain
no request information, it was not really served and thus failed:
from client side:
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x1][BE_REQ_USER][name=ad-heidi(a)ad.contoso.com]
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [dp_attach_req] (0x0400): [RID#2]
DP Request [Account #2]: REQ_TRACE: New request. Flags [0x0001].
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [dp_attach_req] (0x0400): [RID#2]
Number of active DP request: 1
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sss_domain_get_state] (0x1000):
[RID#2] Domain
ipa.subdomain.contoso.com is Active
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sss_domain_get_state] (0x1000):
[RID#2] Domain
ad.contoso.com is Active
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sss_domain_get_state] (0x1000):
[RID#2] Domain
ipa.subdomain.contoso.com is Active
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sss_domain_get_state] (0x1000):
[RID#2] Domain
ad.contoso.com is Active
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_print_server] (0x2000):
[RID#2] Searching 172.16.50.102:389
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_get_generic_ext_step]
(0x0400): [RID#2] calling ldap_search_ext with
[(&(objectClass=ipaUserOverride)(uid=ad-heidi))][cn=Default Trust
View,cn=views,cn=accounts,dc=ipa,dc
=subdomain,dc=contoso,dc=com].
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_get_generic_ext_step]
(0x2000): [RID#2] ldap_search_ext called, msgid = 14
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_op_add] (0x2000): [RID#2] New
operation 14 timeout 30
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_process_result] (0x2000):
Trace: sh[0x55c25d103380], connected[1], ops[0x55c25d17e390], ldap[0x55c25d1006b0]
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_get_generic_op_finished]
(0x0400): [RID#2] Search result: Success(0), no errmsg set
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_op_destructor] (0x2000):
[RID#2] Operation 14 finished
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sss_domain_get_state] (0x1000):
[RID#2] Domain
ipa.subdomain.contoso.com is Active
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sss_domain_get_state] (0x1000):
[RID#2] Domain
ad.contoso.com is Active
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [ipa_s2n_get_acct_info_send]
(0x0400): [RID#2] Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user [ad-heidi]
to IPA server
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [ipa_s2n_exop_send] (0x0400):
[RID#2] Executing extended operation
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [ipa_s2n_exop_send] (0x2000):
[RID#2] ldap_extended_operation sent, msgid = 15
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_op_add] (0x2000): [RID#2] New
operation 15 timeout 30
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_process_result] (0x2000):
Trace: sh[0x55c25d103380], connected[1], ops[0x55c25d17e390], ldap[0x55c25d1006b0]
(2024-02-12 8:48:40): [be[ipa.subdomain.contoso.com]] [sdap_process_result] (0x2000):
Trace: end of ldap_result list
(2024-02-12 8:49:03): [be[ipa.subdomain.contoso.com]] [sdap_process_result] (0x2000):
Trace: sh[0x55c25d103380], connected[1], ops[0x55c25d17e390], ldap[0x55c25d1006b0]
(2024-02-12 8:49:03): [be[ipa.subdomain.contoso.com]] [ipa_s2n_exop_done] (0x0040):
[RID#2] ldap_extended_operation result: Time limit exceeded(3), (null).
The request is sent at 8:48:40. Assuming the time is the same, the
server side did not start at that point yet:
(2024-02-12 8:48:24): [be[ipa.subdomain.consoto.com]] [be_ptask_execute] (0x0400): Task
[Cleanup [id] of
ad.contoso.com]: executing task, timeout 30 seconds
(2024-02-12 8:48:24): [be[ipa.subdomain.consoto.com]] [sysdb_cache_search_users]
(0x2000): Search users with filter:
(&(objectCategory=user)(&(!(dataExpireTimestamp=0))(dataExpireTimestamp<=1707756504)(!(lastLogin=*))))
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [server_setup] (0x3f7c0): Starting
with debug level = 0x3ff0
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [server_setup] (0x0400): CONFDB:
/var/lib/sss/db/config.ldb
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [dp_get_options] (0x0400): Option
lookup_family_order has value ipv4_first
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [dp_get_options] (0x0400): Option
dns_resolver_timeout has value 6
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [dp_get_options] (0x0400): Option
dns_resolver_op_timeout has value 3
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [dp_get_options] (0x0400): Option
dns_resolver_server_timeout has value 1000
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [dp_get_options] (0x0400): Option
dns_resolver_use_search_list is TRUE
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [dp_get_options] (0x0400): Option
dns_discovery_domain has no value
(2024-02-12 8:48:44): [be[ipa.subdomain.consoto.com]] [be_res_get_opts] (0x0100): Lookup
order: ipv4_first
So I suspect the request got simply lost.
SSSD on the client sends LDAP search with a specific control to LDAP
server. This request is taken care of by a plugin in LDAP server code
which issues a local request to SSSD using its API. It should be visible
in the sss_nss.log but there is no such activity at 8:48:40:
(2024-02-12 8:48:13): [nss] [server_setup] (0x3f7c0): Starting with debug level = 0x0070
(2024-02-12 8:48:44): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): CR #2: Could
not get account info [1432158213]: Terminated
(2024-02-12 8:48:45): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#1] CR #4:
Could not get account info [1432158212]: SSSD is offline
(2024-02-12 8:48:45): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): [CID#1] CR #5:
Could not get account info [1432158212]: SSSD is offline
(2024-02-12 8:49:15): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): CR #11: Could
not get account info [1432158213]: Terminated
(2024-02-12 8:49:22): [nss] [cache_req_common_process_dp_reply] (0x3f7c0): CR #13: Could
not get account info [1432158213]: Terminated
(2024-02-12 8:49:47): [nss] [sbus_dbus_connect_address] (0x0020): Unable to register to
unix:path=/var/lib/sss/pipes/private/sbus-dp_ipa.subdomain.contoso.com
[org.freedesktop.DBus.Error.NoReply]: Did not receive a reply. Possible
causes include: the remote application did not send a reply, the message bus security
policy blocked the reply, the reply timeout expired, or the network connection was
broken.
If you are restarting sssd on the server, I'd suggest to wait a bit
until it settles down with its configuration first. Then you can issue a
client request and collect logs.
Thanks
Heidi
--
_______________________________________________
FreeIPA-users mailing list -- freeipa-users(a)lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave(a)lists.fedorahosted.org
Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines:
https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives:
https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedoraho...
Do not reply to spam, report it:
https://pagure.io/fedora-infrastructure/new_issue
--
/ Alexander Bokovoy
Sr. Principal Software Engineer
Security / Identity Management Engineering
Red Hat Limited, Finland