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@ad.domain.com
what doesn't work ssh 'aduse@ad.domain.com'@ipaserver Password: Password: Password: [localuser@ipaserver] su - aduser@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@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@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@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@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@INT.DOMAIN.COM -> krbtgt/INT.DOMAIN.COM@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$@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$@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$@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$@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$@AD.DOMAIN.COM -> krbtgt/AD.DOMAIN.COM@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@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@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@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@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@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@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
On su, 24 helmi 2019, Patrick Irish via FreeIPA-users wrote:
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.
Can you show your sssd configuration? There is something fishy in that SSSD is not splitting apart your AD user name and is asking AD DCs with a fully-qualified name (ad.user@ad.domain.com) instead of just ad.user.
Thank you for the quick response. Let me know anything else you need.
[root@identity sssd]# sssd --version 1.16.3 [root@identity sssd]# ipa --version VERSION: 4.7.0, API_VERSION: 2.229
sssd.conf [domain/int.domain.com] debug_level=9 id_provider = ipa ipa_server_mode = True ipa_server = identity.int.domain.com ipa_domain = int.domain.com ipa_hostname = identity.int.domain.com auth_provider = ipa chpass_provider = ipa access_provider = ipa cache_credentials = True ldap_tls_cacert = /etc/ipa/ca.crt krb5_store_password_if_offline = True
[sssd] services = nss, pam, ifp, ssh, sudo
domains = int.domain.com
[nss] homedir_substring = /home memcache_timeout = 600
[pam] debug_level=9
[sudo]
[autofs]
[ssh] debug_level=9
[pac]
[ifp]
[secrets]
[session_recording]
On Sun, Feb 24, 2019 at 06:20:26AM -0000, Patrick Irish via FreeIPA-users wrote:
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@ad.domain.com
what doesn't work ssh 'aduse@ad.domain.com'@ipaserver Password: Password: Password: [localuser@ipaserver] su - aduser@ad.domain.com Password: su: Authentication failure
Hi,
the domain log only covers the lookup for the User Principal name and email address. There should be lookups for the plain name with a search filter which contains 'sAMAccountName=aduser' before the part you have send. This part would be more interesting because the UPN and email lookups are just a fallback for the case where the lookup with the plain name does not return anything.
Additionally it would be good to see the sssd_nss.log as well since it looks like the issues already happens during the name lookup before the real authentication happens.
bye, Sumit
I had to create a new attempt, here are the logs from the beginning of the attempt. I stopped copying after the logs started repeating.
Tue Feb 26 21:30:31 EST 2019 [root@mgmt ~]# ssh 'aduser@ad.domain.com'@identity Password: Password: Password: aduser@ad.domain.com@identity's password: Permission denied, please try again. aduser@ad.domain.com@identity's password:
[root@mgmt ~]# date Tue Feb 26 21:31:13 EST 2019
sssd_nss.log
(Tue Feb 26 21:06:39 2019) [sssd[nss]] [sss_dp_get_reply] (0x0010): The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Offline] (Tue Feb 26 21:07:43 2019) [sssd[nss]] [sss_dp_get_reply] (0x0010): The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Offline] (Tue Feb 26 21:07:43 2019) [sssd[nss]] [sss_dp_get_reply] (0x0010): The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Offline] (Tue Feb 26 21:07:43 2019) [sssd[nss]] [sss_dp_get_reply] (0x0010): The Data Provider returned an error [org.freedesktop.sssd.Error.DataProvider.Offline]
sssd_int.domain.com.log
(Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x564b204fa2a0 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=aduser@ad.domain.com](Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): DP Request [Account #26]: New request. Flags [0x0001]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Tue Feb 26 21:30:59 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))]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Tue Feb 26 21:30:59 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]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 9 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 9 timeout 6 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[0x564b20535d50], ldap[0x564b20515210] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 9 finished (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaUserOverride)(uid=aduser))]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_ad.domain.com' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'neutral' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 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' (Tue Feb 26 21:30:59 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' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[(nil)], ldap[0x564b20515210] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_done] (0x0040): SRV query failed [4]: Domain name not found (Tue Feb 26 21:30:59 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' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.ad.domain.com' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_done] (0x1000): Using TTL [600] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_get_dc_servers_done] (0x0400): Found 1 domain controllers in domain ad.domain.com (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_connect_host_send] (0x0400): Resolving host dc0.ad.domain.com (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_is_address] (0x4000): [dc0.ad.domain.com] does not look like an IP address (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'dc0.ad.domain.com' in files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in DNS (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_connect_host_resolv_done] (0x0400): Connecting to ldap://dc0.ad.domain.com:389 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [30] for the connection. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Tue Feb 26 21:30:59 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]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_connect_host_done] (0x0400): Successful connection to ldap://dc0.ad.domain.com:389 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.81:389 (Tue Feb 26 21:30:59 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))][]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [netlogon] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 1 timeout 6 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205149c0], connected[1], ops[0x564b20540320], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [netlogon] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205149c0], connected[1], ops[0x564b20540320], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 1 finished (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x564b205149c0], connected[1], ops[(nil)], ldap[0x564b2052dee0], destructor_lock[0], release_memory[0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_get_client_site_done] (0x0400): Found site: Default-First-Site-Name (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_get_client_site_done] (0x0400): Found forest: ad.domain.com (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_site_done] (0x0400): About to discover primary and backup servers (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_discover_servers_send] (0x0400): Looking up primary servers (Tue Feb 26 21:30:59 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' (Tue Feb 26 21:30:59 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' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_done] (0x0040): SRV query failed [4]: Domain name not found (Tue Feb 26 21:30:59 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' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.ad.domain.com' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_done] (0x1000): Using TTL [600] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_servers_done] (0x0400): Got 1 primary and 0 backup servers (Tue Feb 26 21:30:59 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' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [set_srv_data_status] (0x0100): Marking SRV lookup of service 'sd_ad.domain.com' as 'resolved' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x1000): Status of server 'dc0.ad.domain.com' is 'name not resolved' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_is_address] (0x4000): [dc0.ad.domain.com] does not look like an IP address (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [set_server_common_status] (0x0100): Marking server 'dc0.ad.domain.com' as 'resolving name' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'dc0.ad.domain.com' in files (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in DNS (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [set_server_common_status] (0x0100): Marking server 'dc0.ad.domain.com' as 'name resolved' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_resolve_callback] (0x0100): Constructed uri 'ldap://dc0.ad.domain.com' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ad_resolve_callback] (0x0100): Constructed GC uri 'ldap://dc0.ad.domain.com' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_2y1sSd] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_2y1sSd] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [29] for the connection. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Tue Feb 26 21:30:59 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 [29]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.81:389 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 1 timeout 6 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[0x564b20540320], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [currentTime] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [subschemaSubentry] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dsServiceName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [defaultNamingContext] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [schemaNamingContext] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [configurationNamingContext] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [rootDomainNamingContext] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPPolicies] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [highestCommittedUSN] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dnsHostName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ldapServiceName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [serverName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedCapabilities] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isSynchronized] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [isGlobalCatalogReady] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainFunctionality] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [forestFunctionality] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainControllerFunctionality] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[0x564b20540320], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 1 finished (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_rootdse_done] (0x2000): Got rootdse (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [get_naming_context] (0x0200): Using value from [defaultNamingContext] as naming context. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_host_search_base] to [DC=ad,DC=domain,DC=com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [common_parse_search_base] (0x0100): Search base added: [HOST][DC=ad,DC=domain,DC=com][SUBTREE][] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 57524 (int: 57524) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility level to [7] (Tue Feb 26 21:30:59 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] (Tue Feb 26 21:30:59 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) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service sd_ad.domain.com (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_ad.domain.com' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x1000): Status of server 'dc0.ad.domain.com' is 'name resolved' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [get_server_status] (0x1000): Status of server 'dc0.ad.domain.com' is 'name resolved' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT... (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [create_tgt_req_send_buffer] (0x0400): buffer size: 94 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [2290] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [2290] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for TGT child (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[(nil)], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [write_pipe_handler] (0x0400): All data has been sent! (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Tue Feb 26 21:30:59 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 [1551270659] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_cli_auth_step] (0x0100): expire timeout is 900 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1551235559 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sasl_bind_send] (0x0100): Executing sasl bind mech: gssapi, user: INTdomain$ (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [child_sig_handler] (0x1000): Waiting for child [2290]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [child_sig_handler] (0x0100): child [2290] finished successfully. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_cli_connect_recv] (0x0400): Connection established. (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'dc0.ad.domain.com' as 'working' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [set_server_common_status] (0x0100): Marking server 'dc0.ad.domain.com' as 'working' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'dc0.ad.domain.com' as 'working' (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_search_user_next_base] (0x0400): Searching for users with base [dc=ad,dc=domain,dc=com] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.81:389 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(sAMAccountName=aduser)(objectclass=user)(sAMAccountName=*)(objectSID=*))][dc=ad,dc=domain,dc=com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixUserPassword] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [unixHomeDirectory] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPrincipalName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userAccountControl] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userCertificate;binary] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [mail] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 5 timeout 6 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[0x564b21579a00], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [CN=Patrick Irish,CN=Users,DC=ad,DC=domain,DC=com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [whenChanged] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [memberOf] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [uSNChanged] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [name] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectGUID] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userAccountControl] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [primaryGroupID] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectSid] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [accountExpires] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [sAMAccountName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [userPrincipalName] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[0x564b21579a00], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE] (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[0x564b21579a00], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE] (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[0x564b21579a00], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_REFERENCE] (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[0x564b21579a00], ldap[0x564b2052dee0] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 5 finished (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [generic_ext_search_handler] (0x4000): Request included referrals which were ignored. (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 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 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [generic_ext_search_handler] (0x4000): Ref: ldap://ad.domain.com/CN=Configuration,DC=ad,DC=domain,DC=com (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_search_user_process] (0x0400): Search for users, returned 1 results. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_search_user_process] (0x2000): Retrieved total 1 users (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_user] (0x0400): Save user (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_get_primary_name] (0x0400): Processing object aduser (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_user] (0x0400): Processing user aduser@ad.domain.com (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_user] (0x1000): Mapping user [aduser@ad.domain.com] objectSID [S-1-5-21-3719451043-3477422344-1472269353-1104] to unix ID (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_user] (0x2000): Adding originalDN [CN=Patrick Irish,CN=Users,DC=ad,DC=domain,DC=com] to attributes of [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_user] (0x0400): Adding original memberOf attributes to [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20190226171641.0Z] to attributes of [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_user] (0x0400): Adding user principal [aduser@AD.domain.COM] to attributes of [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowLastChange is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMin is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowMax is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowWarning is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowInactive is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowExpire is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): shadowFlag is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbLastPwdChange is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): krbPasswordExpiration is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): pwdAttribute is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedService is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adAccountExpires [9223372036854775807] to attributes of [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): Adding adUserAccountControl [66048] to attributes of [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): nsAccountLock is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedHost is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authorizedRHost is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginDisabled is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginExpirationTime is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): ndsLoginAllowedTimeMap is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): sshPublicKey is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): authType is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): userCertificate is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_attrs_add_ldap_attr] (0x2000): mail is not available for [aduser@ad.domain.com]. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sysdb_attrs_get_aliases] (0x2000): Domain is case-insensitive; will add lowercased aliases (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_user] (0x0400): Storing info for user aduser@ad.domain.com (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2053ced0 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20561a90 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20534b00 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20561a90 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2053ced0 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20561a90 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20534b00 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20561a90 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2053ced0 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20561a90 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=aduser@ad.domain.com,cn=users,cn=ad.domain.com,cn=sysdb] has set [ts_cache] attrs. (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 2) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userPassword] from [aduser@ad.domain.com] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156cf60 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156cf60 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [homeDirectory] from [aduser@ad.domain.com] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20534b00 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156cf60 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156cf60 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [loginShell] from [aduser@ad.domain.com] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156cf60 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156cf60 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [userCertificate] from [aduser@ad.domain.com] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20534b00 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156cf60 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156cf60 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sysdb_remove_attrs] (0x2000): Removing attribute [mail] from [aduser@ad.domain.com] (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20561a90 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156cf60 (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156cf60 "ltdb_timeout" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): cancel ldb transaction (nesting: 3) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 2) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1) (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [sdap_save_users] (0x4000): User 0 processed! (Tue Feb 26 21:30:59 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_users_done] (0x4000): Saving 1 Users - Done (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_done] (0x4000): releasing operation connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20561a90 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20534b00 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20534b00 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2053ced0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20534b00 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20534b00 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20561a90 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20534b00 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20534b00 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20561a90 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [apply_subdomain_homedir] (0x4000): Missing homedir of aduser@ad.domain.com. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2053ced0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b20534b00 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b20534b00 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sysdb_ldb_msg_difference] (0x2000): Added attr [homeDirectory] to entry [name=aduser@ad.domain.com,cn=users,cn=ad.domain.com,cn=sysdb] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): start ldb transaction (nesting: 1) (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b20534b00 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156cf60 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156cf60 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b20534b00 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 1) (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=aduser@ad.domain.com,cn=users,cn=ad.domain.com,cn=sysdb] has set [cache, ts_cache] attrs. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3719451043-3477422344-1472269353-1104))]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3719451043-3477422344-1472269353-1104))][cn=Default Trust View,cn=views,cn=accounts,dc=int,dc=domain,dc=com]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 10 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 10 timeout 6 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b20540450], connected[1], ops[(nil)], ldap[0x564b2052dee0] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[0x564b20569790], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 10 finished (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3719451043-3477422344-1472269353-1104))]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2156cf60 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b21575da0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2156cf60 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b205148c0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2157b280 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b21575da0 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2156cf60 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b205148c0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2157b280 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b205148c0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 0/1 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_initgr_get_overrides_step] (0x1000): Fetching group S-1-5-21-3719451043-3477422344-1472269353-512 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_connect_done] (0x4000): Searching for overrides in view [Default Trust View] with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3719451043-3477422344-1472269353-512))]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3719451043-3477422344-1472269353-512))][cn=Default Trust View,cn=views,cn=accounts,dc=int,dc=domain,dc=com]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 11 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 11 timeout 6 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[0x564b21570430], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 11 finished (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaOverrideAnchor)(ipaAnchorUUID=:SID:S-1-5-21-3719451043-3477422344-1472269353-512))]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_initgr_get_overrides_step] (0x1000): Processing group 1/1 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_search_bases_ex_next_base] (0x0400): Issuing LDAP lookup with base [cn=accounts,dc=int,dc=domain,dc=com] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [objectClass=ipaexternalgroup][cn=accounts,dc=int,dc=domain,dc=com]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 12 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 12 timeout 60 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[0x564b20533a80], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ad_admins_external,cn=groups,cn=accounts,dc=int,dc=domain,dc=com]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [description] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaUniqueID] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaExternalMember] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[0x564b20533a80], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ad_users_external,cn=groups,cn=accounts,dc=int,dc=domain,dc=com]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [description] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaUniqueID] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaExternalMember] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[0x564b20533a80], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 12 finished (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_search_bases_ex_done] (0x0400): Receiving data from base [cn=accounts,dc=int,dc=domain,dc=com] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_get_ext_groups_done] (0x0400): [2] external groups found. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2157c270 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2157b280 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2157c270 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2157b280 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2157c270 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b205148c0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2157b280 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b205148c0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2157b280 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b205148c0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2157b280 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156cf60 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2157b280 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b21574960 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b21574a20 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156cf60 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2157b280 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b21574960 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b21574a20 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b21574960 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [find_ipa_ext_memberships] (0x4000): SID [S-1-5-21-3719451043-3477422344-1472269353-1104] not found in ext group hash. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [find_ipa_ext_memberships] (0x4000): SID [S-1-5-21-3719451043-3477422344-1472269353-512] not found in ext group hash. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [find_ipa_ext_memberships] (0x0400): No external groupmemberships found. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_add_ext_groups_step] (0x4000): No external groups memberships found. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_req_done] (0x0400): DP Request [Account #26]: Request handler finished [0]: Success (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [_dp_req_recv] (0x0400): DP Request [Account #26]: Receiving request data. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #26]: Finished. Success. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_req_reply_std] (0x1000): DP Request [Account #26]: Returning [Success]: 0,0,Success (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::ad.domain.com:name=aduser@ad.domain.com] from reply table (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): DP Request [Account #26]: Request removed. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[(nil)], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x564b204fa2a0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.getAccountInfo on path /org/freedesktop/sssd/dataprovider (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=aduser@ad.domain.com] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b21574960 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156f3e0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b21574960 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156f3e0 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b21574960 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b215701f0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156f3e0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b215701f0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2156f3e0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b21574a20 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2156f3e0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2053ced0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b21574f70 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b21574a20 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2156f3e0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b21574f70 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2053ced0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #27]: New request. Flags [0x0001]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Tue Feb 26 21:31:00 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))]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_print_server] (0x2000): Searching 10.10.60.61:389 (Tue Feb 26 21:31:00 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]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 13 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_add] (0x2000): New operation 13 timeout 6 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[0x564b2050f560], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_op_destructor] (0x2000): Operation 13 finished (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_get_ad_override_done] (0x4000): No override found with filter [(&(objectClass=ipaUserOverride)(uid=aduser))]. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain int.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sss_domain_get_state] (0x1000): Domain ad.domain.com is Active (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b21574f70 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156f3e0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b21574f70 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156f3e0 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b21574f70 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b2156d1e0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156f3e0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b2156d1e0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156f3e0 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b2156d1e0 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x564b21574f70 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x564b2156f3e0 (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Running timer event 0x564b21574f70 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Destroying timer event 0x564b2156f3e0 "ltdb_timeout" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ldb] (0x4000): Ending timer event 0x564b21574f70 "ltdb_callback" (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [check_if_pac_is_available] (0x0400): PAC available but too old. (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_id_op_connect_step] (0x4000): beginning to connect (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_gc_ad.domain.com' (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [get_port_status] (0x1000): Port status of port 0 for server '(no name)' is 'neutral' (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Tue Feb 26 21:31:00 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 (Tue Feb 26 21:31:00 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' (Tue Feb 26 21:31:00 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' (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: sh[0x564b205462e0], connected[1], ops[(nil)], ldap[0x564b20515210] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_discover_srv_done] (0x0040): SRV query failed [4]: Domain name not found (Tue Feb 26 21:31:00 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' (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.ad.domain.com' (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_getsrv_done] (0x1000): Using TTL [600] (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [fo_discover_srv_done] (0x0400): Got 1 servers (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ad_get_dc_servers_done] (0x0400): Found 1 domain controllers in domain ad.domain.com (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [sdap_connect_host_send] (0x0400): Resolving host dc0.ad.domain.com (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_is_address] (0x4000): [dc0.ad.domain.com] does not look like an IP address (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in files (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'dc0.ad.domain.com' in files (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'dc0.ad.domain.com' in DNS (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Tue Feb 26 21:31:00 2019) [sssd[be[int.domain.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
On Sat, Mar 02, 2019 at 04:53:28AM -0000, Patrick Irish via FreeIPA-users wrote:
Is there any more logs you guys would need?
Yes, please send the full logs covering the login attempt, they might look similar that the logs are not repeating.
bye, Sumit
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
I tried to reply earlier but the reply was rejected because of length. Here is the complete log https://pastebin.com/c34RJZB2 . Let me know what else I can get you.
On Thu, Mar 07, 2019 at 05:18:25AM -0000, Patrick Irish via FreeIPA-users wrote:
I tried to reply earlier but the reply was rejected because of length. Here is the complete log https://pastebin.com/c34RJZB2 . Let me know what else I can get you.
Looks like SSSD cannot lookup global catalog servers.
Can you check if
host -t SRV _gc._tcp.Default-First-Site-Name._sites.ad.domain.com
or
host -t SRV _gc._tcp.ad.domain.com
return anything?
bye, Sumit
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
You are a gentleman and a scholar, that was it. Thank you! I had only checked the SRV records that was listed in the documentation.
On Fri, Mar 08, 2019 at 03:11:22AM -0000, Patrick Irish via FreeIPA-users wrote:
You are a gentleman and a scholar, that was it. Thank you! I had only checked the SRV records that was listed in the documentation.
Glad I could help. Which documentation are you referring to, maybe it would be worth to extend the documentation.
bye, Sumit
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
I was following the documentation here https://www.freeipa.org/page/Active_Directory_trust_setup Is there a different doc I should have followed?
On Sun, Mar 10, 2019 at 05:28:15AM -0000, Patrick Irish via FreeIPA-users wrote:
I was following the documentation here https://www.freeipa.org/page/Active_Directory_trust_setup Is there a different doc I should have followed?
Ok, thanks. The checks in this document are just trying to make sure that the basics are working. A AD DNS server should have the _gc SRV entries by default and so for a typically setup it should be sufficient to check just one type of SRV records. Are you using an external DNS server where you have to add the DNS records manually?
bye, Sumit
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
This is a home lab where I'm trying to learn how to make Linux and AD play nice together. I use the dns in my router and havenm't gotten AD to be able to update dns records yet. I didn't know how much AD relied on dns records for things. I was able to get a windows pc to join the domain by mirroring the freeipa generated dns records but changing for the AD domain. Once I had the windows machine joined I figured AD was more or less functional. Thank you again for your help.
Patrick Irish via FreeIPA-users wrote:
This is a home lab where I'm trying to learn how to make Linux and AD play nice together. I use the dns in my router and havenm't gotten AD to be able to update dns records yet. I didn't know how much AD relied on dns records for things. I was able to get a windows pc to join the domain by mirroring the freeipa generated dns records but changing for the AD domain. Once I had the windows machine joined I figured AD was more or less functional. Thank you again for your help.
Please clarify the problem you're having. Something about DNS but I can't tell what the problem is or what the parties are (you mention a router).
A windows machine joined which domain, the AD domain? IPA shouldn't be involved in that at all.
rob
The issue has been resolved. I was trying to provide Sumit with additional context. This thread can be considered closed.
freeipa-users@lists.fedorahosted.org
-
Alexander Bokovoy -
Patrick Irish -
Rob Crittenden -
Sumit Bose