[Freeipa-users] slow login with freeipa 4.2.0

Jakub Hrozek jhrozek at redhat.com
Fri Jul 29 11:40:28 UTC 2016 

On Tue, Jul 26, 2016 at 06:07:10PM +0530, Rakesh Rajasekharan wrote:
> > Any change that it's running on a VM? If so, check your entropy:
> 
> > cat /proc/sys/kernel/random/entropy_avail
> 
> > If it's low (like < 1k), install haveged.
> 
> this indeed is vm , am running it on azure . However, I have a similar set
> up running on aws which works completely fine

Sorry about the delay in replying..

> 
> The entropy was low, around 180, I installed haveged and now its above 3k
> cat /proc/sys/kernel/random/entropy_avail
> 3178
> 
> The timing though is still the same around 19s

I have some comments inline about the config and logs.

> 
> @jakub, i am reattaching the logs.
> 
> The dns resoltion seems fast when I check using dig
> 
> below is my sssd.conf
> [domain/xyz.com]
> selinux_provider=none
> krb5_auth_timeout = 20
> cache_credentials = True
> krb5_store_password_if_offline = True
> ipa_domain = xyz.com
> id_provider = ipa
> auth_provider = ipa
> access_provider = ipa
> ldap_tls_cacert = /etc/ipa/ca.crt
> ipa_hostname = 10.65.16.4

The ipa_hostname value is wrong. It's meant for systems where hostname
reports a different name that what is the name the host is registered as
in IPA. Including an IP address there doesn't make much sense.

> chpass_provider = ipa
> ipa_server = ipa-master-in.xyz.com
> dns_discovery_domain = xyz.com
> ignore_group_members=True
> ldap_purge_cache_timeout = 0
> debug_level=8
> [sssd]
> services = nss, sudo, pam, ssh
> config_file_version = 2
> 
> domains = xyz.com
> [nss]
> homedir_substring = /home
> 
> [pam]
> pam_id_timeout = 3
> 
> [sudo]
> 
> [autofs]
> 
> [ssh]
> 
> [pac]
> 
> [ifp]
> 
> 
> 
> And here is the login times and logs
> 
> [root at ipa-client-1 :~] date;ssh testuser at localhost
> Tue Jul 26 12:06:37 UTC 2016
> testuser at localhost's password:
> Last login: Tue Jul 26 12:03:53 2016 from 127.0.0.1
> [testuser at ipa-client-1 :~] date
> Tue Jul 26 12:06:55 UTC 2016
> 
> 
> sssd_domain logs
> 
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method
> org.freedesktop.sssd.dataprovider.getAccountInfo on path
> /org/freedesktop/sssd/dataprovider
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [be_get_account_info]
> (0x0200): Got request for [0x3][1][name=testuser]
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]]
> [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> domain SID from [(null)]
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]]
> [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> domain SID from [(null)]
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sdap_get_initgr_next_base]
> (0x0400): Searching for users with base [cn=accounts,dc=xyz,dc=com]

--> A request for user's groups arrived.

> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sdap_print_server]
> (0x2000): Searching 10.65.16.4
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sdap_get_generic_ext_step]
> (0x0400): calling ldap_search_ext with
> [(&(uid=testuser)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=xyz,dc=com].
> (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sdap_get_generic_ext_step]
> (0x1000): Requesting attrs: [objectClass]

[...]

> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [acctinfo_callback]
> (0x0100): Request processed. Returned 0,0,Success (Success)

---> Here the request for user's groups finished. It took about a second
in total.

> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler
> on path /org/freedesktop/sssd/dataprovider
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler] (0x0100):
> Got request with the following data
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [pam_print_data] (0x0100):
> command: SSS_PAM_PREAUTH

Preauthentication checks for available login methods...

> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Sending result [0][xyz.com]
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Sent result [0][xyz.com]

---> Here the preauth request finished, within a second.

> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler
> on path /org/freedesktop/sssd/dataprovider
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler] (0x0100):
> Got request with the following data
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [pam_print_data] (0x0100):
> command: PAM_AUTHENTICATE

---> Authentication request is recieved.

> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [krb5_auth_queue_done]
> (0x1000): krb5_auth_queue request [0x7f88d1142ab0] done.
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Sending result [0][xyz.com]
> (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Sent result [0][xyz.com]

Here the authentication finished successfully, again within a second..

> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method org.freedesktop.sssd.service.ping on path
> /org/freedesktop/sssd/service
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler
> on path /org/freedesktop/sssd/dataprovider
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler] (0x0100):
> Got request with the following data
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [pam_print_data] (0x0100):
> command: PAM_ACCT_MGMT

---> Access control request is received

> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [ipa_hbac_evaluate_rules]
> (0x0080): Access granted by HBAC rule [allow_all]
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]

--> User is granted access, we're within two seconds from the first
request, still.

> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0400): SELinux provider doesn't exist, not sending the request to it.
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Sending result [0][xyz.com]
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> (0x0100): Sent result [0][xyz.com]

--> The selinux provider is disabled and quits immediately.

> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [pam_print_data] (0x0100):
> command: PAM_SETCRED
> (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler] (0x0100):
> Sending result [0][xyz.com]

--> The setred PAM target does nothing, just returns success.

...And there nothing happens for 10 seconds, at least not in this log.
Is there any activity in the other SSSD logs in the meantime?

> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method org.freedesktop.sssd.service.ping on path
> /org/freedesktop/sssd/service
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method
> org.freedesktop.sssd.dataprovider.getAccountInfo on path
> /org/freedesktop/sssd/dataprovider
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [be_get_account_info]
> (0x0200): Got request for [0x3][1][name=testuser]
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]]
> [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> domain SID from [(null)]
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]]
> [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> domain SID from [(null)]
> (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sdap_get_initgr_next_base]
> (0x0400): Searching for users with base [cn=accounts,dc=xyz,dc=com]

...Until a request for user groups arrives here..

> (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [acctinfo_callback]
> (0x0100): Request processed. Returned 0,0,Success (Success)

---> Is processed here.

> (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler
> on path /org/freedesktop/sssd/dataprovider
> (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> (0x2000): Not a sysbus message, quit
> (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [be_pam_handler] (0x0100):
> Got request with the following data
> (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [pam_print_data] (0x0100):
> command: PAM_OPEN_SESSION

And the session for the user is opened here.

So my conclusion from the logs is that the delay is not within SSSD. The
next things I would check are:
    - are there any other NSS modules in nsswitch.conf except sss and
      files?
    - is there any other PAM module in the PAM stack except pam_sss.so
      and pam_unix and those that you would expect after IPA client
      installation?
    - is there anything in syslog/journal?
    - if you increase the SSHD debug level, is there anything of
      interest in the SSHD log?
    - if you strace sshd (make sure to strace the child processes also
      and include the -tt flag to see the timestamps with a high
      resultion), do you see any delay there?

More information about the Freeipa-users mailing list