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