[Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)

Jakub Hrozek jhrozek at redhat.com
Tue Apr 7 09:21:45 UTC 2015 

On Tue, Apr 07, 2015 at 11:12:40AM +0200, Martin (Lists) wrote:
> Am 05.04.2015 um 11:51 schrieb Martin (Lists):
> > 
> > Hallo
> > 
> > I have a similar issue. On login (graphic systems and ssh) and on the
> > screen saver I have a delay from about 2 secons to 10 seconds.
> > 
> > According to my logfile i have the following timeline at login:
> > 
> > 0	pam_unix (auth)
> > 3	pam_sss (auth)
> > 3	pam_kwallet (sddm:auth)
> > 4	pam_kwallet (sddm:setcred)
> > 5	pam_unix (session)
> > 
> > First collum is the number of seconds after the first action. On myl old
> > server I had a pure kerberos (handmade) system, which reacted almost
> > instandly.
> > 
> > Regards
> > Martin
> > 
> Hallo
> 
> I enabled debugging (set to level 6). selinux provider is set to none.
> During a login I got data accorting to my attachment.
> 
> Regards
> Martin

If that's all the data, then the login seems quite fast (3 seconds).
The slowdown seems to happen when the krb5 provider is initializing the
krb5 ccache for the user. krb5_child.log with a high debug level would
show what's happening in particular.

> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_req_set_domain] (0x0400): Changing request domain from [mittelerde.de] to [mittelerde.de]
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_pam_handler] (0x0100): Got request with the following data
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): domain: mittelerde.de
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): user: frodo
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): service: sddm
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): tty:
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): ruser:
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): rhost:
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): authtok type: 1
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): newauthtok type: 0
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): priv: 1
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): cli_pid: 6409
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): logon name: not set
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_resolve_server_process] (0x0200): Found address for server gandalf.mittelerde.de: [10.2.33.5] TTL 1200
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://gandalf.mittelerde.de'
> (Tue Apr  7 10:52:38 2015) [sssd[be[mittelerde.de]]] [write_pipe_handler] (0x0400): All data has been sent!

Here we sent data to krb5_child

> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [child_sig_handler] (0x0100): child [6410] finished successfully.

Here the krb5_child process finished

> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [read_pipe_handler] (0x0400): EOF received, client finished
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'gandalf.mittelerde.de' as 'working'
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [set_server_common_status] (0x0100): Marking server 'gandalf.mittelerde.de' as 'working'
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'gandalf.mittelerde.de' as 'working'
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) [Success]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Sending result [0][mittelerde.de]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Sent result [0][mittelerde.de]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_req_set_domain] (0x0400): Changing request domain from [mittelerde.de] to [mittelerde.de]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler] (0x0100): Got request with the following data
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): domain: mittelerde.de
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): user: frodo
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): service: sddm
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): tty:
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): ruser:
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): rhost:
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): authtok type: 0
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): newauthtok type: 0
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): priv: 1
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): cli_pid: 6409
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): logon name: not set
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_access_send] (0x0400): Performing access check for user [frodo]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_account_expired_rhds] (0x0400): Performing RHDS access check for user [frodo]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=kate.mittelerde.de))][cn=accounts,dc=mittelerde,dc=de].
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_x_deref_search_send] (0x0400): Dereferencing entry [fqdn=kate.mittelerde.de,cn=computers,cn=accounts,dc=mittelerde,dc=de] using OpenLDAP deref
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][fqdn=kate.mittelerde.de,cn=computers,cn=accounts,dc=mittelerde,dc=de].
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_x_deref_parse_entry] (0x0400): Got deref control
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_x_deref_parse_entry] (0x0400): All deref results from a single control parsed
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [ipa_hostgroup_info_done] (0x0200): Dereferenced host group: work-pc
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [ipa_hbac_service_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mittelerde,dc=de][2][(objectClass=ipaHBACService)]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACService)][cn=hbac,dc=mittelerde,dc=de].
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [ipa_hbac_servicegroup_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mittelerde,dc=de][2][(objectClass=ipaHBACServiceGroup)]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectClass=ipaHBACServiceGroup)][cn=hbac,dc=mittelerde,dc=de].
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [ipa_hbac_rule_info_next] (0x0400): Sending request for next search base: [cn=hbac,dc=mittelerde,dc=de][2][(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=kate.mittelerde.de,cn=computers,cn=accounts,dc=mittelerde,dc=de)(memberHost=cn=work-pc,cn=hostgroups,cn=accounts,dc=mittelerde,dc=de)(memberHost=cn=work-pc,cn=ng,cn=alt,dc=mittelerde,dc=de)))]
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectclass=ipaHBACRule)(ipaenabledflag=TRUE)(|(hostCategory=all)(memberHost=fqdn=kate.mittelerde.de,cn=computers,cn=accounts,dc=mittelerde,dc=de)(memberHost=cn=work-pc,cn=hostgroups,cn=accounts,dc=mittelerde,dc=de)(memberHost=cn=work-pc,cn=ng,cn=alt,dc=mittelerde,dc=de)))][cn=hbac,dc=mittelerde,dc=de].
> (Tue Apr  7 10:52:41 2015) [sssd[be[mittelerde.de]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
> -- 
> Manage your subscription for the Freeipa-users mailing list:
> https://www.redhat.com/mailman/listinfo/freeipa-users
> Go to http://freeipa.org for more info on the project

More information about the Freeipa-users mailing list