started with level 6 and went up to 10 with pretty much the same logs.
Look at the lines around the gap from 13:05:06 to 13:05:08. That's when the delay happened. Responders other than nss and pam did not log anything within that time span.
It is this line that was waiting for response: (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
----- sssd_nss.log ----- (Tue Apr 14 13:05:06 2015) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning.. (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [qchang@mr.ric] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f8a5b56cc60][20] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f8a5b56cc60][20] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input [qchang]. (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'qchang' matched without domain, user is qchang (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [qchang] from [<ALL>] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mr.ric/qchang] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0100): Requesting info for [qchang@mr.ric] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f8a5b56c920
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f8a5b574840
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f8a5b56c920 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f8a5b574840 "ltdb_timeout"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f8a5b56c920 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [check_cache] (0x0400): Cached entry is valid, returning.. (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getpwnam_search] (0x0400): Returning info for user [qchang@mr.ric] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f8a5b56cc60][20] (Tue Apr 14 13:05:08 2015) [sssd[nss]] [get_client_cred] (0x4000): Client creds: euid[81] egid[81] pid[503]. (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f8a5b574840][21] (Tue Apr 14 13:05:08 2015) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f8a5b574840][21] (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f8a5b574840][21] (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f8a5b574840][21] (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [38] with input [root]. (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'root' matched without domain, user is root (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0100): Requesting info for [root] from [<ALL>] (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mr.ric/root] (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_initgroups_search] (0x0400): User [root] does not exist in [mr.ric]! (negative cache) (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_initgroups_search] (0x0080): No matching domain found for [root], fail! ----- ----- sssd_pam.log ----- (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_check_user_search] (0x0400): Returning info for user [qchang@mr.ric] (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): domain: mr.ric (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): user: qchang (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7402 (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100): logon name: qchang (Tue Apr 14 13:05:06 2015) [sssd[pam]] [sbus_add_timeout] (0x2000): 0x7f1aff4200a0 (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7f1aff4200a0 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7f1aff41ddd0 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_dp_process_reply] (0x0100): received: [0][mr.ric] (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [0]. (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_reply] (0x0200): blen: 23 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f1aff421b40][19] (Tue Apr 14 13:05:08 2015) [sssd[pam]] [reset_idle_timer] (0x4000): Idle timer re-set for client [0x7f1aff421b40][19] (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_cmd_setcred] (0x0100): entering pam_cmd_setcred (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'qchang' matched without domain, user is qchang (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): command: PAM_SETCRED (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): domain: not set (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): user: qchang (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 7402 (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100): logon name: qchang (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/mr.ric/qchang] -----
On 04/13/2015 05:41 PM, Dmitri Pal wrote:
On 04/13/2015 05:29 PM, Qing Chang wrote:
Thanks Lucas for the information.
I tried the selinux line, it did not seem to make a difference.
As I said in my original email, login to the IPA server itself does not exhibit the same behavior, although every system has the same SSSD configuration and SElinux enabled. I actually tried "setenforce 0" on a client without any effect either.
I checked all the reference you provided, my feelings is that the events add up still would not account for 5 seconds delay:-(
If anybody would like to have debug information, please let me know (the procedure to produce). Please also let me know if I should file a bug.
Please see SSSD troubleshooting page. [1] Rise debug_level, inspect the logs and see what operation is really taking the time.
I suspect this there some DNS release timeout that you are hitting but without logs it is not possible to say.
[1] https://fedorahosted.org/sssd/wiki/Troubleshooting
Many thanks, Qing
On Mon, Apr 13, 2015 at 4:22 PM, Lukas Slebodnik <lslebodn@redhat.com mailto:lslebodn@redhat.com> wrote:
On (13/04/15 15:28), Qing Chang wrote: >OS: CentoOS 7.1 >IPA: 4.1.0-18 >SSSD: 1.12.2-58 > >With IPA any clients running CentOS7.1 authentication for ssh and sudo >takes more than 5 seconds _after_ putting in password. If ssh to the IPA >server itself, it authenticates instantly. > >Google did not provide much relevant information. Note that this is not a >slow ssh session to get to authentication prompt, it always gets to the >prompt without delay. > >Also it is not related to NFS performance, it is equally slow if I login to >a NFS server (IPA client) locally or login to a server (also a IPA client) >that has autofs home. > >IPA server is a fresh installation with just a couple of users. I had an >installation previously that has more than a thousand user accounts on >CentOS 6. Users did not have the slowness problem as with this new >installation. > >Hope this list can provide some pointers. > You might hit bug[1]. If you do not use SELinux ser mapping[2] you can try to disable this feature. put "selinux_provider = none" into domain section of sssd.conf If it doesn't help you can tahe a look on sssd<->systemd conversation in mail thread[3] LS [1] https://fedorahosted.org/sssd/ticket/2624 [2] https://www.freeipa.org/page/SELinux_user_mapping [3] http://lists.freedesktop.org/archives/systemd-devel/2015-April/030496.html _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org <mailto:sssd-users@lists.fedorahosted.org> https://lists.fedorahosted.org/mailman/listinfo/sssd-users
sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
-- Thank you, Dmitri Pal
Sr. Engineering Manager IdM portfolio Red Hat, Inc.
sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users