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(a)mr.ric]
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f8a5b56cc60][20]
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f8a5b56cc60][20]
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0400):
>>> Running
>>> command [17] with input [qchang].
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sss_parse_name_for_domains]
>>> (0x0200): name 'qchang' matched without domain, user is qchang
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0100):
>>> Requesting info for [qchang] from [<ALL>]
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [sss_ncache_check_str]
>>> (0x2000):
>>> Checking negative cache for [NCE/USER/mr.ric/qchang]
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getpwnam_search]
>>> (0x0100):
>>> Requesting info for [qchang(a)mr.ric]
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed
>>> event
>>> "ltdb_callback": 0x7f8a5b56c920
>>>
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Added timed
>>> event
>>> "ltdb_timeout": 0x7f8a5b574840
>>>
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Running
>>> timer event
>>> 0x7f8a5b56c920 "ltdb_callback"
>>>
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Destroying
>>> timer
>>> event 0x7f8a5b574840 "ltdb_timeout"
>>>
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [ldb] (0x4000): Ending timer
>>> event
>>> 0x7f8a5b56c920 "ltdb_callback"
>>>
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [check_cache] (0x0400):
>>> Cached entry
>>> is valid, returning..
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [nss_cmd_getpwnam_search]
>>> (0x0400):
>>> Returning info for user [qchang(a)mr.ric]
>>> (Tue Apr 14 13:05:06 2015) [sssd[nss]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f8a5b56cc60][20]
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [get_client_cred] (0x4000):
>>> Client
>>> creds: euid[81] egid[81] pid[503].
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f8a5b574840][21]
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [accept_fd_handler]
>>> (0x0400): Client
>>> connected!
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f8a5b574840][21]
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_cmd_get_version] (0x0200):
>>> Received client version [1].
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_cmd_get_version] (0x0200):
>>> Offered version [1].
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f8a5b574840][21]
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f8a5b574840][21]
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0400):
>>> Running
>>> command [38] with input [root].
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_parse_name_for_domains]
>>> (0x0200): name 'root' matched without domain, user is root
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_getbynam] (0x0100):
>>> Requesting info for [root] from [<ALL>]
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [sss_ncache_check_str]
>>> (0x2000):
>>> Checking negative cache for [NCE/USER/mr.ric/root]
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_initgroups_search]
>>> (0x0400):
>>> User [root] does not exist in [mr.ric]! (negative cache)
>>> (Tue Apr 14 13:05:08 2015) [sssd[nss]] [nss_cmd_initgroups_search]
>>> (0x0080):
>>> No matching domain found for [root], fail!
>>> -----
>>> ----- sssd_pam.log -----
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_check_user_search]
>>> (0x0400):
>>> Returning info for user [qchang(a)mr.ric]
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_dp_send_req] (0x0100):
>>> Sending
>>> request with the following data:
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> command:
>>> PAM_ACCT_MGMT
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> domain:
>>> mr.ric
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> user:
>>> qchang
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> service:
>>> sshd
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> tty: ssh
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> ruser: not
>>> set
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> rhost:
>>> 172.25.12.157
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> authtok
>>> type: 0
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> newauthtok
>>> type: 0
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> priv: 1
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> cli_pid:
>>> 7402
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> logon
>>> name: qchang
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [sbus_add_timeout] (0x2000):
>>> 0x7f1aff4200a0
>>> (Tue Apr 14 13:05:06 2015) [sssd[pam]] [pam_dom_forwarder] (0x0100):
>>> pam_dp_send_req returned 0
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sbus_remove_timeout] (0x2000):
>>> 0x7f1aff4200a0
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sbus_dispatch] (0x4000):
>>> dbus conn:
>>> 0x7f1aff41ddd0
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sbus_dispatch] (0x4000):
>>> Dispatching.
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_dp_process_reply]
>>> (0x0100):
>>> received: [0][mr.ric]
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_reply] (0x0200): pam_reply
>>> called with result [0].
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_reply] (0x0200): blen: 23
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f1aff421b40][19]
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [reset_idle_timer] (0x4000):
>>> Idle
>>> timer re-set for client [0x7f1aff421b40][19]
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_cmd_setcred] (0x0100):
>>> entering
>>> pam_cmd_setcred
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sss_parse_name_for_domains]
>>> (0x0200): name 'qchang' matched without domain, user is qchang
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> command:
>>> PAM_SETCRED
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> domain:
>>> not set
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> user:
>>> qchang
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> service:
>>> sshd
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> tty: ssh
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> ruser: not
>>> set
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> rhost:
>>> 172.25.12.157
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> authtok
>>> type: 0
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> newauthtok
>>> type: 0
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> priv: 1
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> cli_pid:
>>> 7402
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [pam_print_data] (0x0100):
>>> logon
>>> name: qchang
>>> (Tue Apr 14 13:05:08 2015) [sssd[pam]] [sss_ncache_check_str]
>>> (0x2000):
>>> Checking negative cache for [NCE/USER/mr.ric/qchang]
>>> -----
>> 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(a)lists.fedorahosted.org
>>
https://lists.fedorahosted.org/mailman/listinfo/sssd-users
>
> _______________________________________________
> sssd-users mailing list
> sssd-users(a)lists.fedorahosted.org
>
https://lists.fedorahosted.org/mailman/listinfo/sssd-users
_______________________________________________
sssd-users mailing list
sssd-users(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-users