On (16/04/15 10:28), Qing Chang wrote:
I have gone through the log and got the following sections for clarity.
Red lines are where the pause/delay happened. It looks to me two of them (PAM_AUTHENTICATE and Retrieving SELinux user mapping) are due to SSSD taking a break (All data has been sent!) from talking to the IPA server.
I have done some ping test among the servers, average ping time is 0.5ms.
----- one second for PAM_AUTHENTICATE ----- (Wed Apr 15 14:19:44:122152 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 14:19:44:122163 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Wed Apr 15 14:19:44:122173 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 14:19:44:122183 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 14:19:44:122193 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 14:19:44:122202 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 14:19:44:122212 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 14:19:44:122221 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 14:19:44:122232 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 1 (Wed Apr 15 14:19:44:122242 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 14:19:44:122251 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 14:19:44:122261 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 28330 (Wed Apr 15 14:19:44:122271 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 14:19:44:122399 2015) [sssd[be[mr.ric]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Wed Apr 15 14:19:44:122422 2015) [sssd[be[mr.ric]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Wed Apr 15 14:19:44:122443 2015) [sssd[be[mr.ric]]] [be_resolve_server_process] (0x0200): Found address for server mripa1.mr.ric: [172.25.12.153] TTL 1200 (Wed Apr 15 14:19:44:122460 2015) [sssd[be[mr.ric]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://mripa1.mr.ric' (Wed Apr 15 14:19:44:123509 2015) [sssd[be[mr.ric]]] [write_pipe_handler] (0x0400): All data has been sent! (Wed Apr 15 14:19:45:169789 2015) [sssd[be[mr.ric]]] [child_sig_handler] (0x0100): child [28332] finished successfully. (Wed Apr 15 14:19:45:169853 2015) [sssd[be[mr.ric]]] [read_pipe_handler] (0x0400): EOF received, client finished
krb5_child should be spawend here. You might take a look into krb5_child.log
----- one second for PAM_ACCT_MGMT ----- (Wed Apr 15 14:19:45:225894 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 14:19:45:225905 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT (Wed Apr 15 14:19:45:225915 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 14:19:45:225925 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 14:19:45:225934 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 14:19:45:225944 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 14:19:45:225954 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 14:19:45:225963 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 14:19:45:225973 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 14:19:45:225983 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 14:19:45:225992 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 14:19:45:226002 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 28330 (Wed Apr 15 14:19:45:226012 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 14:19:45:226030 2015) [sssd[be[mr.ric]]] [sdap_access_send] (0x0400): Performing access check for user [qchang] (Wed Apr 15 14:19:45:226168 2015) [sssd[be[mr.ric]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user [qchang] (Wed Apr 15 14:19:45:226213 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaHost)(fqdn= mripadm.mr.ric))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:45:228995 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:45:229039 2015) [sssd[be[mr.ric]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Apr 15 14:19:45:229063 2015) [sssd[be[mr.ric]]] [sdap_x_deref_search_send] (0x0400): Dereferencing entry [fqdn=mripadm.mr.ric,cn=computers,cn=acc ounts,dc=mr,dc=ric] using OpenLDAP deref (Wed Apr 15 14:19:45:229077 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][fqdn=mripadm.mr.ri c,cn=computers,cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:46:175840 2015) [sssd[be[mr.ric]]] [sdap_x_deref_parse_entry] (0x0400): Got deref control (Wed Apr 15 14:19:46:175969 2015) [sssd[be[mr.ric]]] [sdap_x_deref_parse_entry] (0x0400): All deref results from a single control parsed (Wed Apr 15 14:19:46:176072 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
It looks like ldap serach was called with dereference. Usually it is called when group has >10 members.
Is the user "qchang" member of meny groups. or does some groups have many members?
----- one second for Retrieving SELinux user mapping ----- (Wed Apr 15 14:19:46:204860 2015) [sssd[be[mr.ric]]] [ipa_get_selinux_send] (0x0400): Retrieving SELinux user mapping (Wed Apr 15 14:19:46:204893 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ipaConfig)(objectClass= ipaGuiConfig))][cn=etc,dc=mr,dc=ric]. (Wed Apr 15 14:19:46:206852 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:46:206899 2015) [sssd[be[mr.ric]]] [ipa_selinux_get_maps_next] (0x0400): Trying to fetch SELinux maps with following parameters: [2] [(&(objectclass=ipaselinuxusermap)(ipaEnabledFlag=TRUE))][cn=selinux,dc=mr,dc=ric] (Wed Apr 15 14:19:46:206917 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaselinuxuser map)(ipaEnabledFlag=TRUE))][cn=selinux,dc=mr,dc=ric]. (Wed Apr 15 14:19:46:207979 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:46:208011 2015) [sssd[be[mr.ric]]] [ipa_selinux_get_maps_done] (0x0400): No SELinux user maps found! (Wed Apr 15 14:19:46:210900 2015) [sssd[be[mr.ric]]] [write_pipe_handler] (0x0400): All data has been sent! (Wed Apr 15 14:19:47:557404 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x1003][1][name=avahi] (Wed Apr 15 14:19:47:557429 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric]
This should not be executed is SELinux provider is disabled. "selinux_provider=none" in domain section.
----- 0.01 second for lookup for avahi and poltitd combined ----- (Wed Apr 15 14:19:47:557404 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x1003][1][name=avahi] ... (Wed Apr 15 14:19:47:569055 2015) [sssd[be[mr.ric]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Wed Apr 15 14:19:47:569093 2015) [sssd[be[mr.ric]]] [acctinfo_callback] (0x0100): Request processed. Returned 3,0,Account info lookup failed (Wed Apr 15 14:19:47:570494 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x1003][1][name=polkitd] ... (Wed Apr 15 14:19:47:581941 2015) [sssd[be[mr.ric]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Wed Apr 15 14:19:47:581975 2015) [sssd[be[mr.ric]]] [acctinfo_callback] (0x0100): Request processed. Returned 3,0,Account info lookup failed
Did you have a change to test the latest snapshot of sssd? It contains fixes for SELinux user mappings so it should be faster even without disabled selinuc_provider
https://copr.fedoraproject.org/coprs/lslebodn/sssd-1-12-latest/
LS