Slow SSSD Login and ldapsearch command
Environment
- Red Hat Enterprise Linux 6
- sssd
Issue
- logins are delayed when sssd has to connect back to Active Directory after the system has been idle
- Issue is also noticed with ldapsearch
Resolution
- Configure a different nameserver in
resolv.conf - Address root issue on the nameserver or in the network that is causing nameserver lookups to take too long.
Root Cause
sssddebug logs show that the delay occurs in the 'sasl_bind_send' function:
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [be_resolve_server_process] (0x0200): Found address for server dc1.windows.dc.testing.com: [10.254.21.75] TTL 3600
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT...
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [create_tgt_req_send_buffer] (0x0400): buffer size: 60
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [3058]
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [3058]
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [sdap_process_result] (0x2000): Trace: sh[0xbd3e30], connected[1], ops[(nil)], ldap[0xc183e0]
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [write_pipe_handler] (0x0400): All data has been sent!
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [sdap_get_tgt_recv] (0x0400): Child responded: 0 [FILE:/var/lib/sss/db/ccache_windows.dc.testing.com], expired on [1425444362]
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1425409262
(Tue Mar 3 13:46:02 2015) [sssd[be[windows.dc.testing.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: RHEL6-SSSD-AD$
(Tue Mar 3 13:46:12 2015) [sssd[be[windows.dc.testing.com]]] [child_sig_handler] (0x1000): Waiting for child [3058].
(Tue Mar 3 13:46:12 2015) [sssd[be[windows.dc.testing.com]]] [child_sig_handler] (0x0100): child [3058] finished successfully.
(Tue Mar 3 13:46:12 2015) [sssd[be[windows.dc.testing.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'dc1.windows.dc.testing.com' as 'working'
(Tue Mar 3 13:46:12 2015) [sssd[be[windows.dc.testing.com]]] [set_server_common_status] (0x0100): Marking server 'dc1.windows.dc.testing.com' as 'working'~~
- Packet capture analysis shows that prior to the LDAP bind, majority of time is spent with DNS lookups
[justintime@pantheist ldapsearch-test1.pcap-ad0930fe-4104-488c-9426-677c47d6fdbd]$ tshark -tad -n -r ldapsearch-test1.pcap "ldap || dns"
112 2015-03-18 10:03:33.564196 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0x512b A dc1.windows.dc.testing.com
113 2015-03-18 10:03:33.565159 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0x1b6d AAAA dc1.windows.dc.testing.com
114 2015-03-18 10:03:33.565618 10.0.2.3 -> 10.0.2.15 DNS 112 Standard query response 0x512b A 10.170.20.56
115 2015-03-18 10:03:33.566095 10.0.2.3 -> 10.0.2.15 DNS 151 Standard query response 0x7600
160 2015-03-18 10:03:38.568807 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0x512b A dc1.windows.dc.testing.com
161 2015-03-18 10:03:38.570061 10.0.2.3 -> 10.0.2.15 DNS 112 Standard query response 0x512b A 10.170.20.56
162 2015-03-18 10:03:38.570116 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0x1b6d AAAA dc1.windows.dc.testing.com
163 2015-03-18 10:03:38.571452 10.0.2.3 -> 10.0.2.15 DNS 151 Standard query response 0x1b6d
167 2015-03-18 10:03:38.572828 10.0.2.15 -> 10.0.2.3 DNS 85 Standard query 0x54b4 PTR 56.20.170.10.in-addr.arpa
168 2015-03-18 10:03:38.574228 10.0.2.3 -> 10.0.2.15 DNS 135 Standard query response 0x54b4 PTR dc1.windows.dc.testing.com
169 2015-03-18 10:03:38.576937 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0xeb44 A dc1.windows.dc.testing.com
170 2015-03-18 10:03:38.576998 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0xc2d5 AAAA dc1.windows.dc.testing.com
171 2015-03-18 10:03:38.578880 10.0.2.3 -> 10.0.2.15 DNS 112 Standard query response 0xeb44 A 10.170.20.56
172 2015-03-18 10:03:38.578885 10.0.2.3 -> 10.0.2.15 DNS 151 Standard query response 0x7d00
178 2015-03-18 10:03:43.581417 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0xeb44 A dc1.windows.dc.testing.com
179 2015-03-18 10:03:43.582553 10.0.2.3 -> 10.0.2.15 DNS 112 Standard query response 0xeb44 A 10.170.20.56
180 2015-03-18 10:03:43.582644 10.0.2.15 -> 10.0.2.3 DNS 96 Standard query 0xc2d5 AAAA dc1.windows.dc.testing.com
181 2015-03-18 10:03:43.584206 10.0.2.3 -> 10.0.2.15 DNS 151 Standard query response 0xc2d5
182 2015-03-18 10:03:43.584381 10.0.2.15 -> 10.0.2.3 DNS 85 Standard query 0xa8e1 PTR 56.20.170.10.in-addr.arpa
183 2015-03-18 10:03:43.586217 10.0.2.3 -> 10.0.2.15 DNS 135 Standard query response 0xa8e1 PTR dc1.windows.dc.testing.com
Diagnostic Steps
- Review a tcpdump when the sssd backend needs to connect to active directory/LDAP
- Check
sssddebug logs - Debug kerberos activity with kinit
KRB5_TRACE=/dev/stderr kinit -k RHEL6-SSSD-AD$
This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.
Welcome! Check out the Getting Started with Red Hat page for quick tours and guides for common tasks.
