(Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [main] (0x0400): ldap_child started. (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [main] (0x2000): context initialized (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x1000): total buffer size: 53 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x1000): realm_str size: 14 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x1000): got realm_str: DEF.XYZ.LOCAL (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x1000): princ_str size: 15 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x1000): got princ_str:HOSTNAME$ (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [main] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [become_user] (0x0200): Trying to become user [0][0]. (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [become_user] (0x0200): Already user [0]. (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [main] (0x2000): Running as [0][0]. (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [main] (0x2000): getting TGT sync (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [DEF.XYZ.LOCAL] (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [HOSTNAME$@DEF.XYZ.LOCAL] (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.800588: Getting initial credentials forHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.800904: Looked up etypes in keytab: des-cbc-crc, des, des-cbc-crc, aes128-cts, aes256-cts, rc4-hmac (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.800997: Sending request (213 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.801393: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.802972: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803130: Response was from master KDC (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803201: Received error from KDC: -1765328359/Additional pre-authentication required (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803323: Processing preauth types: 16, 15, 19, 2 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803373: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803445: RetrievingHOSTNAME$@DEF.XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803515: AS key obtained for encrypted timestamp: aes256-cts/17D9 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803646: Encrypted timestamp (for 1498740544.803541): plain 301AA011180F32303137303632393132343930345AA10502030C42D5, encrypted 2971D0F77341926F39B62C1EA201C8EF648865022DC0728F6FB3BD56540BDA130085ED997BE8C5ED9F9D4177F4421E4C3FBEBB793BA498FF (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803702: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803729: Produced preauth for next request: 2 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803779: Sending request (293 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.803875: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.805187: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.805280: Response was from master KDC (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.805333: Received error from KDC: -1765328332/Response too big for UDP, retry with TCP (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.805363: Request or response is too big for UDP; retrying with TCP (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.805387: Sending request (293 bytes) to DEF.XYZ.LOCAL (tcp only) (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.805464: Initiating TCP connection to stream X.X.37.26:88 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.806495: Sending TCP request to stream X.X.37.26:88 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.807740: Received answer from stream X.X.37.26:88 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.807847: Response was from master KDC (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.807915: Processing preauth types: 19 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.807948: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.807974: Produced preauth for next request: (empty) (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.808041: AS key determined by preauth: aes256-cts/17D9 (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.808188: Decrypted AS reply; session key is: aes256-cts/BA8C (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.808250: FAST negotiation: unavailable (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_kFq2hC] (Thu Jun 29 08:49:04 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740544.808434: Initializing FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_kFq2hC with default princHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740545.71341: RemovingHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL from FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_kFq2hC (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [sss_child_krb5_trace_cb] (0x4000): [2342] 1498740545.71584: StoringHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL in FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_kFq2hC (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_kFq2hC] to [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_kFq2hC] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_kFq2hC] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [prepare_response] (0x0400): Building response for result [0] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [pack_buffer] (0x2000): response size: 62 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [42] msg [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2342]]]] [main] (0x0400): ldap_child completed successfully (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [main] (0x0400): ldap_child started. (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [main] (0x2000): context initialized (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x1000): total buffer size: 53 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x1000): realm_str size: 14 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x1000): got realm_str: DEF.XYZ.LOCAL (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x1000): princ_str size: 15 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x1000): got princ_str:HOSTNAME$ (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [main] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [become_user] (0x0200): Trying to become user [0][0]. (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [become_user] (0x0200): Already user [0]. (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [main] (0x2000): Running as [0][0]. (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [main] (0x2000): getting TGT sync (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [DEF.XYZ.LOCAL] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [HOSTNAME$@DEF.XYZ.LOCAL] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.164426: Getting initial credentials forHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.164702: Looked up etypes in keytab: des-cbc-crc, des, des-cbc-crc, aes128-cts, aes256-cts, rc4-hmac (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.164793: Sending request (213 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.165144: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.166465: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.166608: Response was from master KDC (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.166681: Received error from KDC: -1765328359/Additional pre-authentication required (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.166783: Processing preauth types: 16, 15, 19, 2 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.166832: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.166903: RetrievingHOSTNAME$@DEF.XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.166962: AS key obtained for encrypted timestamp: aes256-cts/17D9 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.167083: Encrypted timestamp (for 1498740545.166987): plain 301AA011180F32303137303632393132343930355AA1050203028C4B, encrypted C6075357BA7FBC2527A3E5C3DDF4A3F848F116BF37D85C811BBEE49D85010A6273CB10FD180135B04DE3F411CE4F365CD2C2D1EBE77D1338 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.167128: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.167154: Produced preauth for next request: 2 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.167203: Sending request (293 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.167295: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.168827: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.168924: Response was from master KDC (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.168966: Received error from KDC: -1765328332/Response too big for UDP, retry with TCP (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.168995: Request or response is too big for UDP; retrying with TCP (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.169020: Sending request (293 bytes) to DEF.XYZ.LOCAL (tcp only) (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.169097: Initiating TCP connection to stream X.X.37.26:88 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.169605: Sending TCP request to stream X.X.37.26:88 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.170854: Received answer from stream X.X.37.26:88 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.170964: Response was from master KDC (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.171029: Processing preauth types: 19 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.171061: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.171098: Produced preauth for next request: (empty) (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.171164: AS key determined by preauth: aes256-cts/17D9 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.171299: Decrypted AS reply; session key is: aes256-cts/622D (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.171378: FAST negotiation: unavailable (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_BXamYQ] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.171543: Initializing FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_BXamYQ with default princHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.428603: RemovingHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL from FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_BXamYQ (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [sss_child_krb5_trace_cb] (0x4000): [2344] 1498740545.428813: StoringHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL in FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_BXamYQ (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_BXamYQ] to [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_BXamYQ] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_BXamYQ] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [prepare_response] (0x0400): Building response for result [0] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [pack_buffer] (0x2000): response size: 62 (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [42] msg [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:05 2017) [[sssd[ldap_child[2344]]]] [main] (0x0400): ldap_child completed successfully (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [main] (0x0400): ldap_child started. (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [main] (0x2000): context initialized (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x1000): total buffer size: 53 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x1000): realm_str size: 14 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x1000): got realm_str: DEF.XYZ.LOCAL (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x1000): princ_str size: 15 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x1000): got princ_str:HOSTNAME$ (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [main] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [become_user] (0x0200): Trying to become user [0][0]. (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [become_user] (0x0200): Already user [0]. (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [main] (0x2000): Running as [0][0]. (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [main] (0x2000): getting TGT sync (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [DEF.XYZ.LOCAL] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [HOSTNAME$@DEF.XYZ.LOCAL] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.307704: Getting initial credentials forHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.307983: Looked up etypes in keytab: des-cbc-crc, des, des-cbc-crc, aes128-cts, aes256-cts, rc4-hmac (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.308074: Sending request (213 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.308453: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.309943: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310108: Response was from master KDC (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310179: Received error from KDC: -1765328359/Additional pre-authentication required (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310283: Processing preauth types: 16, 15, 19, 2 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310343: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310417: RetrievingHOSTNAME$@DEF.XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310481: AS key obtained for encrypted timestamp: aes256-cts/17D9 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310606: Encrypted timestamp (for 1498740551.310507): plain 301AA011180F32303137303632393132343931315AA105020304BCEB, encrypted 5A9C11E845FEC6C3713B6AF5190157C26267C6406863C601AF77E4FCEF48EB1006CF45E5D0556D0D42D12741033D739BB8C6ED19FB5A104C (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310650: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310679: Produced preauth for next request: 2 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310729: Sending request (293 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.310825: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.312381: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.312519: Response was from master KDC (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.312566: Received error from KDC: -1765328332/Response too big for UDP, retry with TCP (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.312596: Request or response is too big for UDP; retrying with TCP (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.312622: Sending request (293 bytes) to DEF.XYZ.LOCAL (tcp only) (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.312704: Initiating TCP connection to stream X.X.37.26:88 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.313203: Sending TCP request to stream X.X.37.26:88 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.314447: Received answer from stream X.X.37.26:88 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.314591: Response was from master KDC (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.314668: Processing preauth types: 19 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.314705: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.314769: Produced preauth for next request: (empty) (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.314817: AS key determined by preauth: aes256-cts/17D9 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.314947: Decrypted AS reply; session key is: aes256-cts/733E (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.315009: FAST negotiation: unavailable (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_QADavh] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.315180: Initializing FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_QADavh with default princHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.576095: RemovingHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL from FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_QADavh (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [sss_child_krb5_trace_cb] (0x4000): [2355] 1498740551.576319: StoringHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL in FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_QADavh (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_QADavh] to [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_QADavh] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_QADavh] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [prepare_response] (0x0400): Building response for result [0] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [pack_buffer] (0x2000): response size: 62 (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [42] msg [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:11 2017) [[sssd[ldap_child[2355]]]] [main] (0x0400): ldap_child completed successfully (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [main] (0x0400): ldap_child started. (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [main] (0x2000): context initialized (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x1000): total buffer size: 53 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x1000): realm_str size: 14 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x1000): got realm_str: DEF.XYZ.LOCAL (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x1000): princ_str size: 15 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x1000): got princ_str:HOSTNAME$ (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [main] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [become_user] (0x0200): Trying to become user [0][0]. (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [become_user] (0x0200): Already user [0]. (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [main] (0x2000): Running as [0][0]. (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [main] (0x2000): getting TGT sync (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [DEF.XYZ.LOCAL] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [HOSTNAME$@DEF.XYZ.LOCAL] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.651752: Getting initial credentials forHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.652046: Looked up etypes in keytab: des-cbc-crc, des, des-cbc-crc, aes128-cts, aes256-cts, rc4-hmac (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.652139: Sending request (213 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.652521: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.653828: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.653956: Response was from master KDC (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654017: Received error from KDC: -1765328359/Additional pre-authentication required (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654103: Processing preauth types: 16, 15, 19, 2 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654148: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654204: RetrievingHOSTNAME$@DEF.XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654271: AS key obtained for encrypted timestamp: aes256-cts/17D9 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654402: Encrypted timestamp (for 1498740557.654297): plain 301AA011180F32303137303632393132343931375AA105020309FBD9, encrypted 264C1FA68CF7CF3D654D9D576224D0489206277557D7727929158223C11271651C4D0BE0EFFD742A0491360B2CEC7162B021B917073E568B (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654447: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654473: Produced preauth for next request: 2 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654517: Sending request (293 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.654608: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.656048: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.656175: Response was from master KDC (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.656222: Received error from KDC: -1765328332/Response too big for UDP, retry with TCP (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.656252: Request or response is too big for UDP; retrying with TCP (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.656276: Sending request (293 bytes) to DEF.XYZ.LOCAL (tcp only) (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.656370: Initiating TCP connection to stream X.X.37.26:88 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.656852: Sending TCP request to stream X.X.37.26:88 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658415: Received answer from stream X.X.37.26:88 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658557: Response was from master KDC (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658634: Processing preauth types: 19 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658669: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658696: Produced preauth for next request: (empty) (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658727: AS key determined by preauth: aes256-cts/17D9 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658897: Decrypted AS reply; session key is: aes256-cts/028F (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.658961: FAST negotiation: unavailable (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_hZR3DR] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.659130: Initializing FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_hZR3DR with default princHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.920144: RemovingHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL from FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_hZR3DR (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [sss_child_krb5_trace_cb] (0x4000): [2356] 1498740557.920365: StoringHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL in FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_hZR3DR (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_hZR3DR] to [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_hZR3DR] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_hZR3DR] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [prepare_response] (0x0400): Building response for result [0] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [pack_buffer] (0x2000): response size: 62 (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [42] msg [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:17 2017) [[sssd[ldap_child[2356]]]] [main] (0x0400): ldap_child completed successfully (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [main] (0x0400): ldap_child started. (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [main] (0x2000): context initialized (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x1000): total buffer size: 53 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x1000): realm_str size: 14 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x1000): got realm_str: DEF.XYZ.LOCAL (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x1000): princ_str size: 15 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x1000): got princ_str:HOSTNAME$ (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [main] (0x2000): Kerberos context initialized (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [become_user] (0x0200): Trying to become user [0][0]. (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [become_user] (0x0200): Already user [0]. (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [main] (0x2000): Running as [0][0]. (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [main] (0x2000): getting TGT sync (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [DEF.XYZ.LOCAL] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [HOSTNAME$@DEF.XYZ.LOCAL] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.9706: Getting initial credentials forHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.9979: Looked up etypes in keytab: des-cbc-crc, des, des-cbc-crc, aes128-cts, aes256-cts, rc4-hmac (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.10065: Sending request (213 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.10418: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.11576: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.11714: Response was from master KDC (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.11789: Received error from KDC: -1765328359/Additional pre-authentication required (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.11887: Processing preauth types: 16, 15, 19, 2 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.11934: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.12004: RetrievingHOSTNAME$@DEF.XYZ.LOCAL from MEMORY:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.12064: AS key obtained for encrypted timestamp: aes256-cts/17D9 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.12184: Encrypted timestamp (for 1498740558.12090): plain 3019A011180F32303137303632393132343931385AA10402022F3A, encrypted EF1D7EBDC0D62C40514918FC74BD057D2DA07609877268DE239C3798FBCB1E0322A8A31364EDF3C7FB935EBF1A13F71AA1072278428811 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.12227: Preauth module encrypted_timestamp (2) (flags=1) returned: 0/Success (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.12253: Produced preauth for next request: 2 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.12302: Sending request (292 bytes) to DEF.XYZ.LOCAL (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.12404: Sending initial UDP request to dgram X.X.37.26:88 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.13793: Received answer from dgram X.X.37.26:88 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.13885: Response was from master KDC (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.13927: Received error from KDC: -1765328332/Response too big for UDP, retry with TCP (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.13955: Request or response is too big for UDP; retrying with TCP (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.13981: Sending request (292 bytes) to DEF.XYZ.LOCAL (tcp only) (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.14055: Initiating TCP connection to stream X.X.37.26:88 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.14557: Sending TCP request to stream X.X.37.26:88 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160389: Received answer from stream X.X.37.26:88 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160546: Response was from master KDC (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160621: Processing preauth types: 19 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160658: Selected etype info: etype aes256-cts, salt "DEF.XYZ.LOCALhosthostname.def.xyz.local", params "" (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160685: Produced preauth for next request: (empty) (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160753: AS key determined by preauth: aes256-cts/17D9 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160891: Decrypted AS reply; session key is: aes256-cts/293E (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.160955: FAST negotiation: unavailable (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_PE59ab] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.161122: Initializing FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_PE59ab with default princHOSTNAME$@DEF.XYZ.LOCAL (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.420548: RemovingHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL from FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_PE59ab (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [sss_child_krb5_trace_cb] (0x4000): [2357] 1498740558.420756: StoringHOSTNAME$@DEF.XYZ.LOCAL -> krbtgt/DEF.XYZ.LOCAL@DEF.XYZ.LOCAL in FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_PE59ab (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_PE59ab] to [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_PE59ab] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_DEF.XYZ.LOCAL_PE59ab] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [prepare_response] (0x0400): Building response for result [0] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [pack_buffer] (0x2000): response size: 62 (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [42] msg [FILE:/var/lib/sss/db/ccache_DEF.XYZ.LOCAL] (Thu Jun 29 08:49:18 2017) [[sssd[ldap_child[2357]]]] [main] (0x0400): ldap_child completed successfully