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(a)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(a)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(a)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(a)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(a)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(a)lists.fedorahosted.org
> <mailto:sssd-users@lists.fedorahosted.org>
>
https://lists.fedorahosted.org/mailman/listinfo/sssd-users
>
>
>
>
> _______________________________________________
> sssd-users mailing list
> sssd-users(a)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(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users