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.
Thanks in advance.
Qing Chang
On 4/13/15 12:28 PM, 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.
Thanks in advance.
Qing Chang
sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
You might try changing /etc/nsswitch.conf and remove SSS from suoders. I have been finding this slows down a lot of operations. Not sure if it is the same as your problem, but it can't hurt to try it.
~J
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
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.
Many thanks, Qing
On Mon, Apr 13, 2015 at 4:22 PM, Lukas Slebodnik 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 https://lists.fedorahosted.org/mailman/listinfo/sssd-users
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
On Mon, Apr 13, 2015 at 05:41:43PM -0400, 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.
Right. Also, are those IPA users or AD users through trusts? (I suspect the former).
I started with level 6 and went up to 10 with pretty much the same logs.
There is probably quite some noise, but look at the lines around the gap from 13:05:06 to 13:05:08. That is about the duration of the delay. Responders other than nss and pam did not log anything within that time span.
----- sssd_nss.log ----- (Tue Apr 14 13:05:03 2015) [sssd[nss]] [sbus_handler_got_caller_id] (0x4000): Received SBUS method [ping] (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": 0x7f8a5b567300
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f8a5b568490
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f8a5b567300 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f8a5b568490 "ltdb_timeout"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f8a5b567300 "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: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": 0x7f8a5b567300
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f8a5b568490
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f8a5b567300 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f8a5b568490 "ltdb_timeout"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f8a5b567300 "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: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": 0x7f8a5b567300
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f8a5b568490
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f8a5b567300 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f8a5b568490 "ltdb_timeout"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f8a5b567300 "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:06 2015) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x7f8a5b563dd0 (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching. (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sbus_message_handler] (0x4000): Received SBUS method [initgrCheck] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sbus_handler_got_caller_id] (0x4000): Received SBUS method [initgrCheck] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_memcache_initgr_check] (0x1000): Got request for [qchang@mr.ric] (Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f8a5b567e20
(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 0x7f8a5b567e20 "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 0x7f8a5b567e20 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f8a5b567e20
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f8a5b56bf50
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f8a5b567e20 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f8a5b575580
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f8a5b575640
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f8a5b56bf50 "ltdb_timeout"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f8a5b567e20 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f8a5b575580 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f8a5b575640 "ltdb_timeout"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f8a5b575580 "ltdb_callback"
(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": 0x7f8a5b5682c0
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f8a5b567e20
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running timer event 0x7f8a5b5682c0 "ltdb_callback"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x7f8a5b567e20 "ltdb_timeout"
(Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x7f8a5b5682c0 "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: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
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
On Tue, Apr 14, 2015 at 03:15:15PM -0400, tmpchq wrote:
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]
The logs are incomplete, moreover we also need the back end logs to be sure.
From the snippet you sent, I only see the account phase is taking 2
seconds. It's impossible what exactly is taking long without the domain logs.
Thanks. Can someone give me a hint what I need to look at on the IPA server? I checked krb5kdc.log but it does not have anything interesting.
Qing
On 04/15/2015 02:50 AM, Jakub Hrozek wrote:
On Tue, Apr 14, 2015 at 03:15:15PM -0400, tmpchq wrote:
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]
The logs are incomplete, moreover we also need the back end logs to be sure.
From the snippet you sent, I only see the account phase is taking 2 seconds. It's impossible what exactly is taking long without the domain logs. _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
On 04/15/2015 03:44 PM, tmpchq wrote:
Thanks. Can someone give me a hint what I need to look at on the IPA server? I checked krb5kdc.log but it does not have anything interesting.
Qing
I think Jakub wanted you to set 'debug_level' to 6 or above in domain section of sssd.conf and then provide us with that log (located in /var/log/sssd/ and named after the domain)
On 04/15/2015 02:50 AM, Jakub Hrozek wrote:
On Tue, Apr 14, 2015 at 03:15:15PM -0400, tmpchq wrote:
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]
The logs are incomplete, moreover we also need the back end logs to be sure.
From the snippet you sent, I only see the account phase is taking 2 seconds. It's impossible what exactly is taking long without the domain logs. _______________________________________________ sssd-users mailing list 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
I did set log level to 10 for domain section too. It did not log anything around the gap shown in sssd_nss and sssd_pam.
I am going to do a test again and post the logs.
Thanks, Qing
On 04/15/2015 09:54 AM, Pavel Reichl wrote:
On 04/15/2015 03:44 PM, tmpchq wrote:
Thanks. Can someone give me a hint what I need to look at on the IPA server? I checked krb5kdc.log but it does not have anything interesting.
Qing
I think Jakub wanted you to set 'debug_level' to 6 or above in domain section of sssd.conf and then provide us with that log (located in /var/log/sssd/ and named after the domain)
On 04/15/2015 02:50 AM, Jakub Hrozek wrote:
On Tue, Apr 14, 2015 at 03:15:15PM -0400, tmpchq wrote:
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]
The logs are incomplete, moreover we also need the back end logs to be sure.
From the snippet you sent, I only see the account phase is taking 2 seconds. It's impossible what exactly is taking long without the domain logs. _______________________________________________ sssd-users mailing list 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
sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
On (15/04/15 10:03), tmpchq wrote:
I did set log level to 10 for domain section too. It did not log anything around the gap shown in sssd_nss and sssd_pam.
I am going to do a test again and post the logs.
If there is a gap then you can take a look to logs in journald. There can be problem with other services.
LS
It was my mistake, I missed [domain] section. Below is at log level 6:
It spent time on checking for SELinux mapping, avahi and polkitd. ----- sssd_mr.ric.log ----- (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x3][1][name=qchang] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=qchang)(objectclass=posixAcco unt)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Save user (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Processing user qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [qchang]. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Adding user principal [qchang@MR.RIC] to attributes of [qchang]. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Storing info for user qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(objectClass=ipaUserGroup)(objec tClass=posixGroup))(cn=*))][cn=ipausers,cn=groups,cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(objectClass=ipaUserGroup)(objec tClass=posixGroup))(cn=*))][ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric]. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_initgr_nested_search] (0x0040): Search for group ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e, cn=sudorules,cn=sudo,dc=mr,dc=ric, returned 0 results. Skipping (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object ipausers (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(gidNumber=10001)(|(objectClass=ip aUserGroup)(objectClass=posixGroup))(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 1 results. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_nested_group_recv] (0x0400): 0 users found in the hash table (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_nested_group_recv] (0x0400): 1 groups found in the hash table (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_group] (0x0400): Processing group qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_process_ghost_members] (0x0400): The group has 0 members (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_process_ghost_members] (0x0400): Group has 0 members (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_group] (0x0400): Storing info for group qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem] (0x0400): Processing group qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem] (0x0400): Failed to get group sid (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem] (0x0400): No members for group [qchang] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ip aAnchorUUID=:IPA:mr.ric:4b2724aa-d87d-11e4-93fa-000c29f4de6e))][cn=Default Trust View,cn=views,cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: No such object(32), no errmsg set (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 1 (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 19776 (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Wed Apr 15 10:22:31 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 10:22:31 2015) [sssd[be[mr.ric]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://mripa1.mr.ric' (Wed Apr 15 10:22:31 2015) [sssd[be[mr.ric]]] [write_pipe_handler] (0x0400): All data has been sent! (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [child_sig_handler] (0x0100): child [19778] finished successfully. (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [read_pipe_handler] (0x0400): EOF received, client finished (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'mripa1.mr.ric' as 'working' (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [set_server_common_status] (0x0100): Marking server 'mripa1.mr.ric' as 'working' (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'mripa1.mr.ric' as 'working' (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success] (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sent result [0][mr.ric] (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 19776 (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [sdap_access_send] (0x0400): Performing access check for user [qchang] (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user [qchang] (Wed Apr 15 10:22:32 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 10:22:32 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [sdap_x_deref_search_send] (0x0400): Dereferencing entry [fqdn=mripadm.mr.ric,cn=computers,cn=accounts,d c=mr,dc=ric] using OpenLDAP deref (Wed Apr 15 10:22:32 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][fqdn=mripadm.mr.ric,cn=co mputers,cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_x_deref_parse_entry] (0x0400): Got deref control (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_x_deref_parse_entry] (0x0400): All deref results from a single control parsed (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_hostgroup_info_done] (0x0200): Dereferenced host group: mr-server-centos (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_hostgroup_info_done] (0x0200): Dereferenced host group: mr-nix (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_hbac_service_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mr,dc=ric][2][( objectClass=ipaHBACService)] (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACService)][cn=hba c,dc=mr,dc=ric]. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_hbac_servicegroup_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mr,dc=ric] [2][(objectClass=ipaHBACServiceGroup)] (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACServiceGroup)][c n=hbac,dc=mr,dc=ric]. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_hbac_rule_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mr,dc=ric][2][(&(o bjectclass=ipaHBACRule)(ipaenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=mripadm.mr.ric,cn=computers,cn=accounts,dc=mr,dc=ric)(memberHost=cn=m r-server-centos,cn=hostgroups,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=hostgroups,c n=accounts,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorules,cn=s udo,dc=mr,dc=ric)))] (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaHBACRule)(ipaenabl edflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=mripadm.mr.ric,cn=computers,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=hostgroups,cn =accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=hostgroups,cn=accounts,dc=mr,dc=ric)(memberH ost=cn=mr-nix,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric)))][cn=hbac,dc= mr,dc=ric]. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [hbac_shost_attrs_to_rule] (0x0400): Processing source hosts for rule [allow_all] (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [allow_all] (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success] (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_get_selinux_send] (0x0400): Retrieving SELinux user mapping (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ipaConfig)(objectClass=ipaGuiC onfig))][cn=etc,dc=mr,dc=ric]. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_selinux_get_maps_next] (0x0400): Trying to fetch SELinux maps with following parameters: [2][(&(obj ectclass=ipaselinuxusermap)(ipaEnabledFlag=TRUE))][cn=selinux,dc=mr,dc=ric] (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaselinuxusermap)(ip aEnabledFlag=TRUE))][cn=selinux,dc=mr,dc=ric]. (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [ipa_selinux_get_maps_done] (0x0400): No SELinux user maps found! (Wed Apr 15 10:22:33 2015) [sssd[be[mr.ric]]] [write_pipe_handler] (0x0400): All data has been sent! (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x1003][1][name=avahi] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=avahi)(objectclass=posixAccou nt)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [acctinfo_callback] (0x0100): Request processed. Returned 3,0,Account info lookup failed (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x1003][1][name=polkitd] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=polkitd)(objectclass=posixAcc ount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [acctinfo_callback] (0x0100): Request processed. Returned 3,0,Account info lookup failed (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [child_sig_handler] (0x0100): child [19779] finished successfully. (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [read_pipe_handler] (0x0400): EOF received, client finished (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, Success) [Success] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sent result [0][mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_SETCRED (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 19776 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 19776 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_SETCRED (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 0 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 19785 (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 10:22:34 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 10:25:01 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=pcp] -----
On 04/15/2015 10:23 AM, Lukas Slebodnik wrote:
On (15/04/15 10:03), tmpchq wrote:
I did set log level to 10 for domain section too. It did not log anything around the gap shown in sssd_nss and sssd_pam.
I am going to do a test again and post the logs.
If there is a gap then you can take a look to logs in journald. There can be problem with other services.
LS _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
On (15/04/15 10:37), tmpchq wrote:
It was my mistake, I missed [domain] section. Below is at log level 6:
It spent time on checking for SELinux mapping, avahi and polkitd.
SELinux mapping should not be checked if you set "selinux_provider=none" Some patches which improve speed caused by SELinux integration in ipa provider were pushed to upstream.
You can test with snapshot of 1.12 branch https://copr.fedoraproject.org/coprs/lslebodn/sssd-1-12-latest/
The initgroups was called for avahi and polkitd. It cannot be filtered out with options filter_users, filter_groups but it should not take a long time unless there is a problem with network.
It would be good to add add microseconds to the timestamp. add "debug_microseconds = true" to domain section.
LS
I noticed that when login to IPA server (mripa1) itself, the only PAM process is PAM_OPEN_SESSION, whereas for mripadm it goes through 5: PAM_AUTHENTICATE, PAM_ACCT_MGMT, PAM_SETCRED, PAM_OPEN_SESSION, PAM_SETCRED in that order. I have virtually identical SSSD and PAM config for both servers...
Microsecond enabled: ----- sssd_mr.ric.log ----- On 04/15/2015 02:08 PM, Lukas Slebodnik wrote:(Wed Apr 15 14:19:44:106338 2015) [sssd[be[mr.ric]]] [be_get_account_info] (0x0200): Got request for [0x3][1][name=qchang] (Wed Apr 15 14:19:44:106368 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 14:19:44:106657 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:44:106713 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:44:106761 2015) [sssd[be[mr.ric]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 14:19:44:106789 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=qchang)(objectclass=po sixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:44:110469 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:44:110561 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Save user (Wed Apr 15 14:19:44:110596 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 14:19:44:110610 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Processing user qchang (Wed Apr 15 14:19:44:110623 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:44:110639 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [qchang]. (Wed Apr 15 14:19:44:110656 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Adding user principal [qchang@MR.RIC] to attributes of [qchang]. (Wed Apr 15 14:19:44:110730 2015) [sssd[be[mr.ric]]] [sdap_save_user] (0x0400): Storing info for user qchang (Wed Apr 15 14:19:44:113458 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 14:19:44:113493 2015) [sssd[be[mr.ric]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Apr 15 14:19:44:113515 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(objectClass=ipaUserGroup )(objectClass=posixGroup))(cn=*))][cn=ipausers,cn=groups,cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:44:114852 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:44:114889 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(objectClass=ipaUserGroup )(objectClass=posixGroup))(cn=*))][ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric]. (Wed Apr 15 14:19:44:115455 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:44:115484 2015) [sssd[be[mr.ric]]] [sdap_initgr_nested_search] (0x0040): Search for group ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29 f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric, returned 0 results. Skipping (Wed Apr 15 14:19:44:115662 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object ipausers (Wed Apr 15 14:19:44:115854 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:44:115891 2015) [sssd[be[mr.ric]]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 14:19:44:115916 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(gidNumber=10001)(|(objectC lass=ipaUserGroup)(objectClass=posixGroup))(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:44:117467 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:44:117500 2015) [sssd[be[mr.ric]]] [sdap_get_groups_process] (0x0400): Search for groups, returned 1 results. (Wed Apr 15 14:19:44:117529 2015) [sssd[be[mr.ric]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP (Wed Apr 15 14:19:44:117543 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:44:117571 2015) [sssd[be[mr.ric]]] [sdap_nested_group_recv] (0x0400): 0 users found in the hash table (Wed Apr 15 14:19:44:117587 2015) [sssd[be[mr.ric]]] [sdap_nested_group_recv] (0x0400): 1 groups found in the hash table (Wed Apr 15 14:19:44:117654 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 14:19:44:117672 2015) [sssd[be[mr.ric]]] [sdap_save_group] (0x0400): Processing group qchang (Wed Apr 15 14:19:44:117683 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:44:117720 2015) [sssd[be[mr.ric]]] [sdap_process_ghost_members] (0x0400): The group has 0 members (Wed Apr 15 14:19:44:117745 2015) [sssd[be[mr.ric]]] [sdap_process_ghost_members] (0x0400): Group has 0 members (Wed Apr 15 14:19:44:117759 2015) [sssd[be[mr.ric]]] [sdap_save_group] (0x0400): Storing info for group qchang (Wed Apr 15 14:19:44:118029 2015) [sssd[be[mr.ric]]] [sdap_get_primary_name] (0x0400): Processing object qchang (Wed Apr 15 14:19:44:118049 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem] (0x0400): Processing group qchang (Wed Apr 15 14:19:44:118060 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem] (0x0400): Failed to get group sid (Wed Apr 15 14:19:44:118071 2015) [sssd[be[mr.ric]]] [sdap_save_grpmem] (0x0400): No members for group [qchang] (Wed Apr 15 14:19:44:120176 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnc hor)(ipaAnchorUUID=:IPA:mr.ric:4b2724aa-d87d-11e4-93fa-000c29f4de6e))][cn=Default Trust View,cn=views,cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:44:120787 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: No such object(32), no errmsg set (Wed Apr 15 14:19:44:121356 2015) [sssd[be[mr.ric]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success (Wed Apr 15 14:19:44:122127 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (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 (Wed Apr 15 14:19:45:169926 2015) [sssd[be[mr.ric]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'mripa1.mr.ric' as 'working' (Wed Apr 15 14:19:45:169953 2015) [sssd[be[mr.ric]]] [set_server_common_status] (0x0100): Marking server 'mripa1.mr.ric' as 'working' (Wed Apr 15 14:19:45:169973 2015) [sssd[be[mr.ric]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'mripa1.mr.ric' as 'working' (Wed Apr 15 14:19:45:221211 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success] (Wed Apr 15 14:19:45:221242 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 14:19:45:221325 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sent result [0][mr.ric] (Wed Apr 15 14:19:45:225865 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (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 (Wed Apr 15 14:19:46:176128 2015) [sssd[be[mr.ric]]] [ipa_hostgroup_info_done] (0x0200): Dereferenced host group: mr-server-centos (Wed Apr 15 14:19:46:176152 2015) [sssd[be[mr.ric]]] [ipa_hostgroup_info_done] (0x0200): Dereferenced host group: mr-nix (Wed Apr 15 14:19:46:176201 2015) [sssd[be[mr.ric]]] [ipa_hbac_service_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mr,dc=ri c][2][(objectClass=ipaHBACService)] (Wed Apr 15 14:19:46:176230 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACService)] [cn=hbac,dc=mr,dc=ric]. (Wed Apr 15 14:19:46:184539 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:46:184615 2015) [sssd[be[mr.ric]]] [ipa_hbac_servicegroup_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mr, dc=ric][2][(objectClass=ipaHBACServiceGroup)] (Wed Apr 15 14:19:46:184644 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACServiceGr oup)][cn=hbac,dc=mr,dc=ric]. (Wed Apr 15 14:19:46:186319 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:46:186443 2015) [sssd[be[mr.ric]]] [ipa_hbac_rule_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mr,dc=ric][ 2][(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=mripadm.mr.ric,cn=computers,cn=accounts,dc=mr,dc=ric)(memberHo st=cn=mr-server-centos,cn=hostgroups,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=hostg roups,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorul es,cn=sudo,dc=mr,dc=ric)))] (Wed Apr 15 14:19:46:186478 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaHBACRule)(i paenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=mripadm.mr.ric,cn=computers,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=hostgr oups,cn=accounts,dc=mr,dc=ric)(memberHost=cn=mr-server-centos,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=cn=mr-nix,cn=hostgroups,cn=accounts,dc=mr,dc=ric)( memberHost=cn=mr-nix,cn=ng,cn=alt,dc=mr,dc=ric)(memberHost=ipaUniqueID=34bb1bba-de25-11e4-b4e1-000c29f4de6e,cn=sudorules,cn=sudo,dc=mr,dc=ric)))][cn=h bac,dc=mr,dc=ric]. (Wed Apr 15 14:19:46:189436 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:46:204453 2015) [sssd[be[mr.ric]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Apr 15 14:19:46:204485 2015) [sssd[be[mr.ric]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Apr 15 14:19:46:204499 2015) [sssd[be[mr.ric]]] [hbac_get_category] (0x0200): Category is set to 'all'. (Wed Apr 15 14:19:46:204511 2015) [sssd[be[mr.ric]]] [hbac_shost_attrs_to_rule] (0x0400): Processing source hosts for rule [allow_all] (Wed Apr 15 14:19:46:204716 2015) [sssd[be[mr.ric]]] [ipa_hbac_evaluate_rules] (0x0080): Access granted by HBAC rule [allow_all] (Wed Apr 15 14:19:46:204747 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success] (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] (Wed Apr 15 14:19:47:557553 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:47:557575 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:47:557592 2015) [sssd[be[mr.ric]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 14:19:47:557604 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=avahi)(objectclass=pos ixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:47:568772 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:47:568858 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Apr 15 14:19:47:568979 2015) [sssd[be[mr.ric]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Wed Apr 15 14:19:47:569042 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (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:570512 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 14:19:47:570590 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:47:570608 2015) [sssd[be[mr.ric]]] [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse domain SID from [(null)] (Wed Apr 15 14:19:47:570617 2015) [sssd[be[mr.ric]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=mr,dc=ric] (Wed Apr 15 14:19:47:570626 2015) [sssd[be[mr.ric]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=polkitd)(objectclass=p osixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=mr,dc=ric]. (Wed Apr 15 14:19:47:581734 2015) [sssd[be[mr.ric]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Apr 15 14:19:47:581814 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (Wed Apr 15 14:19:47:581873 2015) [sssd[be[mr.ric]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Wed Apr 15 14:19:47:581929 2015) [sssd[be[mr.ric]]] [sysdb_search_by_name] (0x0400): No such entry (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 (Wed Apr 15 14:19:47:801991 2015) [sssd[be[mr.ric]]] [child_sig_handler] (0x0100): child [28333] finished successfully. (Wed Apr 15 14:19:47:802026 2015) [sssd[be[mr.ric]]] [read_pipe_handler] (0x0400): EOF received, client finished (Wed Apr 15 14:19:47:802052 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, Success) [Success] (Wed Apr 15 14:19:47:802063 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 14:19:47:802120 2015) [sssd[be[mr.ric]]] [be_pam_handler_callback] (0x0100): Sent result [0][mr.ric] (Wed Apr 15 14:19:47:809548 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 14:19:47:809567 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 14:19:47:809576 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_SETCRED (Wed Apr 15 14:19:47:809583 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 14:19:47:809590 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 14:19:47:809598 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 14:19:47:809605 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 14:19:47:809618 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 14:19:47:809627 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 14:19:47:809634 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 14:19:47:809641 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 14:19:47:809649 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 14:19:47:809656 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 28330 (Wed Apr 15 14:19:47:809663 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 14:19:47:809671 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 14:19:47:922194 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 14:19:47:922216 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 14:19:47:922225 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_OPEN_SESSION (Wed Apr 15 14:19:47:922233 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 14:19:47:922241 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 14:19:47:922249 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 14:19:47:922257 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 14:19:47:922265 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 14:19:47:922273 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 14:19:47:922281 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 14:19:47:922289 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 14:19:47:922297 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 1 (Wed Apr 15 14:19:47:922305 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 28330 (Wed Apr 15 14:19:47:922313 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 14:19:47:922321 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Sending result [0][mr.ric] (Wed Apr 15 14:19:47:926678 2015) [sssd[be[mr.ric]]] [be_req_set_domain] (0x0400): Changing request domain from [mr.ric] to [mr.ric] (Wed Apr 15 14:19:47:926712 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Got request with the following data (Wed Apr 15 14:19:47:926746 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): command: PAM_SETCRED (Wed Apr 15 14:19:47:926757 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): domain: mr.ric (Wed Apr 15 14:19:47:926765 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): user: qchang (Wed Apr 15 14:19:47:926773 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): service: sshd (Wed Apr 15 14:19:47:926781 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): tty: ssh (Wed Apr 15 14:19:47:926788 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): ruser: (Wed Apr 15 14:19:47:926796 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): rhost: 172.25.12.157 (Wed Apr 15 14:19:47:926804 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): authtok type: 0 (Wed Apr 15 14:19:47:926812 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): newauthtok type: 0 (Wed Apr 15 14:19:47:926820 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): priv: 0 (Wed Apr 15 14:19:47:926827 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): cli_pid: 28339 (Wed Apr 15 14:19:47:926835 2015) [sssd[be[mr.ric]]] [pam_print_data] (0x0100): logon name: not set (Wed Apr 15 14:19:47:926843 2015) [sssd[be[mr.ric]]] [be_pam_handler] (0x0100): Sending result [0][mr.ric] -----
On (15/04/15 10:37), tmpchq wrote:
It was my mistake, I missed [domain] section. Below is at log level 6:
It spent time on checking for SELinux mapping, avahi and polkitd.
SELinux mapping should not be checked if you set "selinux_provider=none" Some patches which improve speed caused by SELinux integration in ipa provider were pushed to upstream.
You can test with snapshot of 1.12 branch https://copr.fedoraproject.org/coprs/lslebodn/sssd-1-12-latest/
The initgroups was called for avahi and polkitd. It cannot be filtered out with options filter_users, filter_groups but it should not take a long time unless there is a problem with network.
It would be good to add add microseconds to the timestamp. add "debug_microseconds = true" to domain section.
LS _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
On Wed, Apr 15, 2015 at 02:36:32PM -0400, tmpchq wrote:
I noticed that when login to IPA server (mripa1) itself, the only PAM process is PAM_OPEN_SESSION, whereas for mripadm it goes through 5: PAM_AUTHENTICATE, PAM_ACCT_MGMT, PAM_SETCRED, PAM_OPEN_SESSION, PAM_SETCRED in that order. I have virtually identical SSSD and PAM config for both servers...
how exactly did you login? In the case where only session was called, did you maybe su from root or ssh-ed with GSSAPI? Both cases bypass SSSD..
I was ssh'ing with with password authentication.
On 04/15/2015 02:46 PM, Jakub Hrozek wrote:
On Wed, Apr 15, 2015 at 02:36:32PM -0400, tmpchq wrote:
I noticed that when login to IPA server (mripa1) itself, the only PAM process is PAM_OPEN_SESSION, whereas for mripadm it goes through 5: PAM_AUTHENTICATE, PAM_ACCT_MGMT, PAM_SETCRED, PAM_OPEN_SESSION, PAM_SETCRED in that order. I have virtually identical SSSD and PAM config for both servers...
how exactly did you login? In the case where only session was called, did you maybe su from root or ssh-ed with GSSAPI? Both cases bypass SSSD.. _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
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
----- 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] -----
----- 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 -----
On Wed, Apr 15, 2015 at 2:36 PM, tmpchq tmpchq@gmail.com wrote:
I noticed that when login to IPA server (mripa1) itself, the only PAM process is PAM_OPEN_SESSION, whereas for mripadm it goes through 5: PAM_AUTHENTICATE, PAM_ACCT_MGMT, PAM_SETCRED, PAM_OPEN_SESSION, PAM_SETCRED in that order. I have virtually identical SSSD and PAM config for both servers...
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
sssd-users@lists.fedorahosted.org
-
Dmitri Pal -
Jakub Hrozek -
Janelle -
Lukas Slebodnik -
Pavel Reichl -
Qing Chang