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.
----- 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
----- 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
----- 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]
-----