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 >
(Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [main] (0x0400): krb5_child started. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [unpack_buffer] (0x1000): total buffer size: [146] (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [unpack_buffer] (0x0100): cmd [241] uid [1101] gid [1101] validate [true] enterprise principal [false] offline [false] UPN [[email protected]] (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:1101] old_ccname: [KEYRING:persistent:1101] keytab: [/etc/krb5.keytab] (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [switch_creds] (0x0200): Switch user to [1101][1101]. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [switch_creds] (0x0200): Switch user to [0][0]. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:1101] and is not active and TGT is valid. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [k5c_setup_fast] (0x0100): SSSD_KRB5_FAST_PRINCIPAL is set to [host/[email protected]] (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/[email protected] in keytab. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [match_principal] (0x1000): Principal matched to the sample (host/[email protected]). (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [become_user] (0x0200): Trying to become user [1101][1101]. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [main] (0x2000): Running as [1101][1101]. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [k5c_setup] (0x2000): Running as [1101][1101]. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment. (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true] (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [main] (0x0400): Will perform online auth (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [MITTELERDE.DE] (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406985.752891: Getting initial credentials for [email protected] (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406985.753029: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406985.753088: Retrieving host/[email protected] -> krb5_ccache_conf_data/fast_avail/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE with result: -1765328243/Matching credential not found (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406985.753158: Sending request (170 bytes) to MITTELERDE.DE (Tue Apr 7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406985.753452: Sending initial UDP request to dgram 1.2.3.4:88 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735246: Received answer (345 bytes) from dgram 1.2.3.4:88 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735345: Response was from master KDC (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735386: Received error from KDC: -1765328359/Additional pre-authentication required (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735426: Upgrading to FAST due to presence of PA_FX_FAST in reply (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735443: Restarting to upgrade to FAST (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735467: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735511: Retrieving host/[email protected] -> krb5_ccache_conf_data/fast_avail/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE with result: -1765328243/Matching credential not found (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735530: Upgrading to FAST due to presence of PA_FX_FAST in reply (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735545: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735574: Retrieving host/[email protected] -> krb5_ccache_conf_data/fast_avail/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE with result: -1765328243/Matching credential not found (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735600: Getting credentials host/[email protected] -> krbtgt/[email protected] using ccache MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735650: Retrieving host/[email protected] -> krbtgt/[email protected] from MEMORY:/var/lib/sss/db/fast_ccache_MITTELERDE.DE with result: 0/Success (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735699: Armor ccache sesion key: aes256-cts/DC52 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735762: Creating authenticator for host/[email protected] -> krbtgt/[email protected], seqnum 0, subkey aes256-cts/19F8, session key aes256-cts/DC52 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735889: FAST armor key: aes256-cts/F03B (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.735936: Encoding request body and padata into FAST request (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.736050: Sending request (1009 bytes) to MITTELERDE.DE (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.736132: Sending initial UDP request to dgram 1.2.3.4:88 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.742484: Received answer (634 bytes) from dgram 1.2.3.4:88 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.742564: Response was from master KDC (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.742600: Received error from KDC: -1765328359/Additional pre-authentication required (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.742620: Decoding FAST response (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.742709: Processing preauth types: 136, 19, 138, 133, 137 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.742750: Selected etype info: etype aes256-cts, salt "***", params "" (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.742770: Received cookie: MIT (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.758719: Preauth module encrypted_challenge (138) (real) returned: 0/Success (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.758744: Produced preauth for next request: 133, 138 (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.758760: Encoding request body and padata into FAST request (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.758845: Sending request (1108 bytes) to MITTELERDE.DE (Tue Apr 7 13:43:06 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406986.758915: Sending initial UDP request to dgram 1.2.3.4:88 (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.24880: Received answer (1052 bytes) from dgram 1.2.3.4:88 (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.24994: Response was from master KDC (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25036: Decoding FAST response (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25132: Processing preauth types: 19, 138 (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25156: Selected etype info: etype aes256-cts, salt "***", params "" (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25228: Preauth module encrypted_challenge (138) (real) returned: 0/Success (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25247: Produced preauth for next request: (empty) (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25267: AS key determined by preauth: aes256-cts/A013 (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25309: FAST reply key: aes256-cts/E722 (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25360: Decrypted AS reply; session key is: aes256-cts/2863 (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25396: FAST negotiation: available (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [717509813] (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [validate_tgt] (0x2000): Found keytab entry with the realm of the credential. (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25492: Retrieving host/[email protected] from MEMORY:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25512: Resolving unique ccache of type MEMORY (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25537: Initializing MEMORY:XJ7mgTY with default princ [email protected] (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25558: Removing [email protected] -> krbtgt/[email protected] from MEMORY:XJ7mgTY (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25578: Storing [email protected] -> krbtgt/[email protected] in MEMORY:XJ7mgTY (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25616: Getting credentials [email protected] -> host/[email protected] using ccache MEMORY:XJ7mgTY (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25657: Retrieving [email protected] -> host/[email protected] from MEMORY:XJ7mgTY with result: -1765328243/Matching credential not found (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25689: Retrieving [email protected] -> krbtgt/[email protected] from MEMORY:XJ7mgTY with result: 0/Success (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25709: Starting with TGT for client realm: [email protected] -> krbtgt/[email protected] (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25726: Requesting tickets for host/[email protected], referrals on (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25758: Generated subkey for TGS request: aes256-cts/0817 (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25810: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25890: Encoding request body and padata into FAST request (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25982: Sending request (933 bytes) to MITTELERDE.DE (Tue Apr 7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.26061: Sending initial UDP request to dgram 1.2.3.4:88 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.27153: Initiating TCP connection to stream 1.2.3.4:88 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.27699: Sending TCP request to stream 1.2.3.4:88 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.32846: Received answer (893 bytes) from dgram 1.2.3.4:88 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.32904: Terminating TCP connection to stream 1.2.3.4:88 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33030: Response was from master KDC (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33071: Decoding FAST response (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33177: FAST reply key: aes256-cts/038A (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33236: TGS reply is for [email protected] -> host/[email protected] with session key aes256-cts/D609 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33271: TGS request result: 0/Success (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33289: Received creds for desired service host/[email protected] (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33309: Removing [email protected] -> host/[email protected] from MEMORY:XJ7mgTY (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33328: Storing [email protected] -> host/[email protected] in MEMORY:XJ7mgTY (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33383: Creating authenticator for [email protected] -> host/[email protected], seqnum 0, subkey (null), session key aes256-cts/D609 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33466: Retrieving host/[email protected] from MEMORY:/etc/krb5.keytab (vno 1, enctype aes256-cts) with result: 0/Success (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33537: Decrypted AP-REQ with specified server principal host/[email protected]: aes256-cts/7685 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33562: AP-REQ ticket: [email protected] -> host/[email protected], session key aes256-cts/D609 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33822: Negotiated enctype based on authenticator: aes256-cts (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33854: Initializing MEMORY:rd_req2 with default princ [email protected] (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33879: Removing [email protected] -> host/[email protected] from MEMORY:rd_req2 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33899: Storing [email protected] -> host/[email protected] in MEMORY:rd_req2 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33927: Destroying ccache MEMORY:XJ7mgTY (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [validate_tgt] (0x0400): TGT verified using key for [host/[email protected]]. (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33981: Destroying ccache MEMORY:rd_req2 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_get_ccache_name_for_principal] (0x4000): Location: [KEYRING:persistent:1101] (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_get_ccache_name_for_principal] (0x4000): tmp_ccname: [KEYRING:persistent:1101:krb_ccache_Iw82BAp] (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [create_ccache] (0x4000): Initializing ccache of type [KEYRING] (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [safe_remove_old_ccache_file] (0x0400): New and old ccache file are the same, none will be deleted. (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [k5c_send_data] (0x0200): Received error code 0 (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [pack_response_packet] (0x2000): response packet size: [132] (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [k5c_send_data] (0x4000): Response sent. (Tue Apr 7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [main] (0x0400): krb5_child completed successfully
-- 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
