[Freeipa-users] Ad user password authentication doesn't work

I've been fighting with this for 2 months. I've rebuilt both the ad and ip server twice. Currently ipa and ad only contain a single unique user. AD and ipa are on separate dns domains (ad.domain.com and int.domain.com respectively). AD domain has windows pc joined to it. IPA server has linux server joined to it. Any help is greatly appreciated. AD server Server: dc0.ad.domain.com Domain: ad.domain.com IP: 10.10.60.81 IPA server Server: identity.int.domain.com domain int.domain.com IP: 10.10.60.61 What works on ipa server: id aduser getent passwd aduser kinit aduser(a)ad.domain.com what doesn't work ssh 'aduse@ad.domain.com'(a)ipaserver Password: Password: Password: [localuser@ipaserver] su - aduser(a)ad.domain.com Password: su: Authentication failure logs: ldap_child.log (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [main] (0x0400): ldap_child started. (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [main] (0x2000): context initialized (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x1000): total buffer size: 70 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x1000): realm_str size: 16 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x1000): got realm_str: INT.DOMAIN.COM (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x1000): princ_str size: 30 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x1000): got princ_str: host/identity.int.domain.com (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x1000): keytab_name size: 0 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [main] (0x2000): Kerberos context initialized (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [become_user] (0x0200): Trying to become user [0][0]. (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [become_user] (0x0200): Already user [0]. (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [main] (0x2000): Running as [0][0]. (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [main] (0x2000): getting TGT sync (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [INT.DOMAIN.COM] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/identity.int.domain.com(a)INT.DOMAIN.COM] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/etc/krb5.keytab] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x0100): Will canonicalize principals (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14735: Getting initial credentials for host/identity.int.domain.com(a)INT.DOMAIN.COM (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14736: Looked up etypes in keytab: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14738: Sending unauthenticated request (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14739: Sending request (219 bytes) to INT.DOMAIN.COM (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14740: Initiating TCP connection to stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14741: ending TCP request to stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14742: Received answer (593 bytes) from stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14743: Terminating TCP connection to stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14744: Response was from master KDC (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14745: Received error from KDC: -1765328359/Additional pre-authentication required (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14748: Preauthenticating using KDC method data (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14749: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-PK-AS-REQ_OLD (14), PA-FX-FAST (136), PA-ETYPE-INFO2 (19), PA-PKINIT-KX (147), PA-SPAKE (151), PA-ENC-TIMESTAMP (2), PA_AS_FRESHNESS (150), PA-FX-COOKIE (133) (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14750: Selected etype info: etype aes256-cts, salt "INT.DOMAIN.COMhostidentity.int.domain.com", params "" (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14751: Received cookie: MIT1\x00\x00\x00\x01\x86\x9a\x8e>yI7\xe0\x9a\xa5xym\xa2,F{`d\xe7 N \x12\xef\xf1\x09)\x09:y\xc7J\xc8\xcd0U\x01\xacs\xbc\x02\x9a\xae\xfc\xe0\xa6\x0c\xe0\x96\x04e\xde\xc5?\xa0:U\xb8\xcdm\xbe\x0e\xf5\x9eW`\xa1\xd0\xcd\xed\xcd\xd0\x1a\xbb\xcfz\xe3\x91T\x03\xba\x05J\x8cz\xe3\x90\xe6\x8f\xa1\xf23\xea\xf8\x97\x12\xb7}\x15.\xd06$\x1aZ\xe7\xd5\xfd\x09D\xb2n\xafV\xb3\xc9\xab\xf8\xe7\xd3h-\xac?\x87\x15>\xd3G (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14752: PKINIT client has no configured identity; giving up (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14753: Preauth module pkinit (147) (info) returned: 0/Success (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14754: PKINIT client received freshness token from KDC (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14755: Preauth module pkinit (150) (info) returned: 0/Success (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14756: PKINIT client has no configured identity; giving up (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14757: Preauth module pkinit (16) (real) returned: 22/Invalid argument (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14758: PKINIT client ignoring draft 9 offer from RFC 4556 KDC (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14759: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14760: PKINIT client ignoring draft 9 offer from RFC 4556 KDC (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14761: Preauth module pkinit (14) (real) returned: -1765328360/Preauthentication failed (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14762: PAKE challenge received with group 1, pubkey 400BEA93DC1F29293028E9CBDAB7FE7649318A0DBF7AF492C319ADA76A4B59F4 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14763: Retrieving host/identity.int.domain.com(a)INT.DOMAIN.COM from MEMORY:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14764: SPAKE key generated with pubkey 9BE6AA79E0B53D1B97641EB9FA6A27D0EE7C0387B05032B85920E190546464A6 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14765: SPAKE algorithm result: A501375464DD840A9E83F2038D18FE4AE664D3E8676983319E38E4D443476779 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14766: SPAKE final transcript hash: 27EB757B9F468B2A657293FB37623F3E7D47179A7A11B85D898D95011449DA2C (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14767: Sending SPAKE response (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14768: Preauth module spake (151) (real) returned: 0/Success (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14770: Sending request (478 bytes) to INT.DOMAIN.COM (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14771: Initiating TCP connection to stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14772: Sending TCP request to stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14773: Received answer (1496 bytes) from stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14774: Terminating TCP connection to stream 10.10.60.61:88 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14775: Response was from master KDC (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14776: Processing preauth types: PA-ETYPE-INFO2 (19) (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14777: Selected etype info: etype aes256-cts, salt "INT.DOMAIN.COMhostidentity.int.domain.com", params "" (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14778: Produced preauth for next request: (empty) (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14779: AS key determined by preauth: aes256-cts/5039 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14780: Decrypted AS reply; session key is: aes256-cts/4179 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14781: FAST negotiation: available (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_INT.DOMAIN.COM_YzeV0z] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14782: Initializing FILE:/var/lib/sss/db/ccache_INT.DOMAIN.COM_YzeV0z with default princ host/identity.int.domain.com(a)INT.DOMAIN.COM (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [sss_child_krb5_trace_cb] (0x4000): [2798] 1550983820.14783: Storing host/identity.int.domain.com(a)INT.DOMAIN.COM -> krbtgt/INT.DOMAIN.COM(a)INT.DOMAIN.COM in FILE:/var/lib/sss/db/ccache_INT.DOMAIN.COM_YzeV0z (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_INT.DOMAIN.COM_YzeV0z] to [/var/lib/sss/db/ccache_INT.DOMAIN.COM] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_INT.DOMAIN.COM_YzeV0z] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_INT.DOMAIN.COM_YzeV0z] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [prepare_response] (0x0400): Building response for result [0] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [pack_buffer] (0x2000): response size: 64 (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [44] msg [FILE:/var/lib/sss/db/ccache_INT.DOMAIN.COM] (Sat Feb 23 23:50:20 2019) [[sssd[ldap_child[2798]]]] [main] (0x0400): ldap_child completed successfully (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [main] (0x0400): ldap_child started. (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [main] (0x2000): context initialized (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): total buffer size: 94 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): realm_str size: 15 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): got realm_str: AD.DOMAIN.COM (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): princ_str size: 12 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): got princ_str: INTDOMAIN$ (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): keytab_name size: 43 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): got keytab_name: /var/lib/sss/keytabs/ad.domain.com.keytab (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x1000): lifetime: 86400 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unpack_buffer] (0x0200): Will run as [0][0]. (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [privileged_krb5_setup] (0x2000): Kerberos context initialized (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [main] (0x2000): Kerberos context initialized (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [become_user] (0x0200): Trying to become user [0][0]. (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [become_user] (0x0200): Already user [0]. (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [main] (0x2000): Running as [0][0]. (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [main] (0x2000): getting TGT sync (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x2000): got realm_name: [AD.DOMAIN.COM] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x0100): Principal name is: [INTDOMAIN$(a)AD.DOMAIN.COM] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x0100): Using keytab [MEMORY:/var/lib/sss/keytabs/ad.domain.com.keytab] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234657: Getting initial credentials for INTDOMAIN$(a)AD.DOMAIN.COM (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234658: Looked up etypes in keytab: aes256-cts, aes128-cts, rc4-hmac (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234660: Sending unauthenticated request (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234661: Sending request (198 bytes) to AD.DOMAIN.COM (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234662: Initiating TCP connection to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234663: Sending TCP request to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234664: Received answer (206 bytes) from stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234665: Terminating TCP connection to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234666: Response was from master KDC (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234667: Received error from KDC: -1765328359/Additional pre-authentication required (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234670: Preauthenticating using KDC method data (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234671: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2) (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234672: Selected etype info: etype aes256-cts, salt "AD.DOMAIN.COMkrbtgtINTDOMAIN", params "" (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234673: PKINIT client has no configured identity; giving up (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234674: PKINIT client has no configured identity; giving up (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234675: Preauth module pkinit (16) (real) returned: 22/Invalid argument (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234676: PKINIT client ignoring draft 9 offer from RFC 4556 KDC (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234677: Preauth module pkinit (15) (real) returned: -1765328360/Preauthentication failed (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234678: Retrieving INTDOMAIN$(a)AD.DOMAIN.COM from MEMORY:/var/lib/sss/keytabs/ad.domain.com.keytab (vno 0, enctype aes256-cts) with result: 0/Success (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234679: AS key obtained for encrypted timestamp: aes256-cts/18D5 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234681: Encrypted timestamp (for 1550983885.896873): plain 301AA011180F32303139303232343034353132355AA10502030DAF69, encrypted F264C965CF31F9501C9942AFEBF282493E712F282BBB6B47C1F7417317F6334B814F2E7CAB6FE13117A3BC3B8F8E91F5D0576E7957684AB3 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234682: Preauth module encrypted_timestamp (2) (real) returned: 0/Success (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234683: Produced preauth for next request: PA-ENC-TIMESTAMP (2) (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234684: Sending request (278 bytes) to AD.DOMAIN.COM (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234685: Initiating TCP connection to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234686: Sending TCP request to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234685: Initiating TCP connection to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234686: Sending TCP request to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234687: Received answer (1585 bytes) from stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234688: Terminating TCP connection to stream 10.10.60.81:88 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234689: Response was from master KDC (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234690: Processing preauth types: PA-ETYPE-INFO2 (19) (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234691: Selected etype info: etype aes256-cts, salt "AD.DOMAIN.COMkrbtgtINTDOMAIN", params "" (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234692: Produced preauth for next request: (empty) (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234693: AS key determined by preauth: aes256-cts/18D5 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234694: Decrypted AS reply; session key is: aes256-cts/AE91 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234695: FAST negotiation: unavailable (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x2000): credentials initialized (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x2000): keytab ccname: [FILE:/var/lib/sss/db/ccache_AD.DOMAIN.COM_ZuI79F] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234696: Initializing FILE:/var/lib/sss/db/ccache_AD.DOMAIN.COM_ZuI79F with default princ INTDOMAIN$(a)AD.DOMAIN.COM (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [sss_child_krb5_trace_cb] (0x4000): [2802] 1550983884.234697: Storing INTDOMAIN$(a)AD.DOMAIN.COM -> krbtgt/AD.DOMAIN.COM(a)AD.DOMAIN.COM in FILE:/var/lib/sss/db/ccache_AD.DOMAIN.COM_ZuI79F (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x2000): credentials stored (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x2000): Got KDC time offset (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [ldap_child_get_tgt_sync] (0x2000): Renaming [/var/lib/sss/db/ccache_AD.DOMAIN.COM_ZuI79F] to [/var/lib/sss/db/ccache_AD.DOMAIN.COM] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/db/ccache_AD.DOMAIN.COM_ZuI79F] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/db/ccache_AD.DOMAIN.COM_ZuI79F] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [prepare_response] (0x0400): Building response for result [0] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [pack_buffer] (0x2000): response size: 63 (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [pack_buffer] (0x1000): result [0] krberr [0] msgsize [43] msg [FILE:/var/lib/sss/db/ccache_AD.DOMAIN.COM] (Sat Feb 23 23:51:24 2019) [[sssd[ldap_child[2802]]]] [main] (0x0400): ldap_child completed successfully krb5_child.log: empty during log in attempts sssd_int.domain.com.log (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_done] (0x0400): DP Request [Subdomains #15]: Request handler finished [0]: Success (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [_dp_req_recv] (0x0400): DP Request [Subdomains #15]: Receiving request data. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Subdomains #15]: Finished. Success. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_reply_std] (0x1000): DP Request [Subdomains #15]: Returning [Success]: 0,0,Success (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_table_value_destructor] (0x0400): Removing [8:8:0000:ad.domain.com'] from reply table (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): DP Request [Subdomains #15]: Request removed. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c16110], connected[1], ops[(nil)], ldap[0x561795c1df90] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x561795bad8d0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): Dispatching. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name='aduser(a)ad.domain.com'] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): DP Request [Account #16]: New request. Flags [0x0001]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [cn=accounts,dc=int,dc=domain,dc=com] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(krbPrincipalName='aduser@ad.domain.com')(mail='aduser@ad.domain.com')(krbPrincipalName='aduser\\@ad.domain.com'@INT.domain.COM))(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=int,dc=domain,dc=com]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaNTSecurityIdentifier] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUserAuthType] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 14 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 14 timeout 6 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c16110], connected[1], ops[0x561795c0d3a0], ldap[0x561795c1df90] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 14 finished (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_process] (0x0400): Search for users, returned 0 results. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [cn=trusts,dc=int,dc=domain,dc=com] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(&(|(krbPrincipalName='aduser@ad.domain.com')(mail='aduser@ad.domain.com')(krbPrincipalName='aduser\\@ad.domain.com'@INT.domain.COM))(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))(objectClass=ipaIDObject))][cn=trusts,dc=int,dc=domain,dc=com]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaNTSecurityIdentifier] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPasswordExpiration] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginExpirationTime] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginAllowedTimeMap] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUserAuthType] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 15 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 15 timeout 6 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c16110], connected[1], ops[0x561795c0d3a0], ldap[0x561795c1df90] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c16110], connected[1], ops[0x561795c0d3a0], ldap[0x561795c1df90] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 15 finished (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_process] (0x0400): Search for users, returned 0 results. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_process] (0x2000): Retrieved total 0 users (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x561795c16e00 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x561795c16cf0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x561795c16e00 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x561795c16cf0 "ltdb_timeout" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x561795c16e00 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_search_by_name] (0x0400): No such entry (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_cache_search_groups] (0x2000): Search groups with filter: (&(objectCategory=group)(ghost='aduser(a)ad.domain.com')) (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x561795c1c110 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x561795c16cf0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x561795c1c110 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x561795c16cf0 "ltdb_timeout" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x561795c1c110 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_cache_search_groups] (0x2000): No such entry (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x561795c16e00 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x561795c16cf0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x561795c16e00 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x561795c16cf0 "ltdb_timeout" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x561795c16e00 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_search_user_by_upn] (0x0400): No entry with upn ['aduser(a)ad.domain.com'] found. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_done] (0x0400): DP Request [Account #16]: Request handler finished [0]: Success (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [_dp_req_recv] (0x0400): DP Request [Account #16]: Receiving request data. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #16]: Finished. Success. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #16]: Returning [Success]: 0,0,Success (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:U:int.domain.com:name='aduser@ad.domain.com'] from reply table (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): DP Request [Account #16]: Request removed. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c16110], connected[1], ops[(nil)], ldap[0x561795c1df90] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x561795bad8d0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): Dispatching. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name='aduser(a)ad.domain.com'] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): DP Request [Account #17]: New request. Flags [0x0001]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaUserOverride)(uid='aduser))]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid='aduser))][cn=Default Trust View,cn=views,cn=accounts,dc=int,dc=domain,dc=com]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 16 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 16 timeout 6 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c16110], connected[1], ops[0x561795c0b230], ldap[0x561795c1df90] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 16 finished (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaUserOverride)(uid='aduser))]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x1000): Status of server 'dc0.ad.domain.com' is 'working' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x0100): Hostname resolution expired, resetting the server status of 'dc0.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [set_server_common_status] (0x0100): Marking server 'dc0.ad.domain.com' as 'name not resolved' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [get_port_status] (0x1000): Port status of port 389 for server 'dc0.ad.domain.com' is 'working' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is expired (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [collapse_srv_lookup] (0x0100): Need to refresh SRV lookup for domain ad.domain.com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain ad.domain.com and site Default-First-Site-Name (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c16110], connected[1], ops[(nil)], ldap[0x561795c1df90] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_done] (0x0040): SRV query failed [4]: Domain name not found (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_done] (0x1000): Using TTL [600] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_get_dc_servers_done] (0x0400): Found 1 domain controllers in domain ad.domain.com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_connect_host_send] (0x0400): Resolving host dc0.ad.domain.com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_is_address] (0x4000): [dc0.ad.domain.com] does not look like an IP address (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'dc0.ad.domain.com' in files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in DNS (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_connect_host_resolv_done] (0x0400): Connecting to ldap://dc0.ad.domain.com:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [30] for the connection. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://dc0.ad.domain.com:389/??base] with fd [30]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_connect_host_done] (0x0400): Successful connection to ldap://dc0.ad.domain.com:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.81:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=ad.domain.com)(NtVer=\14\00\00\00))][]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 1 timeout 6 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795bb41c0], connected[1], ops[0x561795c1ad50], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [netlogon] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795bb41c0], connected[1], ops[0x561795c1ad50], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 1 finished (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x561795bb41c0], connected[1], ops[(nil)], ldap[0x561795bc93c0], destructor_lock[0], release_memory[0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_get_client_site_done] (0x0400): Found site: Default-First-Site-Name (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_get_client_site_done] (0x0400): Found forest: ad.domain.com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_site_done] (0x0400): About to discover primary and backup servers (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_discover_servers_send] (0x0400): Looking up primary servers (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'Default-First-Site-Name._sites.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.Default-First-Site-Name._sites.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_done] (0x0040): SRV query failed [4]: Domain name not found (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_done] (0x1000): Using TTL [600] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_servers_done] (0x0400): Got 1 primary and 0 backup servers (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_add_server_to_list] (0x0400): Inserted primary server 'dc0.ad.domain.com:389' to service 'sd_ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_ad.domain.com' as 'resolved' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x1000): Status of server 'dc0.ad.domain.com' is 'name not resolved' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_is_address] (0x4000): [dc0.ad.domain.com] does not look like an IP address (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [set_server_common_status] (0x0100): Marking server 'dc0.ad.domain.com' as 'resolving name' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'dc0.ad.domain.com' in files (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in DNS (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [set_server_common_status] (0x0100): Marking server 'dc0.ad.domain.com' as 'name resolved' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [be_resolve_server_process] (0x0200): Found address for server dc0.ad.domain.com: [10.10.60.81] TTL 600 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://dc0.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://dc0.ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [krb5_add_krb5info_offline_callback] (0x4000): Removal callback already available for service [sd_ad.domain.com]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_2flUNz] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_2flUNz] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [25] for the connection. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://dc0.ad.domain.com:389/??base] with fd [25]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.81:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 1 timeout 6 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[0x561795c15290], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [currentTime] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [subschemaSubentry] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dsServiceName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [defaultNamingContext] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [schemaNamingContext] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [configurationNamingContext] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [rootDomainNamingContext] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPPolicies] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [highestCommittedUSN] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dnsHostName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ldapServiceName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [serverName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedCapabilities] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isSynchronized] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isGlobalCatalogReady] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainFunctionality] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [forestFunctionality] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainControllerFunctionality] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[0x561795c15290], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 1 finished (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_rootdse_done] (0x2000): Got rootdse (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 49446 (int: 49446) (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [7] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Will look for schema at [CN=Schema,CN=Configuration,DC=ad,DC=domain,DC=com] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_kinit_send] (0x0400): Attempting kinit (/var/lib/sss/keytabs/ad.domain.com.keytab, INTdomain$, AD.domain.COM, 86400) (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service sd_ad.domain.com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_ad.domain.com' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x1000): Status of server 'dc0.ad.domain.com' is 'name resolved' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x1000): Status of server 'dc0.ad.domain.com' is 'name resolved' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [be_resolve_server_process] (0x0200): Found address for server dc0.ad.domain.com: [10.10.60.81] TTL 600 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT... (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [create_tgt_req_send_buffer] (0x0400): buffer size: 94 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [2802] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for TGT child (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[(nil)], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [write_pipe_handler] (0x0400): All data has been sent! (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_tgt_recv] (0x0400): Child responded: 0 [FILE:/var/lib/sss/db/ccache_AD.domain.COM], expired on [1551019884] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1550984784 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: INTdomain$ (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [child_sig_handler] (0x1000): Waiting for child [2802]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [child_sig_handler] (0x0100): child [2802] finished successfully. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_cli_connect_recv] (0x0400): Connection established. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2086 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'dc0.ad.domain.com' as 'working' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [set_server_common_status] (0x0100): Marking server 'dc0.ad.domain.com' as 'working' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'dc0.ad.domain.com' as 'working' (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_done] (0x2000): Old USN: 49438, New USN: 49446 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [dc=ad,dc=domain,dc=com] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.81:389 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(|(userPrincipalName='aduser@ad.domain.com')(mail='aduser@ad.domain.com')(userPrincipalName='aduser\\@ad.domain.com'@AD.domain.COM))(objectclass=user)(sAMAccountName=*)(objectSID=*))][dc=ad,dc=domain,dc=com]. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 5 timeout 6 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[0x561795c298a0], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://ForestDnsZones.ad.domain.com/DC=ForestDnsZones,DC=ad,DC=domain,DC=com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[0x561795c298a0], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://DomainDnsZones.ad.domain.com/DC=DomainDnsZones,DC=ad,DC=domain,DC=com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[0x561795c298a0], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_add_references] (0x1000): Additional References: ldap://ad.domain.com/CN=Configuration,DC=ad,DC=domain,DC=com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[0x561795c298a0], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 5 finished (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [generic_ext_search_handler] (0x4000): Request included referrals which were ignored. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [generic_ext_search_handler] (0x4000): Ref: ldap://ForestDnsZones.ad.domain.com/DC=ForestDnsZones,DC=ad,DC=domain,DC=com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [generic_ext_search_handler] (0x4000): Ref: ldap://DomainDnsZones.ad.domain.com/DC=DomainDnsZones,DC=ad,DC=domain,DC=com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [generic_ext_search_handler] (0x4000): Ref: ldap://ad.domain.com/CN=Configuration,DC=ad,DC=domain,DC=com (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_process] (0x0400): Search for users, returned 0 results. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_search_user_process] (0x2000): Retrieved total 0 users (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x561795c16cf0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x561795c2a8f0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x561795c16cf0 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x561795c2a8f0 "ltdb_timeout" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x561795c16cf0 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_search_by_name] (0x0400): No such entry (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_cache_search_groups] (0x2000): Search groups with filter: (&(objectCategory=group)(ghost='aduser(a)ad.domain.com')) (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x561795c1c110 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x561795c2a8f0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x561795c1c110 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x561795c2a8f0 "ltdb_timeout" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x561795c1c110 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_cache_search_groups] (0x2000): No such entry (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x561795c16cf0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x561795c2a8f0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x561795c16cf0 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x561795c2a8f0 "ltdb_timeout" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x561795c16cf0 "ltdb_callback" (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sysdb_search_user_by_upn] (0x0400): No entry with upn ['aduser(a)ad.domain.com'] found. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_acct_ad_part_done] (0x0080): Object not found, ending request (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_done] (0x0400): DP Request [Account #17]: Request handler finished [0]: Success (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [_dp_req_recv] (0x0400): DP Request [Account #17]: Receiving request data. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #17]: Finished. Success. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #17]: Returning [Success]: 0,0,Success (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1:U:ad.domain.com:name='aduser@ad.domain.com'] from reply table (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): DP Request [Account #17]: Request removed. (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x561795c078f0], connected[1], ops[(nil)], ldap[0x561795bc93c0] (Sat Feb 23 23:51:24 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list