[Freeipa-users] Slow logins with multi site replication

Mon Aug 1 14:35:04 UTC 2016

Hi,

I am experiencing slow logins and sudo authentication for servers joined to my FreeIPA domain. I have been following the other recent thread on slow logins and believe my issue is different.

I have replication setup with 2 FreeIPA servers at each of 3 sites. The replication is working well and I am able to login correctly on client servers with correct sudo permissions etc. Logins seem to take a long time however. There seems to be some kind of DNS/connection timeout issues, see the example below where the client times out on the auth01 server, then retries and connects. I have also seen it switch to an alternate IPA server on timeout. Total delay in this example is about 10 seconds however it can take longer (approx 30 seconds). It is worth mentioning that client servers in each site cannot connect to IPA servers is a different site - however in the example below the auth01 IPA server is in the same site as the client server. I'm not sure if there is any way to make the IPA clients site aware so they prefer to log in to a local server?

On the IPA servers themselves there is no noticeable delay and once I have authenticated with sudo once, subsequent attempts in the same login are also near instant. I have not been able to find any reason for this delay in any logs (which probably just means I'm not looking in the right place).

DNS servers are running on each IPA server and responding well whenever I have tested.

IPA Servers: CentOS 7.2.1511 running IPA 4.2.0 (from standard CentOS repo)

Client servers: Ubuntu 14.04 running IPA 3.3.4 (From standard Ubuntu repo)

Any comments or suggestions greatly appreciated.

Thanks,

Neal.

Example sssd log for a "sudo -l" attempt.

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [be_get_account_info] (0x0100): Got request for [3][1][name=neal]

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [sdap_attrs_get_sid_str] (0x0080): No [objectSIDString] attribute while id-mapping. [0][Success]

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [be_pam_handler] (0x0100): Got request with the following data

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): domain: fqdn.com

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): user: neal

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): service: sudo

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): tty: /dev/pts/3

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): ruser: neal

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): rhost:

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): authtok type: 1

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): newauthtok type: 0

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): priv: 0

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): cli_pid: 7429

(Mon Aug 1 14:39:53 2016) [sssd[be[fqdn.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'

(Mon Aug 1 14:39:59 2016) [sssd[be[fqdn.com]]] [krb5_child_timeout] (0x0040): Timeout for child [7430] reached. In case KDC is distant or network is slow you may consider increasing value of krb5_auth_timeout.

(Mon Aug 1 14:39:59 2016) [sssd[be[fqdn.com]]] [krb5_auth_done] (0x0020): child timed out!

(Mon Aug 1 14:39:59 2016) [sssd[be[fqdn.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'auth01.fqdn.com' as 'not working'

(Mon Aug 1 14:39:59 2016) [sssd[be[fqdn.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'

(Mon Aug 1 14:39:59 2016) [sssd[be[fqdn.com]]] [child_sig_handler] (0x0020): waitpid did not found a child with changed status.

(Mon Aug 1 14:39:59 2016) [sssd[be[fqdn.com]]] [child_sig_handler] (0x0020): child [7430] was terminated by signal [9].

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'auth01.fqdn.com' as 'working'

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [set_server_common_status] (0x0100): Marking server 'auth01.fqdn.com' as 'working'

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_pam_handler_callback] (0x0100): Sending result [0][fqdn.com]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_pam_handler_callback] (0x0100): Sent result [0][fqdn.com]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [child_sig_handler] (0x0100): child [7431] finished successfully.

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_get_account_info] (0x0100): Got request for [3][1][name=neal]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [sdap_attrs_get_sid_str] (0x0080): No [objectSIDString] attribute while id-mapping. [0][Success]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_pam_handler] (0x0100): Got request with the following data

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): domain: fqdn.com

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): user: neal

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): service: sudo

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): tty: /dev/pts/3

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): ruser: neal

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): rhost:

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): authtok type: 0

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): newauthtok type: 0

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): priv: 0

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [pam_print_data] (0x0100): cli_pid: 7429

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [hbac_user_attrs_to_rule] (0x0020): [uid=admin,cn=users,cn=accounts,dc=fqnd,dc=com] does not map to either a user or group. Skipping

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [global_login]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, Success) [Success]

(Mon Aug 1 14:40:04 2016) [sssd[be[fqdn.com]]] [be_pam_handler_callback] (0x0100): Sending result [0][fqdn.com]

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20160801/216dbbdd/attachment.htm>