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 [fr...@mittelerde.de]
(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/kate.mittelerde...@mittelerde.de]
(Tue Apr  7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/kate.mittelerde...@mittelerde.de in keytab.
(Tue Apr  7 13:43:05 2015) [[sssd[krb5_child[8101]]]] [match_principal] (0x1000): Principal matched to the sample (host/kate.mittelerde...@mittelerde.de).
(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 fr...@mittelerde.de

(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/kate.mittelerde...@mittelerde.de -> 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/kate.mittelerde...@mittelerde.de -> 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/kate.mittelerde...@mittelerde.de -> 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/kate.mittelerde...@mittelerde.de -> krbtgt/mittelerde...@mittelerde.de 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/kate.mittelerde...@mittelerde.de -> krbtgt/mittelerde...@mittelerde.de 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/kate.mittelerde...@mittelerde.de -> krbtgt/mittelerde...@mittelerde.de, 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/kate.mittelerde...@mittelerde.de 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 fr...@mittelerde.de

(Tue Apr  7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25558: Removing fr...@mittelerde.de -> krbtgt/mittelerde...@mittelerde.de from MEMORY:XJ7mgTY

(Tue Apr  7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25578: Storing fr...@mittelerde.de -> krbtgt/mittelerde...@mittelerde.de 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 fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de 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 fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de 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 fr...@mittelerde.de -> krbtgt/mittelerde...@mittelerde.de 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: fr...@mittelerde.de -> krbtgt/mittelerde...@mittelerde.de

(Tue Apr  7 13:43:07 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406987.25726: Requesting tickets for host/kate.mittelerde...@mittelerde.de, 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 fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de 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/kate.mittelerde...@mittelerde.de

(Tue Apr  7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33309: Removing fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de from MEMORY:XJ7mgTY

(Tue Apr  7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33328: Storing fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de 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 fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de, 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/kate.mittelerde...@mittelerde.de 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/kate.mittelerde...@mittelerde.de: 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: fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de, 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 fr...@mittelerde.de

(Tue Apr  7 13:43:08 2015) [[sssd[krb5_child[8101]]]] [sss_child_krb5_trace_cb] (0x4000): [8101] 1428406988.33879: Removing fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de 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 fr...@mittelerde.de -> host/kate.mittelerde...@mittelerde.de 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/kate.mittelerde...@mittelerde.de].
(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

Reply via email to