On Срд, 14 лют 2024, Heidi Hough via FreeIPA-users wrote:
I had restarted the sssd services on server and client after updating
the ldap_search_timeout value. I did let it run for much longer,
ensuring sssd services were all reported as online when issuing
systemctl status sssd on both server and client.
You will find logs for a failed login attempt to the freeipa client.
The login attempt took place at 13:26. I was quite bothered by the
face that the sssd_nss log on the server was not populated during this
attempt, but was populated during the prior attempt that I shared. Is
there a better way to identify if the sssd_nss service is
running/online?
It depends on what debug level you have used. I suspect you only put
debug_level statement in the [domain/...] section, right? If you want to
get more details from different SSSD components, you need to put
debug_level statements in the separate sections.
Or use 'sssctl debug-level .. ' which sets debug_level value to all
sections at runtime but it is only active until restart.
You mentioned:
"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."
Is there a way to troubleshoot this specific process?
389-ds accesslog will contain all LDAP connections. You may search there
for 'IPA trusted domain ID mapper' being mentioned. This is an example
from my test environment:
[14/Feb/2024:08:04:37.169019132 +0000] conn=81003 op=23 EXT
oid="2.16.840.1.113730.3.8.10.4.2" name="IPA trusted domain ID
mapper"
[14/Feb/2024:08:04:37.169182709 +0000] conn=81003 op=23 RESULT err=32 tag=120 nentries=0
wtime=0.001993588 optime=0.000164749 etime=0.002157265
In your case I see this on the client side:
(2024-02-13 13:26:55): [be[ipa.subdomain.contoso.com]] [ipa_s2n_get_acct_info_send]
(0x0400): [RID#150] Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user
[heidi-ad] to IPA server
(2024-02-13 13:26:55): [be[ipa.subdomain.contoso.com]] [ipa_s2n_exop_send] (0x0400):
[RID#150] Executing extended operation
(2024-02-13 13:26:55): [be[ipa.subdomain.contoso.com]] [ipa_s2n_exop_send] (0x2000):
[RID#150] ldap_extended_operation sent, msgid = 5
(2024-02-13 13:26:55): [be[ipa.subdomain.contoso.com]] [sdap_op_add] (0x2000): [RID#150]
New operation 5 timeout 10
(2024-02-13 13:27:05): [be[ipa.subdomain.contoso.com]] [sdap_op_timeout] (0x1000):
[RID#150] Issuing timeout [ldap_opt_timeout] for message id 5
(2024-02-13 13:27:05): [be[ipa.subdomain.contoso.com]] [sdap_call_op_callback] (0x3f7c0):
[RID#150] LDAP operation [5][server: [172.16.50.102:389] IPA EXOP] seems slow, took more
than 80% of timeout [10].
(2024-02-13 13:27:05): [be[ipa.subdomain.contoso.com]] [sdap_op_destructor] (0x1000):
[RID#150] Abandoning operation 5
(2024-02-13 13:27:05): [be[ipa.subdomain.contoso.com]] [ipa_s2n_get_user_done] (0x0040):
[RID#150] s2n exop request failed.
It is still failing as server side processing takes longer than the
client side timeout (10 seconds). However, server side logs don't have
any corresponding communication at about this time and SSSD domain logs
cut short at 13:27:01. The closest request for 'heidi-ad' account came
at 13:09:20:
$ grep 'Got request for' sssd_ipa.subdomain.contoso.com.log
(2024-02-13 13:09:20): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x1][BE_REQ_USER][name=heidi-ad(a)ad.contoso.com]
(2024-02-13 13:09:20): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=heidi-ad(a)ad.contoso.com]
(2024-02-13 13:09:21): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=603892026]
(2024-02-13 13:09:21): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=602655731]
(2024-02-13 13:09:21): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604961401]
(2024-02-13 13:09:22): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=602655735]
(2024-02-13 13:09:25): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604859746]
(2024-02-13 13:09:32): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604965529]
(2024-02-13 13:10:50): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=abc(a)ad.contoso.com]
(2024-02-13 13:10:50): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=abc(a)ipa.subdomain.contoso.com]
(2024-02-13 13:10:50): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=nobody(a)ad.contoso.com]
(2024-02-13 13:26:37): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=605125185]
(2024-02-13 13:26:37): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=601449600]
(2024-02-13 13:26:39): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604750598]
(2024-02-13 13:26:42): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=605323973]
(2024-02-13 13:26:45): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=605323972]
(2024-02-13 13:26:51): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604874522]
(2024-02-13 13:26:51): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604954881]
(2024-02-13 13:26:51): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604962564]
(2024-02-13 13:26:53): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=605156103]
(2024-02-13 13:26:54): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=605150943]
(2024-02-13 13:26:54): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604144821]
(2024-02-13 13:26:55): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=605251188]
(2024-02-13 13:26:56): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=605131034]
(2024-02-13 13:26:56): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=604758004]
(2024-02-13 13:27:01): [be[ipa.subdomain.contoso.com]] [dp_get_account_info_send]
(0x0200): Got request for [0x2][BE_REQ_GROUP][idnumber=602656027]
Note that REQ_FULL_WITH_MEMBERS on the client side against the user would be mapped to
BE_REQ_USER request on the server side.
So we still have no proper logs covering the period of the request --
unless your client has time not in sync with the server.
--
/ Alexander Bokovoy
Sr. Principal Software Engineer
Security / Identity Management Engineering
Red Hat Limited, Finland