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

Martin (Lists) lists at fahrendorf.de
Tue Apr 7 15:57:49 UTC 2015 

Hallo

attached you can find the data from krb_child.log. As far as I can see
it, the three seconds are due to the communication with the kerberos
server. (1.2.3.4 is my server).

regards
Martin

Am 07.04.2015 um 11:21 schrieb Jakub Hrozek:
> 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
>

-------------- next part --------------
A non-text attachment was scrubbed...
Name: krb5_child.log
Type: text/x-log
Size: 19601 bytes
Desc: not available
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20150407/1ff600aa/attachment.bin>

More information about the Freeipa-users mailing list