Hello,
I'm unable to ssh as an AD user to a freeipa client. I am, however able to ssh as an AD user to a freeipa server. I can also ssh to a freeipa client AND server using a FreeIPA account. Our IPA domain (ipa.subdomain.contoso.com) is set up with a one-way trust with ad.contoso.com. Our AD is on the larger side with 400,000+ user accounts.
An ldbsearch on the client cache file returns 42 records, the same search on the server cache returns 113551 records. Searching for a specific user; ldbsearch -H /var/lib/sss/db/cache_ipa.subdomain.contoso.com.ldb '(name=heidi-ad@ad.contoso.com)' returns zero records on the freeipa client and 1 record on the freeipa server.
Dig commands (dig -t SRV _ldap._tcp.ipa.subdomain.contoso.com and dig -t SRV _ldap._tcp.ad.contoso.com) also return expected results.
server:sssd.conf https://privatebin.net/?42cff7bd431068d7#FmeM5p3R88U9oQd98UvoaVHZ3PzeZTGvS5V...
client:sssd.conf https://privatebin.net/?d4f20faca95236f4#D8WtjwDMaAB932W66YMgW5HtXkdfez1Ht1v...
I'm not sure what to key in on in the SSSD logs to identify what's going wrong here and how to resolve it. I've attempted to fiddle with multiple timeout settings, but haven't identified the right ones. I do see SSSD is reported as offline and this very much feels like a communication issue. I have uploaded sanitized SSSD logs from rl9-ipa-client1.in.subdomain.contoso.com and freeipa2.ipa.subdomain.contoso.com for a failed login attempt at the following: https://privatebin.net/?1028b6754421174b#DDDuthsRbLjxt4rS1mr263MmJ2qjhLgLHpy...
Thanks, Heidi
On Пят, 09 лют 2024, Heidi Hough via FreeIPA-users wrote:
Hello,
I'm unable to ssh as an AD user to a freeipa client. I am, however able to ssh as an AD user to a freeipa server. I can also ssh to a freeipa client AND server using a FreeIPA account. Our IPA domain (ipa.subdomain.contoso.com) is set up with a one-way trust with ad.contoso.com. Our AD is on the larger side with 400,000+ user accounts.
An ldbsearch on the client cache file returns 42 records, the same search on the server cache returns 113551 records. Searching for a specific user; ldbsearch -H /var/lib/sss/db/cache_ipa.subdomain.contoso.com.ldb '(name=heidi-ad@ad.contoso.com)' returns zero records on the freeipa client and 1 record on the freeipa server.
Dig commands (dig -t SRV _ldap._tcp.ipa.subdomain.contoso.com and dig -t SRV _ldap._tcp.ad.contoso.com) also return expected results.
server:sssd.conf https://privatebin.net/?42cff7bd431068d7#FmeM5p3R88U9oQd98UvoaVHZ3PzeZTGvS5V...
client:sssd.conf https://privatebin.net/?d4f20faca95236f4#D8WtjwDMaAB932W66YMgW5HtXkdfez1Ht1v...
I'm not sure what to key in on in the SSSD logs to identify what's going wrong here and how to resolve it. I've attempted to fiddle with multiple timeout settings, but haven't identified the right ones. I do see SSSD is reported as offline and this very much feels like a communication issue. I have uploaded sanitized SSSD logs from rl9-ipa-client1.in.subdomain.contoso.com and freeipa2.ipa.subdomain.contoso.com for a failed login attempt at the following: https://privatebin.net/?1028b6754421174b#DDDuthsRbLjxt4rS1mr263MmJ2qjhLgLHpy...
Thanks for the logs. Can you say where the logs from the IPA server start from? It would be best if you could provide tarballs of /var/log/sssd from both the client and the server at the same time period. With this pastebin it is impossible to differentiate logs from the client from the logs of the server.
(2024-02-09 11:35:00): [be[ipa.subdomain.contoso.com]] [ipa_s2n_get_acct_info_send] (0x0400): [RID#2] Sending request_type: [REQ_FULL_WITH_MEMBERS] for trust user [heidi-ad] to IPA server (2024-02-09 11:35:00): [be[ipa.subdomain.contoso.com]] [ipa_s2n_exop_send] (0x0400): [RID#2] Executing extended operation (2024-02-09 11:35:00): [be[ipa.subdomain.contoso.com]] [ipa_s2n_exop_send] (0x2000): [RID#2] ldap_extended_operation sent, msgid = 15 (2024-02-09 11:35:00): [be[ipa.subdomain.contoso.com]] [sdap_op_add] (0x2000): [RID#2] New operation 15 timeout 6 (2024-02-09 11:35:00): [be[ipa.subdomain.contoso.com]] [sdap_process_result] (0x2000): Trace: sh[0x5591a0d6cde0], connected[1], ops[0x5591a0d7ae80], ldap[0x5591a0d721f0] (2024-02-09 11:35:00): [be[ipa.subdomain.contoso.com]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (2024-02-09 11:35:06): [be[ipa.subdomain.contoso.com]] [sdap_op_timeout] (0x1000): [RID#2] Issuing timeout [ldap_opt_timeout] for message id 15 (2024-02-09 11:35:06): [be[ipa.subdomain.contoso.com]] [sdap_call_op_callback] (0x3f7c0): [RID#2] LDAP operation [15][server: [172.16.50.102:389] IPA EXOP] seems slow, took more than 80% of timeout [6]. (2024-02-09 11:35:06): [be[ipa.subdomain.contoso.com]] [sdap_op_destructor] (0x1000): [RID#2] Abandoning operation 15 (2024-02-09 11:35:06): [be[ipa.subdomain.contoso.com]] [ipa_s2n_get_user_done] (0x0040): [RID#2] s2n exop request failed.
This says that a client has asked the server to resolve AD user but this operation took longer than expected timeout of 6 seconds and the client abandoned the request. You need to get logs from the IPA server at the same timeframe and see why it failed to complete in time.
ldap_search_timout is by default 6 seconds and you have no modification of that so this matches client abandoning a search.
Thanks, Heidi -- _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@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.fedorahoste... Do not reply to spam, report it: https://pagure.io/fedora-infrastructure/new_issue
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#DwWqNUD96mcHqBYoNi7u97n9ZZ6ZNYeVDTr... Server https://privatebin.net/?f8a35b7c92fae546#DT3sHCD9kY7h3UZrRSBX8VbBkmccRCVkggu...
Thanks Heidi
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#DwWqNUD96mcHqBYoNi7u97n9ZZ6ZNYeVDTr... Server https://privatebin.net/?f8a35b7c92fae546#DT3sHCD9kY7h3UZrRSBX8VbBkmccRCVkggu...
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@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@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@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.fedorahoste... Do not reply to spam, report it: https://pagure.io/fedora-infrastructure/new_issue
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?
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?
Server Logs https://privatebin.net/?862036054ee43408#82w4yEWnVV3hvz4JeU4hTacoMeArh4ETZiC... Client Logs https://privatebin.net/?f1e3f32ff85a5d84#HyQpVgLyNp9JASZhCHjeKxY1PVefqb7s5eR...
Heidi
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@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@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@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@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@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.
Server Logs https://privatebin.net/?862036054ee43408#82w4yEWnVV3hvz4JeU4hTacoMeArh4ETZiC... Client Logs https://privatebin.net/?f1e3f32ff85a5d84#HyQpVgLyNp9JASZhCHjeKxY1PVefqb7s5eR...
Heidi
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@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.fedorahoste... Do not reply to spam, report it: https://pagure.io/fedora-infrastructure/new_issue
You are correct, debugging was only specified in the [domain/...] section. I have enabled for nss and gathered logs again. The client and server times are indeed in sync.
I initiated my login attempt at approximately 10:16:30. At approximately 10:17:10 I was presented with a prompt to enter my password. After entering my password I was again presented with a password prompt. After entering multiple times with no success I waited and eventually the connection attempt timed out.
Server Logs for this attempt https://privatebin.net/?74adb14729c459fc#EhqWm6x2LVgfnL7iAmLZDFh3TtXpwgsH9wj... Client Logs for this attempt https://privatebin.net/?1d3532466812bef2#C6ECF2RnRMEXVi7HGLd8iYvhoSmEw2uRs88...
It seems like a considerable amount of time is spent searching the AD groups a user is a member of. For testing purposes, an AD account was created that is not a member of any groups. This user was able to successfully log in. What additional steps should be taken to account for AD's where users are members of many groups? To add to the complexity, many of these groups are nested.
I've reviewed this document (https://access.redhat.com/articles/2133801) and spent time adjusting parameters with little success.
The sssd.conf on both client and server include the following in the [domain/...] section:
subdomain_inherit = ignore_group_members ignore_group_members = True
Should these be placed somewhere else instead? Are there other options that should be set to account for large numbers of nested AD groups?
Thank you Heidi
On Чцв, 15 лют 2024, Heidi Hough via FreeIPA-users wrote:
You are correct, debugging was only specified in the [domain/...] section. I have enabled for nss and gathered logs again. The client and server times are indeed in sync.
I initiated my login attempt at approximately 10:16:30. At approximately 10:17:10 I was presented with a prompt to enter my password. After entering my password I was again presented with a password prompt. After entering multiple times with no success I waited and eventually the connection attempt timed out.
Server Logs for this attempt https://privatebin.net/?74adb14729c459fc#EhqWm6x2LVgfnL7iAmLZDFh3TtXpwgsH9wj... Client Logs for this attempt https://privatebin.net/?1d3532466812bef2#C6ECF2RnRMEXVi7HGLd8iYvhoSmEw2uRs88...
It seems like a considerable amount of time is spent searching the AD groups a user is a member of. For testing purposes, an AD account was created that is not a member of any groups. This user was able to successfully log in. What additional steps should be taken to account for AD's where users are members of many groups? To add to the complexity, many of these groups are nested.
If time to resolve all groups is above 10 seconds, then you might want to increase timeouts. There are three elements in a lookup:
- SSSD on the client to IPA server's LDAP server - IPA server's LDAP server to local SSSD on the IPA server - SSSD on the IPA server to AD DCs
The middle one (LDAP server plugin to local SSSD) should have a timeout that covers time spent in resolving the most complex query issued to AD DCs. SSSD on the client should be able to handle at least that timeout too.
I've reviewed this document (https://access.redhat.com/articles/2133801) and spent time adjusting parameters with little success.
The sssd.conf on both client and server include the following in the [domain/...] section:
subdomain_inherit = ignore_group_members ignore_group_members = True
Should these be placed somewhere else instead? Are there other options that should be set to account for large numbers of nested AD groups?
No, these should be OK. The only potential change you might want to do is to bump a timeout used by the ipa-exdom-extop plugin when it talks to the SSSD on the server side:
https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/9/htm...
It is 10 seconds by default but in your case it looks like the whole set of operations to reverse resolve all those groups takes around 20-26 seconds. Notice the diffs between 'Looking up ...' and 'Object found, but needs to be refreshed', most are within the same second but few are requiring up to 5 seconds. These are actions to do 'initgroups' operation which is typically run by the client side when you log in, to build a list of secondary groups for your login process. I guess a first login would require a lot time due to this information being not yet available but consequent ones would take much lower time.
$ grep 'CID#8' sssd_nss.log |grep -E '(Looking up|but needs)' (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #31: Looking up heidi-ad@ad.contoso.com (2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #31: Looking up [heidi-ad@ad.contoso.com] in cache (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #31: Object found, but needs to be refreshed. (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #32: Looking up heidi-ad@ad.contoso.com (2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #32: Looking up [heidi-ad@ad.contoso.com] in cache (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #32: Object found, but needs to be refreshed. (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #33: Looking up heidi-ad@ad.contoso.com (2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #33: Looking up [heidi-ad@ad.contoso.com] in cache (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #33: Object found, but needs to be refreshed. (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #34: Looking up GID:603892026@ad.contoso.com (2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #34: Looking up [GID:603892026@ad.contoso.com] in cache (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #34: Object found, but needs to be refreshed. (2024-02-14 10:16:30): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #35: Looking up GID:602655731@ad.contoso.com (2024-02-14 10:16:30): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #35: Looking up [GID:602655731@ad.contoso.com] in cache (2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #35: Object found, but needs to be refreshed. (2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #36: Looking up GID:604961401@ad.contoso.com (2024-02-14 10:16:31): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #36: Looking up [GID:604961401@ad.contoso.com] in cache (2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #36: Object found, but needs to be refreshed. (2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #37: Looking up GID:602655735@ad.contoso.com (2024-02-14 10:16:31): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #37: Looking up [GID:602655735@ad.contoso.com] in cache (2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #37: Object found, but needs to be refreshed. (2024-02-14 10:16:31): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #38: Looking up GID:604859746@ad.contoso.com (2024-02-14 10:16:31): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #38: Looking up [GID:604859746@ad.contoso.com] in cache (2024-02-14 10:16:34): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #38: Object found, but needs to be refreshed. (2024-02-14 10:16:34): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #39: Looking up GID:604965529@ad.contoso.com (2024-02-14 10:16:34): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #39: Looking up [GID:604965529@ad.contoso.com] in cache (2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #39: Object found, but needs to be refreshed. (2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #40: Looking up GID:605125185@ad.contoso.com (2024-02-14 10:16:39): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #40: Looking up [GID:605125185@ad.contoso.com] in cache (2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #40: Object found, but needs to be refreshed. (2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #41: Looking up GID:601449600@ad.contoso.com (2024-02-14 10:16:39): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #41: Looking up [GID:601449600@ad.contoso.com] in cache (2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #41: Object found, but needs to be refreshed. (2024-02-14 10:16:39): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #42: Looking up GID:604750598@ad.contoso.com (2024-02-14 10:16:39): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #42: Looking up [GID:604750598@ad.contoso.com] in cache (2024-02-14 10:16:40): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #42: Object found, but needs to be refreshed. (2024-02-14 10:16:40): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #43: Looking up GID:605323973@ad.contoso.com (2024-02-14 10:16:40): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #43: Looking up [GID:605323973@ad.contoso.com] in cache (2024-02-14 10:16:42): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #43: Object found, but needs to be refreshed. (2024-02-14 10:16:42): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #44: Looking up GID:605323972@ad.contoso.com (2024-02-14 10:16:42): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #44: Looking up [GID:605323972@ad.contoso.com] in cache (2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #44: Object found, but needs to be refreshed. (2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #46: Looking up GID:604874522@ad.contoso.com (2024-02-14 10:16:44): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #46: Looking up [GID:604874522@ad.contoso.com] in cache (2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #46: Object found, but needs to be refreshed. (2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #47: Looking up GID:604954881@ad.contoso.com (2024-02-14 10:16:44): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #47: Looking up [GID:604954881@ad.contoso.com] in cache (2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #47: Object found, but needs to be refreshed. (2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #49: Looking up GID:604962564@ad.contoso.com (2024-02-14 10:16:44): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #49: Looking up [GID:604962564@ad.contoso.com] in cache (2024-02-14 10:16:44): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #49: Object found, but needs to be refreshed. (2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #51: Looking up GID:605156103@ad.contoso.com (2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #51: Looking up [GID:605156103@ad.contoso.com] in cache (2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #51: Object found, but needs to be refreshed. (2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #53: Looking up GID:605150943@ad.contoso.com (2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #53: Looking up [GID:605150943@ad.contoso.com] in cache (2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #53: Object found, but needs to be refreshed. (2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #55: Looking up GID:604144821@ad.contoso.com (2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #55: Looking up [GID:604144821@ad.contoso.com] in cache (2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #55: Object found, but needs to be refreshed. (2024-02-14 10:16:45): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #57: Looking up GID:605251188@ad.contoso.com (2024-02-14 10:16:45): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #57: Looking up [GID:605251188@ad.contoso.com] in cache (2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #57: Object found, but needs to be refreshed. (2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #59: Looking up GID:605131034@ad.contoso.com (2024-02-14 10:16:46): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #59: Looking up [GID:605131034@ad.contoso.com] in cache (2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #59: Object found, but needs to be refreshed. (2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #61: Looking up GID:604758004@ad.contoso.com (2024-02-14 10:16:46): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #61: Looking up [GID:604758004@ad.contoso.com] in cache (2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #61: Object found, but needs to be refreshed. (2024-02-14 10:16:46): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #63: Looking up GID:602656027@ad.contoso.com (2024-02-14 10:16:46): [nss] [cache_req_search_cache] (0x0400): [CID#8] CR #63: Looking up [GID:602656027@ad.contoso.com] in cache (2024-02-14 10:16:52): [nss] [cache_req_search_send] (0x0400): [CID#8] CR #63: Object found, but needs to be refreshed.
Thank you for your guidance with this issue. Adjusting the ipaExtdomMaxNssTimeout and client pam_id_timeout allowed a successful login for an AD user on our system. We will continue to fine-tune timeout settings to identify the best values for our environment.
Heidi
freeipa-users@lists.fedorahosted.org