[2020/10/27 11:36:13.576201, 5, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/debug.c:809(debug_dump_status) INFO: Current debug levels: all: 10 tdb: 10 printdrivers: 10 lanman: 10 smb: 10 rpc_parse: 10 rpc_srv: 10 rpc_cli: 10 passdb: 10 sam: 10 auth: 10 winbind: 10 vfs: 10 idmap: 10 quota: 10 acls: 10 locking: 10 msdfs: 10 dmapi: 10 registry: 10 scavenger: 10 dns: 10 ldb: 10 tevent: 10 auth_audit: 10 auth_json_audit: 10 kerberos: 10 drs_repl: 10 smb2: 10 smb2_credits: 10 dsdb_audit: 10 dsdb_json_audit: 10 dsdb_password_audit: 10 dsdb_password_json_audit: 10 dsdb_transaction_audit: 10 dsdb_transaction_json_audit: 10 dsdb_group_audit: 10 dsdb_group_json_audit: 10 [2020/10/27 11:36:49.433971, 4, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:1626(child_handler) child daemon request 56 [2020/10/27 11:36:49.434070, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual.c:770(child_process_request) child_process_request: request fn NDRCMD [2020/10/27 11:36:49.434152, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_dual_ndr.c:362(winbindd_dual_ndrcmd) winbindd_dual_ndrcmd: Running command WBINT_PINGDC (ZTEST) [2020/10/27 11:36:49.434197, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:482(ndr_print_function_debug) wbint_PingDc: struct wbint_PingDc in: struct wbint_PingDc [2020/10/27 11:36:49.434360, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:482(ndr_print_function_debug) netr_LogonControl: struct netr_LogonControl in: struct netr_LogonControl logon_server : * logon_server : '\\WIN-EJ7MV1SFC5N.ztest.ad' function_code : NETLOGON_CONTROL_QUERY (1) level : 0x00000002 (2) [2020/10/27 11:36:49.434549, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:433(ndr_print_debug) &r: struct ncacn_packet rpc_vers : 0x05 (5) rpc_vers_minor : 0x00 (0) ptype : DCERPC_PKT_REQUEST (0) pfc_flags : 0x03 (3) 1: DCERPC_PFC_FLAG_FIRST 1: DCERPC_PFC_FLAG_LAST 0: DCERPC_PFC_FLAG_PENDING_CANCEL_OR_HDR_SIGNING 0: DCERPC_PFC_FLAG_CONC_MPX 0: DCERPC_PFC_FLAG_DID_NOT_EXECUTE 0: DCERPC_PFC_FLAG_MAYBE 0: DCERPC_PFC_FLAG_OBJECT_UUID drep: ARRAY(4) [0] : 0x10 (16) [1] : 0x00 (0) [2] : 0x00 (0) [3] : 0x00 (0) frag_length : 0x0018 (24) auth_length : 0x0038 (56) call_id : 0x00000012 (18) u : union dcerpc_payload(case 0) request: struct dcerpc_request alloc_hint : 0x00000050 (80) context_id : 0x0000 (0) opnum : 0x000c (12) object : union dcerpc_object(case 0) empty: struct dcerpc_empty stub_and_verifier : DATA_BLOB length=0 [2020/10/27 11:36:49.435042, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:433(ndr_print_debug) &r: struct dcerpc_auth auth_type : DCERPC_AUTH_TYPE_SCHANNEL (68) auth_level : DCERPC_AUTH_LEVEL_PRIVACY (6) auth_pad_length : 0x00 (0) auth_reserved : 0x00 (0) auth_context_id : 0x00000001 (1) credentials : DATA_BLOB length=0 [2020/10/27 11:36:49.435302, 5, pid=23765, effective(0, 0), real(0, 0), class=rpc_cli] ../../source3/rpc_client/cli_pipe.c:827(rpc_api_pipe_send) rpc_api_pipe: host WIN-EJ7MV1SFC5N.ztest.ad [2020/10/27 11:36:49.435338, 5, pid=23765, effective(0, 0), real(0, 0), class=rpc_cli] ../../source3/rpc_client/cli_pipe.c:179(rpc_write_send) rpc_write_send: data_to_write: 168 [2020/10/27 11:36:49.438818, 5, pid=23765, effective(0, 0), real(0, 0), class=rpc_cli] ../../source3/rpc_client/cli_pipe.c:99(rpc_read_send) rpc_read_send: data_to_read: 16 [2020/10/27 11:36:49.438894, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:433(ndr_print_debug) state->pkt: struct ncacn_packet rpc_vers : 0x05 (5) rpc_vers_minor : 0x00 (0) ptype : DCERPC_PKT_FAULT (3) pfc_flags : 0x03 (3) 1: DCERPC_PFC_FLAG_FIRST 1: DCERPC_PFC_FLAG_LAST 0: DCERPC_PFC_FLAG_PENDING_CANCEL_OR_HDR_SIGNING 0: DCERPC_PFC_FLAG_CONC_MPX 0: DCERPC_PFC_FLAG_DID_NOT_EXECUTE 0: DCERPC_PFC_FLAG_MAYBE 0: DCERPC_PFC_FLAG_OBJECT_UUID drep: ARRAY(4) [0] : 0x10 (16) [1] : 0x00 (0) [2] : 0x00 (0) [3] : 0x00 (0) frag_length : 0x0020 (32) auth_length : 0x0000 (0) call_id : 0x00000012 (18) u : union dcerpc_payload(case 3) fault: struct dcerpc_fault alloc_hint : 0x00000020 (32) context_id : 0x0000 (0) cancel_count : 0x00 (0) flags : 0x00 (0) 0: DCERPC_FAULT_FLAG_EXTENDED_ERROR_INFORMATION status : DCERPC_FAULT_ACCESS_DENIED (5) reserved : 0x00000000 (0) error_and_verifier : DATA_BLOB length=0 [2020/10/27 11:36:49.439439, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_cli] ../../source3/rpc_client/cli_pipe.c:569(cli_pipe_validate_current_pdu) ../../source3/rpc_client/cli_pipe.c:569: RPC fault code DCERPC_FAULT_ACCESS_DENIED received from host WIN-EJ7MV1SFC5N.ztest.ad! [2020/10/27 11:36:49.439487, 10, pid=23765, effective(0, 0), real(0, 0), class=rpc_cli] ../../source3/rpc_client/cli_pipe.c:979(rpc_api_pipe_got_pdu) rpc_api_pipe: got frag len of 32 at offset 0: NT_STATUS_ACCESS_DENIED [2020/10/27 11:36:49.439657, 5, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/smb/smb2_signing.c:174(smb2_signing_sign_pdu) signed SMB2 message [2020/10/27 11:36:49.441164, 3, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:2157(connection_ok) connection_ok: Connection to WIN-EJ7MV1SFC5N.ztest.ad for domain ZTEST is not connected [2020/10/27 11:36:49.441232, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:216(saf_fetch) saf_fetch: Returning "WIN-EJ7MV1SFC5N.ztest.ad" for "ZTEST" domain [2020/10/27 11:36:49.441260, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ZTEST server WIN-EJ7MV1SFC5N.ztest.ad [2020/10/27 11:36:49.441281, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1917(cm_open_connection) cm_open_connection: saf_servername is 'WIN-EJ7MV1SFC5N.ztest.ad' for domain ZTEST [2020/10/27 11:36:49.441311, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ZTEST.AD': "Default-First-Site-Name" [2020/10/27 11:36:49.441332, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up WIN-EJ7MV1SFC5N.ztest.ad#20 (sitename Default-First-Site-Name) [2020/10/27 11:36:49.441356, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:166(namecache_fetch) name WIN-EJ7MV1SFC5N.ztest.ad#20 found. [2020/10/27 11:36:49.441399, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:36:49.441438, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:255(ads_try_connect) ads_try_connect: sending CLDAP request to 10.20.88.51 (realm: ztest.ad) [2020/10/27 11:36:56.340623, 2, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/cldap.c:401(ads_cldap_netlogon) ads_cldap_netlogon: did not get a reply [2020/10/27 11:36:56.340711, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:260(ads_try_connect) ads_try_connect: CLDAP request 10.20.88.51 failed. [2020/10/27 11:36:56.340756, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NEG_CONN_CACHE/ZTEST,WIN-EJ7MV1SFC5N.ztest.ad] and timeout=[Tue Oct 27 11:37:56 2020 UTC] (60 seconds ahead) [2020/10/27 11:36:56.340846, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:190(add_failed_connection_entry) add_failed_connection_entry: added domain ZTEST (WIN-EJ7MV1SFC5N.ztest.ad) to failed conn cache [2020/10/27 11:36:56.340878, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAFJOIN/DOMAIN/ZTEST]) [2020/10/27 11:36:56.340901, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAF/DOMAIN/ZTEST]) [2020/10/27 11:36:56.340926, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:164(saf_delete) saf_delete: domain = [ZTEST] [2020/10/27 11:36:56.340946, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NEG_CONN_CACHE/ztest.ad,WIN-EJ7MV1SFC5N.ztest.ad] and timeout=[Tue Oct 27 11:37:56 2020 UTC] (60 seconds ahead) [2020/10/27 11:36:56.340985, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:190(add_failed_connection_entry) add_failed_connection_entry: added domain ztest.ad (WIN-EJ7MV1SFC5N.ztest.ad) to failed conn cache [2020/10/27 11:36:56.341007, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAFJOIN/DOMAIN/ZTEST.AD]) [2020/10/27 11:36:56.341028, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAF/DOMAIN/ZTEST.AD]) [2020/10/27 11:36:56.341052, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:164(saf_delete) saf_delete: domain = [ztest.ad] [2020/10/27 11:36:56.341074, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1955(cm_open_connection) cm_open_connection: dcname is 'WIN-EJ7MV1SFC5N.ztest.ad' for domain ZTEST [2020/10/27 11:36:56.341155, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741823 for domain ZTEST server WIN-EJ7MV1SFC5N.ztest.ad [2020/10/27 11:36:56.341208, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:36:56.341234, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery_dc.c:78(ads_dc_name) ads_dc_name: domain=ZTEST [2020/10/27 11:36:56.341258, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:36:56.341279, 6, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:420(resolve_and_ping_dns) resolve_and_ping_dns: (cldap) looking for realm 'ztest.ad' [2020/10/27 11:36:56.341317, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3322(get_sorted_dc_list) get_sorted_dc_list: attempting lookup for name ztest.ad (sitename Default-First-Site-Name) [2020/10/27 11:36:56.341345, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:36:56.341368, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:36:56.341389, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#1c (sitename Default-First-Site-Name) [2020/10/27 11:36:56.341416, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:166(namecache_fetch) name ztest.ad#1C found. [2020/10/27 11:36:56.341448, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:36:56.341471, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:36:56.341497, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:36:56.341521, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:36:56.341540, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:36:56.341559, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:36:56.341577, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.88.51:389 10.20.90.85:389 [2020/10/27 11:36:56.341602, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:36:56.341623, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:255(ads_try_connect) ads_try_connect: sending CLDAP request to 10.20.88.51 (realm: ztest.ad) [2020/10/27 11:37:03.579411, 2, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/cldap.c:401(ads_cldap_netlogon) ads_cldap_netlogon: did not get a reply [2020/10/27 11:37:03.579503, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:260(ads_try_connect) ads_try_connect: CLDAP request 10.20.88.51 failed. [2020/10/27 11:37:03.579542, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NEG_CONN_CACHE/ztest.ad,10.20.88.51] and timeout=[Tue Oct 27 11:38:03 2020 UTC] (60 seconds ahead) [2020/10/27 11:37:03.579617, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:190(add_failed_connection_entry) add_failed_connection_entry: added domain ztest.ad (10.20.88.51) to failed conn cache [2020/10/27 11:37:03.579651, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:37:03.579675, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:255(ads_try_connect) ads_try_connect: sending CLDAP request to 10.20.90.85 (realm: ztest.ad) [2020/10/27 11:37:03.581591, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:433(ndr_print_debug) &response->data.nt5_ex: struct NETLOGON_SAM_LOGON_RESPONSE_EX command : LOGON_SAM_LOGON_RESPONSE_EX (23) sbz : 0x0000 (0) server_type : 0x0000f1fc (61948) 0: NBT_SERVER_PDC 1: NBT_SERVER_GC 1: NBT_SERVER_LDAP 1: NBT_SERVER_DS 1: NBT_SERVER_KDC 1: NBT_SERVER_TIMESERV 1: NBT_SERVER_CLOSEST 1: NBT_SERVER_WRITABLE 0: NBT_SERVER_GOOD_TIMESERV 0: NBT_SERVER_NDNC 0: NBT_SERVER_SELECT_SECRET_DOMAIN_6 1: NBT_SERVER_FULL_SECRET_DOMAIN_6 1: NBT_SERVER_ADS_WEB_SERVICE 1: NBT_SERVER_DS_8 0: NBT_SERVER_HAS_DNS_NAME 0: NBT_SERVER_IS_DEFAULT_NC 0: NBT_SERVER_FOREST_ROOT domain_uuid : d602c5bc-0513-4954-b09a-05ad2ad71b68 forest : 'ztest.ad' dns_domain : 'ztest.ad' pdc_dns_name : 'WIN-JIE7G4JU4L2.ztest.ad' domain_name : 'ZTEST' pdc_name : 'WIN-JIE7G4JU4L2' user_name : '' server_site : 'Default-First-Site-Name' client_site : 'Default-First-Site-Name' sockaddr_size : 0x00 (0) sockaddr: struct nbt_sockaddr sockaddr_family : 0x00000000 (0) pdc_ip : (null) remaining : DATA_BLOB length=0 next_closest_site : NULL nt_version : 0x00000005 (5) 1: NETLOGON_NT_VERSION_1 0: NETLOGON_NT_VERSION_5 1: NETLOGON_NT_VERSION_5EX 0: NETLOGON_NT_VERSION_5EX_WITH_IP 0: NETLOGON_NT_VERSION_WITH_CLOSEST_SITE 0: NETLOGON_NT_VERSION_AVOID_NT4EMUL 0: NETLOGON_NT_VERSION_PDC 0: NETLOGON_NT_VERSION_IP 0: NETLOGON_NT_VERSION_LOCAL 0: NETLOGON_NT_VERSION_GC lmnt_token : 0xffff (65535) lm20_token : 0xffff (65535) [2020/10/27 11:37:03.582488, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ZTEST], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:37:03.582518, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587878176 seconds ahead) [2020/10/27 11:37:03.582559, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ztest.ad], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:37:03.582579, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST.AD] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587878176 seconds ahead) [2020/10/27 11:37:03.582617, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:636(ads_connect) Successfully contacted LDAP server 10.20.90.85 [2020/10/27 11:37:03.582646, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:37:03.582675, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:213(ads_closest_dc) ads_closest_dc: NBT_SERVER_CLOSEST flag set [2020/10/27 11:37:03.582730, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:691(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: fname = /var/lock/samba/smb_krb5/krb5.conf.ZTEST, realm = ztest.ad, domain = ZTEST [2020/10/27 11:37:03.582763, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:37:03.582788, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:37:03.582818, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename Default-First-Site-Name) [2020/10/27 11:37:03.582849, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:37:03.582915, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:37:03.582939, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:03.583004, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] B3 17 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 ........ ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:37:04.584283, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:37:04.584365, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:37:04.584392, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:04.584495, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 43 9E 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 C....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:37:04.586065, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 43 9E 85 80 00 01 00 01 00 00 00 01 09 5F 6B 65 C....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 00 .....!.. ...X. .. [0060] 00 64 00 58 0F 77 69 6E 2D 65 6A 37 6D 76 31 73 .d.X.win -ej7mv1s [0070] 66 63 35 6E 05 7A 74 65 73 74 02 61 64 00 C0 64 fc5n.zte st.ad..d [0080] 00 01 00 01 00 00 0E 10 00 04 0A 14 58 33 ........ ....X3 [2020/10/27 11:37:04.586349, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/1/0/0 recs [2020/10/27 11:37:04.586418, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:04.586443, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 1 addresses: 10.20.88.51:88 [2020/10/27 11:37:04.586469, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 1 DC's from auto lookup [2020/10/27 11:37:04.586520, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741823 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:37:04.586542, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3202(get_dc_list) get_dc_list: negative entry 10.20.88.51 removed from DC list [2020/10/27 11:37:04.586559, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:04.586575, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 0 ip addresses in an ordered list [2020/10/27 11:37:04.586592, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: [2020/10/27 11:37:04.586610, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:452(get_kdc_ip_string) got 0 addresses from site Default-First-Site-Name search [2020/10/27 11:37:04.586639, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:37:04.586662, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:37:04.586680, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename (null)) [2020/10/27 11:37:04.586705, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:37:04.586763, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:37:04.586787, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:04.586856, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] E7 27 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 .'...... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:37:05.951822, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:37:05.951923, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:37:05.951951, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:05.952070, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 9F 79 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 .y...... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:37:05.953627, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 9F 79 85 80 00 01 00 01 00 00 00 01 09 5F 6B 65 .y...... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 !.....!. ....X. . [0040] 00 00 64 00 58 0F 77 69 6E 2D 65 6A 37 6D 76 31 ..d.X.wi n-ej7mv1 [0050] 73 66 63 35 6E 05 7A 74 65 73 74 02 61 64 00 C0 sfc5n.zt est.ad.. [0060] 45 00 01 00 01 00 00 0E 10 00 04 0A 14 58 33 E....... .....X3 [2020/10/27 11:37:05.953846, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/1/0/0 recs [2020/10/27 11:37:05.953920, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:05.953945, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 1 addresses: 10.20.88.51:88 [2020/10/27 11:37:05.953972, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 1 DC's from auto lookup [2020/10/27 11:37:05.954022, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741823 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:37:05.954044, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3202(get_dc_list) get_dc_list: negative entry 10.20.88.51 removed from DC list [2020/10/27 11:37:05.954061, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:05.954078, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 0 ip addresses in an ordered list [2020/10/27 11:37:05.954142, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: [2020/10/27 11:37:05.954167, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:458(get_kdc_ip_string) got 0 addresses from site-less search [2020/10/27 11:37:05.954186, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:490(get_kdc_ip_string) get_kdc_ip_string: 0 additional KDCs to test [2020/10/27 11:37:05.954203, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:550(get_kdc_ip_string) get_kdc_ip_string: Returning kdc = 10.20.90.85 [2020/10/27 11:37:05.954301, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:822(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: wrote file /var/lock/samba/smb_krb5/krb5.conf.ZTEST with realm ZTEST.AD KDC list = kdc = 10.20.90.85 [2020/10/27 11:37:05.954343, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery_dc.c:152(ads_dc_name) ads_dc_name: using server='WIN-JIE7G4JU4L2.ZTEST.AD' IP=10.20.90.85 [2020/10/27 11:37:05.954376, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:37:05.954397, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3322(get_sorted_dc_list) get_sorted_dc_list: attempting lookup for name ztest.ad (sitename Default-First-Site-Name) [2020/10/27 11:37:05.954441, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:37:05.954468, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:37:05.954486, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#1c (sitename Default-First-Site-Name) [2020/10/27 11:37:05.954512, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:166(namecache_fetch) name ztest.ad#1C found. [2020/10/27 11:37:05.954541, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:05.954561, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:37:05.954585, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741823 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:37:05.954605, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3202(get_dc_list) get_dc_list: negative entry 10.20.88.51 removed from DC list [2020/10/27 11:37:05.954626, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:37:05.954644, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:05.954663, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 1 ip addresses in an ordered list [2020/10/27 11:37:05.954680, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.90.85:389 [2020/10/27 11:37:05.954704, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ZTEST server 10.20.90.85 [2020/10/27 11:37:05.954726, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3322(get_sorted_dc_list) get_sorted_dc_list: attempting lookup for name ztest.ad (sitename NULL) [2020/10/27 11:37:05.954748, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:37:05.954769, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:37:05.954786, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#1c (sitename (null)) [2020/10/27 11:37:05.954820, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:166(namecache_fetch) name ztest.ad#1C found. [2020/10/27 11:37:05.954849, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:05.954869, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:37:05.954893, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741823 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:37:05.954913, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3202(get_dc_list) get_dc_list: negative entry 10.20.88.51 removed from DC list [2020/10/27 11:37:05.954943, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:37:05.954963, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:05.954982, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 1 ip addresses in an ordered list [2020/10/27 11:37:05.954999, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.90.85:389 [2020/10/27 11:37:05.955021, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ZTEST server 10.20.90.85 [2020/10/27 11:37:05.955077, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/lib/util_sock.c:515(open_socket_out_send) Connecting to 10.20.90.85 at port 445 [2020/10/27 11:37:05.956991, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:255(ads_try_connect) ads_try_connect: sending CLDAP request to 10.20.90.85 (realm: ztest.ad) [2020/10/27 11:37:05.958766, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:433(ndr_print_debug) &response->data.nt5_ex: struct NETLOGON_SAM_LOGON_RESPONSE_EX command : LOGON_SAM_LOGON_RESPONSE_EX (23) sbz : 0x0000 (0) server_type : 0x0000f1fc (61948) 0: NBT_SERVER_PDC 1: NBT_SERVER_GC 1: NBT_SERVER_LDAP 1: NBT_SERVER_DS 1: NBT_SERVER_KDC 1: NBT_SERVER_TIMESERV 1: NBT_SERVER_CLOSEST 1: NBT_SERVER_WRITABLE 0: NBT_SERVER_GOOD_TIMESERV 0: NBT_SERVER_NDNC 0: NBT_SERVER_SELECT_SECRET_DOMAIN_6 1: NBT_SERVER_FULL_SECRET_DOMAIN_6 1: NBT_SERVER_ADS_WEB_SERVICE 1: NBT_SERVER_DS_8 0: NBT_SERVER_HAS_DNS_NAME 0: NBT_SERVER_IS_DEFAULT_NC 0: NBT_SERVER_FOREST_ROOT domain_uuid : d602c5bc-0513-4954-b09a-05ad2ad71b68 forest : 'ztest.ad' dns_domain : 'ztest.ad' pdc_dns_name : 'WIN-JIE7G4JU4L2.ztest.ad' domain_name : 'ZTEST' pdc_name : 'WIN-JIE7G4JU4L2' user_name : '' server_site : 'Default-First-Site-Name' client_site : 'Default-First-Site-Name' sockaddr_size : 0x00 (0) sockaddr: struct nbt_sockaddr sockaddr_family : 0x00000000 (0) pdc_ip : (null) remaining : DATA_BLOB length=0 next_closest_site : NULL nt_version : 0x00000005 (5) 1: NETLOGON_NT_VERSION_1 0: NETLOGON_NT_VERSION_5 1: NETLOGON_NT_VERSION_5EX 0: NETLOGON_NT_VERSION_5EX_WITH_IP 0: NETLOGON_NT_VERSION_WITH_CLOSEST_SITE 0: NETLOGON_NT_VERSION_AVOID_NT4EMUL 0: NETLOGON_NT_VERSION_PDC 0: NETLOGON_NT_VERSION_IP 0: NETLOGON_NT_VERSION_LOCAL 0: NETLOGON_NT_VERSION_GC lmnt_token : 0xffff (65535) lm20_token : 0xffff (65535) [2020/10/27 11:37:05.959680, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ZTEST], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:37:05.959711, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587878174 seconds ahead) [2020/10/27 11:37:05.959755, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ztest.ad], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:37:05.959775, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST.AD] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587878174 seconds ahead) [2020/10/27 11:37:05.959824, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:636(ads_connect) Successfully contacted LDAP server 10.20.90.85 [2020/10/27 11:37:05.959852, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:79(namecache_store) namecache_store: storing 1 address for WIN-JIE7G4JU4L2.ztest.ad#20: 10.20.90.85 [2020/10/27 11:37:05.959879, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NBT/WIN-JIE7G4JU4L2.ZTEST.AD#20] and timeout=[Tue Oct 27 11:48:05 2020 UTC] (660 seconds ahead) [2020/10/27 11:37:05.959915, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1441(dcip_check_name) dcip_check_name: flags = 0xf1fc [2020/10/27 11:37:05.959935, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:213(ads_closest_dc) ads_closest_dc: NBT_SERVER_CLOSEST flag set [2020/10/27 11:37:05.959955, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ZTEST.AD': "Default-First-Site-Name" [2020/10/27 11:37:05.959994, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:691(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: fname = /var/lock/samba/smb_krb5/krb5.conf.ZTEST, realm = ztest.ad, domain = ZTEST [2020/10/27 11:37:05.960022, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:37:05.960045, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:37:05.960063, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename Default-First-Site-Name) [2020/10/27 11:37:05.960085, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:37:05.960199, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:37:05.960226, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:05.960285, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] C9 D9 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 ........ ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:37:06.961495, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:37:06.961584, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:37:06.961611, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:06.961717, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] F9 59 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 .Y...... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:37:06.963506, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] F9 59 85 80 00 01 00 01 00 00 00 01 09 5F 6B 65 .Y...... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 00 .....!.. ...X. .. [0060] 00 64 00 58 0F 77 69 6E 2D 65 6A 37 6D 76 31 73 .d.X.win -ej7mv1s [0070] 66 63 35 6E 05 7A 74 65 73 74 02 61 64 00 C0 64 fc5n.zte st.ad..d [0080] 00 01 00 01 00 00 0E 10 00 04 0A 14 58 33 ........ ....X3 [2020/10/27 11:37:06.963743, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/1/0/0 recs [2020/10/27 11:37:06.963823, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:06.963852, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 1 addresses: 10.20.88.51:88 [2020/10/27 11:37:06.963877, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 1 DC's from auto lookup [2020/10/27 11:37:06.963926, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741823 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:37:06.963948, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3202(get_dc_list) get_dc_list: negative entry 10.20.88.51 removed from DC list [2020/10/27 11:37:06.963965, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:06.963982, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 0 ip addresses in an ordered list [2020/10/27 11:37:06.963998, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: [2020/10/27 11:37:06.964016, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:452(get_kdc_ip_string) got 0 addresses from site Default-First-Site-Name search [2020/10/27 11:37:06.964062, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:37:06.964149, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:37:06.964195, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename (null)) [2020/10/27 11:37:06.964224, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:37:06.964290, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:37:06.964314, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:06.964370, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 62 A5 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 b....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:37:09.197791, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:37:09.197897, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:37:09.197926, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:37:09.198044, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] B2 0E 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 ........ ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:37:09.199656, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] B2 0E 85 80 00 01 00 01 00 00 00 01 09 5F 6B 65 ........ ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 !.....!. ....X. . [0040] 00 00 64 00 58 0F 77 69 6E 2D 65 6A 37 6D 76 31 ..d.X.wi n-ej7mv1 [0050] 73 66 63 35 6E 05 7A 74 65 73 74 02 61 64 00 C0 sfc5n.zt est.ad.. [0060] 45 00 01 00 01 00 00 0E 10 00 04 0A 14 58 33 E....... .....X3 [2020/10/27 11:37:09.199872, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/1/0/0 recs [2020/10/27 11:37:09.199946, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:09.199972, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 1 addresses: 10.20.88.51:88 [2020/10/27 11:37:09.199999, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 1 DC's from auto lookup [2020/10/27 11:37:09.200047, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741823 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:37:09.200123, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3202(get_dc_list) get_dc_list: negative entry 10.20.88.51 removed from DC list [2020/10/27 11:37:09.200158, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:37:09.200176, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 0 ip addresses in an ordered list [2020/10/27 11:37:09.200193, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: [2020/10/27 11:37:09.200211, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:458(get_kdc_ip_string) got 0 addresses from site-less search [2020/10/27 11:37:09.200230, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:490(get_kdc_ip_string) get_kdc_ip_string: 0 additional KDCs to test [2020/10/27 11:37:09.200247, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:550(get_kdc_ip_string) get_kdc_ip_string: Returning kdc = 10.20.90.85 [2020/10/27 11:37:09.200345, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:822(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: wrote file /var/lock/samba/smb_krb5/krb5.conf.ZTEST with realm ZTEST.AD KDC list = kdc = 10.20.90.85 [2020/10/27 11:37:09.200394, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:91(saf_store) saf_store: domain = [ZTEST], server = [WIN-JIE7G4JU4L2.ztest.ad], expire = [1603799529] [2020/10/27 11:37:09.200418, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[SAF/DOMAIN/ZTEST] and timeout=[Tue Oct 27 11:52:09 2020 UTC] (900 seconds ahead) [2020/10/27 11:37:09.200468, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:91(saf_store) saf_store: domain = [ztest.ad], server = [WIN-JIE7G4JU4L2.ztest.ad], expire = [1603799529] [2020/10/27 11:37:09.200489, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[SAF/DOMAIN/ZTEST.AD] and timeout=[Tue Oct 27 11:52:09 2020 UTC] (900 seconds ahead) [2020/10/27 11:37:09.200531, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1057(cm_prepare_connection) cm_prepare_connection: connecting to DC WIN-JIE7G4JU4L2.ztest.ad for domain ZTEST [2020/10/27 11:37:09.200696, 5, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util_net.c:1055(print_socket_options) Socket options: SO_KEEPALIVE = 0 SO_REUSEADDR = 0 SO_BROADCAST = 0 TCP_NODELAY = 1 TCP_KEEPCNT = 9 TCP_KEEPIDLE = 7200 TCP_KEEPINTVL = 75 IPTOS_LOWDELAY = 0 IPTOS_THROUGHPUT = 0 SO_REUSEPORT = 0 SO_SNDBUF = 87040 SO_RCVBUF = 372480 SO_SNDLOWAT = 1 SO_RCVLOWAT = 1 SO_SNDTIMEO = 0 SO_RCVTIMEO = 0 TCP_QUICKACK = 1 TCP_DEFER_ACCEPT = 0 [2020/10/27 11:37:09.203075, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:221(samba_ldb_connect) [2020/10/27 11:37:09.203267, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: SEARCH dn: @MODULES scope: base expr: (@LIST=*) attr: @LIST control: [2020/10/27 11:37:09.203319, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_lock [2020/10/27 11:37:09.203344, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_next_request: (tdb)->search [2020/10/27 11:37:09.203378, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_callback": 0x7fdcdb11f2a0 [2020/10/27 11:37:09.203403, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_timeout": 0x7fdcdb11fde0 [2020/10/27 11:37:09.203429, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Running timer event 0x7fdcdb11f2a0 "ldb_kv_callback" [2020/10/27 11:37:09.203463, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_response: DONE error: 0 [2020/10/27 11:37:09.203491, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_unlock [2020/10/27 11:37:09.203513, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fde0 "ldb_kv_timeout" [2020/10/27 11:37:09.203535, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11f2a0 "ldb_kv_callback" [2020/10/27 11:37:09.203571, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: no modules required by the db [2020/10/27 11:37:09.203591, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: No modules specified for this database [2020/10/27 11:37:09.203618, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: REGISTER_CONTROL 1.2.840.113556.1.4.1413 control: [2020/10/27 11:37:09.203649, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_asprintf/set_errstring: unable to find module or backend to handle operation: request [2020/10/27 11:37:09.203690, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: SEARCH dn: scope: base expr: (objectClass=*) attr: rootDomainNamingContext attr: configurationNamingContext attr: schemaNamingContext attr: defaultNamingContext control: [2020/10/27 11:37:09.203740, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_lock [2020/10/27 11:37:09.203762, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_next_request: (tdb)->search [2020/10/27 11:37:09.203783, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_callback": 0x7fdcdb11fae0 [2020/10/27 11:37:09.203816, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_timeout": 0x7fdcdb11fde0 [2020/10/27 11:37:09.203843, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Running timer event 0x7fdcdb11fae0 "ldb_kv_callback" [2020/10/27 11:37:09.203868, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_asprintf/set_errstring: NULL Base DN invalid for a base search [2020/10/27 11:37:09.203893, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_response: DONE error: 34 msg: NULL Base DN invalid for a base search [2020/10/27 11:37:09.203921, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_unlock [2020/10/27 11:37:09.203953, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fde0 "ldb_kv_timeout" [2020/10/27 11:37:09.203979, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fae0 "ldb_kv_callback" [2020/10/27 11:37:09.204007, 3, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:332(ldb_wrap_connect) ldb_wrap open of secrets.ldb [2020/10/27 11:37:09.204057, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: SEARCH dn: cn=Primary Domains scope: sub expr: (&(flatname=ZTEST)(objectclass=primaryDomain)) attr: control: [2020/10/27 11:37:09.204152, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_lock [2020/10/27 11:37:09.204183, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_next_request: (tdb)->search [2020/10/27 11:37:09.204204, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_callback": 0x7fdcdb11f2a0 [2020/10/27 11:37:09.204227, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_timeout": 0x7fdcdb11fde0 [2020/10/27 11:37:09.204250, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Running timer event 0x7fdcdb11f2a0 "ldb_kv_callback" [2020/10/27 11:37:09.204356, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_response: DONE error: 0 [2020/10/27 11:37:09.204385, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_unlock [2020/10/27 11:37:09.204407, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fde0 "ldb_kv_timeout" [2020/10/27 11:37:09.204429, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11f2a0 "ldb_kv_callback" [2020/10/27 11:37:09.204461, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_asprintf/set_errstring: dsdb_search at ../../source4/dsdb/common/util.c:4760 [2020/10/27 11:37:09.204527, 5, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1156(cm_prepare_connection) connecting to WIN-JIE7G4JU4L2.ztest.ad (ZTEST, ztest.ad) with account [ZTEST\VSA-000001C7$] principal [VSA-000001C7$@ZTEST.AD] and realm [ZTEST.AD] [2020/10/27 11:37:09.204584, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/cliconnect.c:302(cli_session_creds_prepare_krb5) cli_session_creds_prepare_krb5: Doing kinit for VSA-000001C7$@ZTEST.AD to access WIN-JIE7G4JU4L2.ztest.ad [2020/10/27 11:37:09.204694, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:152(kerberos_kinit_password_ext) kerberos_kinit_password_ext: as VSA-000001C7$@ZTEST.AD using [MEMORY:cliconnect] as ccache and config [/var/lock/samba/smb_krb5/krb5.conf.ZTEST] [2020/10/27 11:37:09.608500, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:212(kerberos_kinit_password_ext) kerberos_kinit_password_ext: VSA-000001C7$@ZTEST.AD mapped to vsa-000001c7$@ZTEST.AD [2020/10/27 11:37:09.608998, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/cliconnect.c:364(cli_session_creds_prepare_krb5) cli_session_creds_prepare_krb5: Successfully authenticated as VSA-000001C7$@ZTEST.AD (vsa-000001c7$@ZTEST.AD) to access WIN-JIE7G4JU4L2.ztest.ad using Kerberos [2020/10/27 11:37:09.609293, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/cliconnect.c:1343(cli_session_setup_spnego_send) cli_session_setup_spnego_send: Connect to WIN-JIE7G4JU4L2.ztest.ad as vsa-000001c7$@ZTEST.AD using SPNEGO [2020/10/27 11:37:09.609869, 5, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec_start.c:739(gensec_start_mech) Starting GENSEC mechanism spnego [2020/10/27 11:37:09.610301, 5, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec_start.c:739(gensec_start_mech) Starting GENSEC submechanism gse_krb5 [2020/10/27 11:41:32.552378, 10, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec.c:456(gensec_update_send) gensec_update_send: gse_krb5[0x7fdcdb010960]: subreq: 0x7fdcdb092980 [2020/10/27 11:41:32.552451, 10, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec.c:456(gensec_update_send) gensec_update_send: spnego[0x7fdcdb010a60]: subreq: 0x7fdcdb128080 [2020/10/27 11:41:32.552495, 10, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec.c:514(gensec_update_done) gensec_update_done: gse_krb5[0x7fdcdb010960]: NT_STATUS_MORE_PROCESSING_REQUIRED tevent_req[0x7fdcdb092980/../../source3/librpc/crypto/gse.c:849]: state[2] error[0 (0x0)] state[struct gensec_gse_update_state (0x7fdcdb092b30)] timer[(nil)] finish[../../source3/librpc/crypto/gse.c:859] [2020/10/27 11:41:32.552570, 10, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec.c:514(gensec_update_done) gensec_update_done: spnego[0x7fdcdb010a60]: NT_STATUS_MORE_PROCESSING_REQUIRED tevent_req[0x7fdcdb128080/../../auth/gensec/spnego.c:1629]: state[2] error[0 (0x0)] state[struct gensec_spnego_update_state (0x7fdcdb128230)] timer[(nil)] finish[../../auth/gensec/spnego.c:2113] [2020/10/27 11:41:32.552743, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/cliconnect.c:1730(cli_session_setup_creds_done_spnego) SPNEGO login failed: The transport connection has been reset. [2020/10/27 11:41:32.552818, 1, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1172(cm_prepare_connection) authenticated session setup to WIN-JIE7G4JU4L2.ztest.ad using vsa-000001c7$@ZTEST.AD failed with NT_STATUS_CONNECTION_RESET [2020/10/27 11:41:32.552935, 1, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1312(cm_prepare_connection) Failed to prepare SMB connection to WIN-JIE7G4JU4L2.ztest.ad: NT_STATUS_CONNECTION_RESET [2020/10/27 11:41:32.552998, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NEG_CONN_CACHE/ZTEST,WIN-JIE7G4JU4L2.ztest.ad] and timeout=[Tue Oct 27 11:42:32 2020 UTC] (60 seconds ahead) [2020/10/27 11:41:32.553064, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:190(add_failed_connection_entry) add_failed_connection_entry: added domain ZTEST (WIN-JIE7G4JU4L2.ztest.ad) to failed conn cache [2020/10/27 11:41:32.553200, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAFJOIN/DOMAIN/ZTEST]) [2020/10/27 11:41:32.553239, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAF/DOMAIN/ZTEST]) [2020/10/27 11:41:32.553267, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:164(saf_delete) saf_delete: domain = [ZTEST] [2020/10/27 11:41:32.553289, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NEG_CONN_CACHE/ztest.ad,WIN-JIE7G4JU4L2.ztest.ad] and timeout=[Tue Oct 27 11:42:32 2020 UTC] (60 seconds ahead) [2020/10/27 11:41:32.553325, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:190(add_failed_connection_entry) add_failed_connection_entry: added domain ztest.ad (WIN-JIE7G4JU4L2.ztest.ad) to failed conn cache [2020/10/27 11:41:32.553360, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAFJOIN/DOMAIN/ZTEST.AD]) [2020/10/27 11:41:32.553383, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:333(gencache_del) Deleting cache entry (key=[SAF/DOMAIN/ZTEST.AD]) [2020/10/27 11:41:32.553408, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:164(saf_delete) saf_delete: domain = [ztest.ad] [2020/10/27 11:41:32.553437, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1955(cm_open_connection) cm_open_connection: dcname is 'WIN-JIE7G4JU4L2.ztest.ad' for domain ZTEST [2020/10/27 11:41:32.553465, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result -1073741299 for domain ZTEST server WIN-JIE7G4JU4L2.ztest.ad [2020/10/27 11:41:32.553502, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:41:32.553527, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery_dc.c:78(ads_dc_name) ads_dc_name: domain=ZTEST [2020/10/27 11:41:32.553552, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:41:32.553573, 6, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:420(resolve_and_ping_dns) resolve_and_ping_dns: (cldap) looking for realm 'ztest.ad' [2020/10/27 11:41:32.553590, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3322(get_sorted_dc_list) get_sorted_dc_list: attempting lookup for name ztest.ad (sitename Default-First-Site-Name) [2020/10/27 11:41:32.553616, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:41:32.553641, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:41:32.553661, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#1c (sitename Default-First-Site-Name) [2020/10/27 11:41:32.553687, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:166(namecache_fetch) name ztest.ad#1C found. [2020/10/27 11:41:32.553717, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:32.553737, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:41:32.553761, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:32.553801, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NEG_CONN_CACHE/ztest.ad,10.20.88.51] and timeout=[Thu Jan 1 00:00:00 1970 UTC] (-1603798892 seconds in the past) [2020/10/27 11:41:32.553847, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:41:32.553868, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:32.553897, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:41:32.553916, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.90.85:389 10.20.88.51:389 [2020/10/27 11:41:32.553942, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:32.553964, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:255(ads_try_connect) ads_try_connect: sending CLDAP request to 10.20.90.85 (realm: ztest.ad) [2020/10/27 11:41:32.556689, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:433(ndr_print_debug) &response->data.nt5_ex: struct NETLOGON_SAM_LOGON_RESPONSE_EX command : LOGON_SAM_LOGON_RESPONSE_EX (23) sbz : 0x0000 (0) server_type : 0x0000f1fc (61948) 0: NBT_SERVER_PDC 1: NBT_SERVER_GC 1: NBT_SERVER_LDAP 1: NBT_SERVER_DS 1: NBT_SERVER_KDC 1: NBT_SERVER_TIMESERV 1: NBT_SERVER_CLOSEST 1: NBT_SERVER_WRITABLE 0: NBT_SERVER_GOOD_TIMESERV 0: NBT_SERVER_NDNC 0: NBT_SERVER_SELECT_SECRET_DOMAIN_6 1: NBT_SERVER_FULL_SECRET_DOMAIN_6 1: NBT_SERVER_ADS_WEB_SERVICE 1: NBT_SERVER_DS_8 0: NBT_SERVER_HAS_DNS_NAME 0: NBT_SERVER_IS_DEFAULT_NC 0: NBT_SERVER_FOREST_ROOT domain_uuid : d602c5bc-0513-4954-b09a-05ad2ad71b68 forest : 'ztest.ad' dns_domain : 'ztest.ad' pdc_dns_name : 'WIN-JIE7G4JU4L2.ztest.ad' domain_name : 'ZTEST' pdc_name : 'WIN-JIE7G4JU4L2' user_name : '' server_site : 'Default-First-Site-Name' client_site : 'Default-First-Site-Name' sockaddr_size : 0x00 (0) sockaddr: struct nbt_sockaddr sockaddr_family : 0x00000000 (0) pdc_ip : (null) remaining : DATA_BLOB length=0 next_closest_site : NULL nt_version : 0x00000005 (5) 1: NETLOGON_NT_VERSION_1 0: NETLOGON_NT_VERSION_5 1: NETLOGON_NT_VERSION_5EX 0: NETLOGON_NT_VERSION_5EX_WITH_IP 0: NETLOGON_NT_VERSION_WITH_CLOSEST_SITE 0: NETLOGON_NT_VERSION_AVOID_NT4EMUL 0: NETLOGON_NT_VERSION_PDC 0: NETLOGON_NT_VERSION_IP 0: NETLOGON_NT_VERSION_LOCAL 0: NETLOGON_NT_VERSION_GC lmnt_token : 0xffff (65535) lm20_token : 0xffff (65535) [2020/10/27 11:41:32.560153, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ZTEST], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:41:32.560189, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587877907 seconds ahead) [2020/10/27 11:41:32.560231, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ztest.ad], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:41:32.560265, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST.AD] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587877907 seconds ahead) [2020/10/27 11:41:32.560304, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:636(ads_connect) Successfully contacted LDAP server 10.20.90.85 [2020/10/27 11:41:32.560333, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:41:32.560358, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:213(ads_closest_dc) ads_closest_dc: NBT_SERVER_CLOSEST flag set [2020/10/27 11:41:32.560398, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:691(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: fname = /var/lock/samba/smb_krb5/krb5.conf.ZTEST, realm = ztest.ad, domain = ZTEST [2020/10/27 11:41:32.560426, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:41:32.560449, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:41:32.560467, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename Default-First-Site-Name) [2020/10/27 11:41:32.560489, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:41:32.560549, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:41:32.560573, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:32.560638, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 03 E8 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 ........ ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:41:34.325315, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:41:34.325414, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:41:34.325441, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:34.325553, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] E7 45 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 .E...... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:41:34.329143, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] E7 45 85 80 00 01 00 02 00 00 00 02 09 5F 6B 65 .E...... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 00 .....!.. ...X. .. [0060] 00 64 00 58 0F 77 69 6E 2D 6A 69 65 37 67 34 6A .d.X.win -jie7g4j [0070] 75 34 6C 32 05 7A 74 65 73 74 02 61 64 00 C0 0C u4l2.zte st.ad... [0080] 00 21 00 01 00 00 02 58 00 20 00 00 00 64 00 58 .!.....X . ...d.X [0090] 0F 77 69 6E 2D 65 6A 37 6D 76 31 73 66 63 35 6E .win-ej7 mv1sfc5n [00A0] 05 7A 74 65 73 74 02 61 64 00 C0 64 00 01 00 01 .ztest.a d..d.... [00B0] 00 00 0E 10 00 04 0A 14 5A 55 C0 90 00 01 00 01 ........ ZU...... [00C0] 00 00 0E 10 00 04 0A 14 58 33 ........ X3 [2020/10/27 11:41:34.329455, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/2/0/0 recs [2020/10/27 11:41:34.329524, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:34.329551, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 2 addresses: 10.20.90.85:88 10.20.88.51:88 [2020/10/27 11:41:34.329578, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:41:34.329619, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:34.329648, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:41:34.329668, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:34.329688, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:41:34.329705, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.90.85:88 10.20.88.51:88 [2020/10/27 11:41:34.329726, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:452(get_kdc_ip_string) got 2 addresses from site Default-First-Site-Name search [2020/10/27 11:41:34.329754, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:41:34.329789, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:41:34.329810, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename (null)) [2020/10/27 11:41:34.329835, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:41:34.329903, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:41:34.329937, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:34.329996, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 2D B2 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 -....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:41:35.331213, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:41:35.331308, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:41:35.331335, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:35.331446, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 77 BB 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 w....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:41:35.332583, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 77 BB 85 80 00 01 00 02 00 00 00 02 09 5F 6B 65 w....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 !.....!. ....X. . [0040] 00 00 64 00 58 0F 77 69 6E 2D 6A 69 65 37 67 34 ..d.X.wi n-jie7g4 [0050] 6A 75 34 6C 32 05 7A 74 65 73 74 02 61 64 00 C0 ju4l2.zt est.ad.. [0060] 0C 00 21 00 01 00 00 02 58 00 20 00 00 00 64 00 ..!..... X. ...d. [0070] 58 0F 77 69 6E 2D 65 6A 37 6D 76 31 73 66 63 35 X.win-ej 7mv1sfc5 [0080] 6E 05 7A 74 65 73 74 02 61 64 00 C0 45 00 01 00 n.ztest. ad..E... [0090] 01 00 00 0E 10 00 04 0A 14 5A 55 C0 71 00 01 00 ........ .ZU.q... [00A0] 01 00 00 0E 10 00 04 0A 14 58 33 ........ .X3 [2020/10/27 11:41:35.332868, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/2/0/0 recs [2020/10/27 11:41:35.332942, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:35.332969, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 2 addresses: 10.20.90.85:88 10.20.88.51:88 [2020/10/27 11:41:35.332995, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:41:35.333037, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:35.333067, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:41:35.333145, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:35.333196, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:41:35.333242, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.90.85:88 10.20.88.51:88 [2020/10/27 11:41:35.333265, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:458(get_kdc_ip_string) got 2 addresses from site-less search [2020/10/27 11:41:35.333284, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:490(get_kdc_ip_string) get_kdc_ip_string: 1 additional KDCs to test [2020/10/27 11:41:39.197772, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:550(get_kdc_ip_string) get_kdc_ip_string: Returning kdc = 10.20.90.85 [2020/10/27 11:41:39.197967, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:822(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: wrote file /var/lock/samba/smb_krb5/krb5.conf.ZTEST with realm ZTEST.AD KDC list = kdc = 10.20.90.85 [2020/10/27 11:41:39.198014, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery_dc.c:152(ads_dc_name) ads_dc_name: using server='WIN-JIE7G4JU4L2.ZTEST.AD' IP=10.20.90.85 [2020/10/27 11:41:39.198063, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ztest.ad': "Default-First-Site-Name" [2020/10/27 11:41:39.198085, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3322(get_sorted_dc_list) get_sorted_dc_list: attempting lookup for name ztest.ad (sitename Default-First-Site-Name) [2020/10/27 11:41:39.198169, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:41:39.198198, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:41:39.198218, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#1c (sitename Default-First-Site-Name) [2020/10/27 11:41:39.198246, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:166(namecache_fetch) name ztest.ad#1C found. [2020/10/27 11:41:39.198279, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:39.198300, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:41:39.198324, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:39.198350, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:41:39.198370, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:39.198389, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:41:39.198407, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.90.85:389 10.20.88.51:389 [2020/10/27 11:41:39.198433, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ZTEST server 10.20.90.85 [2020/10/27 11:41:39.198457, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ZTEST server 10.20.88.51 [2020/10/27 11:41:39.198498, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3322(get_sorted_dc_list) get_sorted_dc_list: attempting lookup for name ztest.ad (sitename NULL) [2020/10/27 11:41:39.198523, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:41:39.198544, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:41:39.198561, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#1c (sitename (null)) [2020/10/27 11:41:39.198584, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:166(namecache_fetch) name ztest.ad#1C found. [2020/10/27 11:41:39.198609, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:39.198627, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:41:39.198648, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:39.198671, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:41:39.198690, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:39.198709, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:41:39.198726, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.90.85:389 10.20.88.51:389 [2020/10/27 11:41:39.198750, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ZTEST server 10.20.90.85 [2020/10/27 11:41:39.198772, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ZTEST server 10.20.88.51 [2020/10/27 11:41:39.198849, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/lib/util_sock.c:515(open_socket_out_send) Connecting to 10.20.90.85 at port 445 [2020/10/27 11:41:39.199969, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:255(ads_try_connect) ads_try_connect: sending CLDAP request to 10.20.90.85 (realm: ztest.ad) [2020/10/27 11:41:39.201633, 1, pid=23765, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:433(ndr_print_debug) &response->data.nt5_ex: struct NETLOGON_SAM_LOGON_RESPONSE_EX command : LOGON_SAM_LOGON_RESPONSE_EX (23) sbz : 0x0000 (0) server_type : 0x0000f1fc (61948) 0: NBT_SERVER_PDC 1: NBT_SERVER_GC 1: NBT_SERVER_LDAP 1: NBT_SERVER_DS 1: NBT_SERVER_KDC 1: NBT_SERVER_TIMESERV 1: NBT_SERVER_CLOSEST 1: NBT_SERVER_WRITABLE 0: NBT_SERVER_GOOD_TIMESERV 0: NBT_SERVER_NDNC 0: NBT_SERVER_SELECT_SECRET_DOMAIN_6 1: NBT_SERVER_FULL_SECRET_DOMAIN_6 1: NBT_SERVER_ADS_WEB_SERVICE 1: NBT_SERVER_DS_8 0: NBT_SERVER_HAS_DNS_NAME 0: NBT_SERVER_IS_DEFAULT_NC 0: NBT_SERVER_FOREST_ROOT domain_uuid : d602c5bc-0513-4954-b09a-05ad2ad71b68 forest : 'ztest.ad' dns_domain : 'ztest.ad' pdc_dns_name : 'WIN-JIE7G4JU4L2.ztest.ad' domain_name : 'ZTEST' pdc_name : 'WIN-JIE7G4JU4L2' user_name : '' server_site : 'Default-First-Site-Name' client_site : 'Default-First-Site-Name' sockaddr_size : 0x00 (0) sockaddr: struct nbt_sockaddr sockaddr_family : 0x00000000 (0) pdc_ip : (null) remaining : DATA_BLOB length=0 next_closest_site : NULL nt_version : 0x00000005 (5) 1: NETLOGON_NT_VERSION_1 0: NETLOGON_NT_VERSION_5 1: NETLOGON_NT_VERSION_5EX 0: NETLOGON_NT_VERSION_5EX_WITH_IP 0: NETLOGON_NT_VERSION_WITH_CLOSEST_SITE 0: NETLOGON_NT_VERSION_AVOID_NT4EMUL 0: NETLOGON_NT_VERSION_PDC 0: NETLOGON_NT_VERSION_IP 0: NETLOGON_NT_VERSION_LOCAL 0: NETLOGON_NT_VERSION_GC lmnt_token : 0xffff (65535) lm20_token : 0xffff (65535) [2020/10/27 11:41:39.202541, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ZTEST], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:41:39.202571, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587877900 seconds ahead) [2020/10/27 11:41:39.202616, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:71(sitename_store) sitename_store: realm = [ztest.ad], sitename = [Default-First-Site-Name], expire = [2085923199] [2020/10/27 11:41:39.202636, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[AD_SITENAME/DOMAIN/ZTEST.AD] and timeout=[Wed Dec 31 23:59:59 -2147481749 UTC] (67768034587877900 seconds ahead) [2020/10/27 11:41:39.202679, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:636(ads_connect) Successfully contacted LDAP server 10.20.90.85 [2020/10/27 11:41:39.202704, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namecache.c:79(namecache_store) namecache_store: storing 1 address for WIN-JIE7G4JU4L2.ztest.ad#20: 10.20.90.85 [2020/10/27 11:41:39.202731, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[NBT/WIN-JIE7G4JU4L2.ZTEST.AD#20] and timeout=[Tue Oct 27 11:52:39 2020 UTC] (660 seconds ahead) [2020/10/27 11:41:39.202765, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1441(dcip_check_name) dcip_check_name: flags = 0xf1fc [2020/10/27 11:41:39.202797, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/ldap.c:213(ads_closest_dc) ads_closest_dc: NBT_SERVER_CLOSEST flag set [2020/10/27 11:41:39.202820, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/sitename_cache.c:105(sitename_fetch) sitename_fetch: Returning sitename for realm 'ZTEST.AD': "Default-First-Site-Name" [2020/10/27 11:41:39.202860, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:691(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: fname = /var/lock/samba/smb_krb5/krb5.conf.ZTEST, realm = ztest.ad, domain = ZTEST [2020/10/27 11:41:39.202899, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:41:39.202923, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:41:39.202942, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename Default-First-Site-Name) [2020/10/27 11:41:39.202965, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:41:39.203028, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:41:39.203052, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:39.203165, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 96 C4 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 ........ ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:41:40.204368, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:41:40.204452, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:41:40.204480, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.Default-First-Site-Name._sites.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:40.204591, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 3E BD 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 >....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 .. [2020/10/27 11:41:40.205838, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 3E BD 85 80 00 01 00 02 00 00 00 02 09 5F 6B 65 >....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 17 44 65 66 61 rberos._ tcp.Defa [0020] 75 6C 74 2D 46 69 72 73 74 2D 53 69 74 65 2D 4E ult-Firs t-Site-N [0030] 61 6D 65 06 5F 73 69 74 65 73 02 64 63 06 5F 6D ame._sit es.dc._m [0040] 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 21 sdcs.zte st.ad..! [0050] 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 00 .....!.. ...X. .. [0060] 00 64 00 58 0F 77 69 6E 2D 65 6A 37 6D 76 31 73 .d.X.win -ej7mv1s [0070] 66 63 35 6E 05 7A 74 65 73 74 02 61 64 00 C0 0C fc5n.zte st.ad... [0080] 00 21 00 01 00 00 02 58 00 20 00 00 00 64 00 58 .!.....X . ...d.X [0090] 0F 77 69 6E 2D 6A 69 65 37 67 34 6A 75 34 6C 32 .win-jie 7g4ju4l2 [00A0] 05 7A 74 65 73 74 02 61 64 00 C0 64 00 01 00 01 .ztest.a d..d.... [00B0] 00 00 0E 10 00 04 0A 14 58 33 C0 90 00 01 00 01 ........ X3...... [00C0] 00 00 0E 10 00 04 0A 14 5A 55 ........ ZU [2020/10/27 11:41:40.206220, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/2/0/0 recs [2020/10/27 11:41:40.206292, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:40.206318, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 2 addresses: 10.20.88.51:88 10.20.90.85:88 [2020/10/27 11:41:40.206345, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:41:40.206389, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:41:40.206415, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:40.206436, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:40.206456, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:41:40.206474, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.88.51:88 10.20.90.85:88 [2020/10/27 11:41:40.206494, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:452(get_kdc_ip_string) got 2 addresses from site Default-First-Site-Name search [2020/10/27 11:41:40.206522, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:213(saf_fetch) saf_fetch: failed to find server for "ztest.ad" domain [2020/10/27 11:41:40.206546, 3, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3126(get_dc_list) get_dc_list: preferred server list: ", *" [2020/10/27 11:41:40.206563, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2606(internal_resolve_name) internal_resolve_name: looking up ztest.ad#dcdc (sitename (null)) [2020/10/27 11:41:40.206587, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2426(resolve_ads) resolve_ads: Attempting to resolve KDCs for ztest.ad using DNS [2020/10/27 11:41:40.206645, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #0 to 10.20.88.51 [2020/10/27 11:41:40.206669, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.88.51 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:40.206724, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 41 88 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 A....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:41:41.555290, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:274(dns_lookup_waited) dns_lookup_waited: waited [2020/10/27 11:41:41.555367, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns_lookup.c:137(dns_lookup_send_next) dns_lookup_send_next: Sending DNS request #1 to 10.20.90.85 [2020/10/27 11:41:41.555394, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:436(dns_cli_request_send) dns_cli_request_send: Asking 10.20.90.85 for _kerberos._tcp.dc._msdcs.ztest.ad/1/33 via UDP [2020/10/27 11:41:41.555521, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 51 95 01 00 00 01 00 00 00 00 00 00 09 5F 6B 65 Q....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 !.. [2020/10/27 11:41:41.556661, 10, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util.c:664(dump_data) [0000] 51 95 85 80 00 01 00 02 00 00 00 02 09 5F 6B 65 Q....... ....._ke [0010] 72 62 65 72 6F 73 04 5F 74 63 70 02 64 63 06 5F rberos._ tcp.dc._ [0020] 6D 73 64 63 73 05 7A 74 65 73 74 02 61 64 00 00 msdcs.zt est.ad.. [0030] 21 00 01 C0 0C 00 21 00 01 00 00 02 58 00 20 00 !.....!. ....X. . [0040] 00 00 64 00 58 0F 77 69 6E 2D 65 6A 37 6D 76 31 ..d.X.wi n-ej7mv1 [0050] 73 66 63 35 6E 05 7A 74 65 73 74 02 61 64 00 C0 sfc5n.zt est.ad.. [0060] 0C 00 21 00 01 00 00 02 58 00 20 00 00 00 64 00 ..!..... X. ...d. [0070] 58 0F 77 69 6E 2D 6A 69 65 37 67 34 6A 75 34 6C X.win-ji e7g4ju4l [0080] 32 05 7A 74 65 73 74 02 61 64 00 C0 45 00 01 00 2.ztest. ad..E... [0090] 01 00 00 0E 10 00 04 0A 14 58 33 C0 71 00 01 00 ........ .X3.q... [00A0] 01 00 00 0E 10 00 04 0A 14 5A 55 ........ .ZU [2020/10/27 11:41:41.556947, 10, pid=23765, effective(0, 0), real(0, 0)] ../../libcli/dns/dns.c:511(dns_cli_request_udp_done) dns_cli_request_udp_done: Got op=8580 1/2/0/0 recs [2020/10/27 11:41:41.557018, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:41.557045, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:2799(internal_resolve_name) internal_resolve_name: returning 2 addresses: 10.20.88.51:88 10.20.90.85:88 [2020/10/27 11:41:41.557072, 8, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3148(get_dc_list) Adding 2 DC's from auto lookup [2020/10/27 11:41:41.557159, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.88.51 [2020/10/27 11:41:41.557196, 9, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/conncache.c:151(check_negative_conn_cache) check_negative_conn_cache returning result 0 for domain ztest.ad server 10.20.90.85 [2020/10/27 11:41:41.557216, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:1148(remove_duplicate_addrs2) remove_duplicate_addrs2: looking for duplicate address/port pairs [2020/10/27 11:41:41.557237, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3272(get_dc_list) get_dc_list: returning 2 ip addresses in an ordered list [2020/10/27 11:41:41.557255, 4, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:3273(get_dc_list) get_dc_list: 10.20.88.51:88 10.20.90.85:88 [2020/10/27 11:41:41.557275, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:458(get_kdc_ip_string) got 2 addresses from site-less search [2020/10/27 11:41:41.557294, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:490(get_kdc_ip_string) get_kdc_ip_string: 1 additional KDCs to test [2020/10/27 11:41:44.558204, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:550(get_kdc_ip_string) get_kdc_ip_string: Returning kdc = 10.20.90.85 [2020/10/27 11:41:44.558352, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:822(create_local_private_krb5_conf_for_domain) create_local_private_krb5_conf_for_domain: wrote file /var/lock/samba/smb_krb5/krb5.conf.ZTEST with realm ZTEST.AD KDC list = kdc = 10.20.90.85 [2020/10/27 11:41:44.558420, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:91(saf_store) saf_store: domain = [ZTEST], server = [WIN-JIE7G4JU4L2.ztest.ad], expire = [1603799804] [2020/10/27 11:41:44.558450, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[SAF/DOMAIN/ZTEST] and timeout=[Tue Oct 27 11:56:44 2020 UTC] (900 seconds ahead) [2020/10/27 11:41:44.558510, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/namequery.c:91(saf_store) saf_store: domain = [ztest.ad], server = [WIN-JIE7G4JU4L2.ztest.ad], expire = [1603799804] [2020/10/27 11:41:44.558531, 10, pid=23765, effective(0, 0), real(0, 0), class=tdb] ../../source3/lib/gencache.c:283(gencache_set_data_blob) gencache_set_data_blob: Adding cache entry with key=[SAF/DOMAIN/ZTEST.AD] and timeout=[Tue Oct 27 11:56:44 2020 UTC] (900 seconds ahead) [2020/10/27 11:41:44.558573, 10, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1057(cm_prepare_connection) cm_prepare_connection: connecting to DC WIN-JIE7G4JU4L2.ztest.ad for domain ZTEST [2020/10/27 11:41:44.558734, 5, pid=23765, effective(0, 0), real(0, 0)] ../../lib/util/util_net.c:1055(print_socket_options) Socket options: SO_KEEPALIVE = 0 SO_REUSEADDR = 0 SO_BROADCAST = 0 TCP_NODELAY = 1 TCP_KEEPCNT = 9 TCP_KEEPIDLE = 7200 TCP_KEEPINTVL = 75 IPTOS_LOWDELAY = 0 IPTOS_THROUGHPUT = 0 SO_REUSEPORT = 0 SO_SNDBUF = 87040 SO_RCVBUF = 372480 SO_SNDLOWAT = 1 SO_RCVLOWAT = 1 SO_SNDTIMEO = 0 SO_RCVTIMEO = 0 TCP_QUICKACK = 1 TCP_DEFER_ACCEPT = 0 [2020/10/27 11:41:44.560595, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:221(samba_ldb_connect) [2020/10/27 11:41:44.560741, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: SEARCH dn: @MODULES scope: base expr: (@LIST=*) attr: @LIST control: [2020/10/27 11:41:44.560806, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_lock [2020/10/27 11:41:44.560835, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_next_request: (tdb)->search [2020/10/27 11:41:44.560859, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_callback": 0x7fdcdb11fde0 [2020/10/27 11:41:44.560881, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_timeout": 0x7fdcdb11fea0 [2020/10/27 11:41:44.560905, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Running timer event 0x7fdcdb11fde0 "ldb_kv_callback" [2020/10/27 11:41:44.560935, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_response: DONE error: 0 [2020/10/27 11:41:44.560962, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_unlock [2020/10/27 11:41:44.560984, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fea0 "ldb_kv_timeout" [2020/10/27 11:41:44.561006, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fde0 "ldb_kv_callback" [2020/10/27 11:41:44.561034, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: no modules required by the db [2020/10/27 11:41:44.561053, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: No modules specified for this database [2020/10/27 11:41:44.561127, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: REGISTER_CONTROL 1.2.840.113556.1.4.1413 control: [2020/10/27 11:41:44.561174, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_asprintf/set_errstring: unable to find module or backend to handle operation: request [2020/10/27 11:41:44.561221, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: SEARCH dn: scope: base expr: (objectClass=*) attr: rootDomainNamingContext attr: configurationNamingContext attr: schemaNamingContext attr: defaultNamingContext control: [2020/10/27 11:41:44.561271, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_lock [2020/10/27 11:41:44.561296, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_next_request: (tdb)->search [2020/10/27 11:41:44.561316, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_callback": 0x7fdcdb11fba0 [2020/10/27 11:41:44.561339, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_timeout": 0x7fdcdb11fea0 [2020/10/27 11:41:44.561362, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Running timer event 0x7fdcdb11fba0 "ldb_kv_callback" [2020/10/27 11:41:44.561386, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_asprintf/set_errstring: NULL Base DN invalid for a base search [2020/10/27 11:41:44.561421, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_response: DONE error: 34 msg: NULL Base DN invalid for a base search [2020/10/27 11:41:44.561453, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_unlock [2020/10/27 11:41:44.561476, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fea0 "ldb_kv_timeout" [2020/10/27 11:41:44.561498, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fba0 "ldb_kv_callback" [2020/10/27 11:41:44.561526, 3, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:332(ldb_wrap_connect) ldb_wrap open of secrets.ldb [2020/10/27 11:41:44.561576, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: SEARCH dn: cn=Primary Domains scope: sub expr: (&(flatname=ZTEST)(objectclass=primaryDomain)) attr: control: [2020/10/27 11:41:44.561620, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_lock [2020/10/27 11:41:44.561643, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_next_request: (tdb)->search [2020/10/27 11:41:44.561664, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_callback": 0x7fdcdb11fde0 [2020/10/27 11:41:44.561686, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Added timed event "ldb_kv_timeout": 0x7fdcdb11fea0 [2020/10/27 11:41:44.561709, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Running timer event 0x7fdcdb11fde0 "ldb_kv_callback" [2020/10/27 11:41:44.561832, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_response: DONE error: 0 [2020/10/27 11:41:44.561864, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_trace_request: (tdb)->read_unlock [2020/10/27 11:41:44.561887, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fea0 "ldb_kv_timeout" [2020/10/27 11:41:44.561909, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: Destroying timer event 0x7fdcdb11fde0 "ldb_kv_callback" [2020/10/27 11:41:44.561940, 10, pid=23765, effective(0, 0), real(0, 0), class=ldb] ../../lib/ldb-samba/ldb_wrap.c:79(ldb_wrap_debug) ldb: ldb_asprintf/set_errstring: dsdb_search at ../../source4/dsdb/common/util.c:4760 [2020/10/27 11:41:44.562004, 5, pid=23765, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd_cm.c:1156(cm_prepare_connection) connecting to WIN-JIE7G4JU4L2.ztest.ad (ZTEST, ztest.ad) with account [ZTEST\VSA-000001C7$] principal [VSA-000001C7$@ZTEST.AD] and realm [ZTEST.AD] [2020/10/27 11:41:44.562067, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/cliconnect.c:302(cli_session_creds_prepare_krb5) cli_session_creds_prepare_krb5: Doing kinit for VSA-000001C7$@ZTEST.AD to access WIN-JIE7G4JU4L2.ztest.ad [2020/10/27 11:41:44.562241, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:152(kerberos_kinit_password_ext) kerberos_kinit_password_ext: as VSA-000001C7$@ZTEST.AD using [MEMORY:cliconnect] as ccache and config [/var/lock/samba/smb_krb5/krb5.conf.ZTEST] [2020/10/27 11:41:44.710007, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libads/kerberos.c:212(kerberos_kinit_password_ext) kerberos_kinit_password_ext: VSA-000001C7$@ZTEST.AD mapped to vsa-000001c7$@ZTEST.AD [2020/10/27 11:41:44.710294, 10, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/cliconnect.c:364(cli_session_creds_prepare_krb5) cli_session_creds_prepare_krb5: Successfully authenticated as VSA-000001C7$@ZTEST.AD (vsa-000001c7$@ZTEST.AD) to access WIN-JIE7G4JU4L2.ztest.ad using Kerberos [2020/10/27 11:41:44.710602, 5, pid=23765, effective(0, 0), real(0, 0)] ../../source3/libsmb/cliconnect.c:1343(cli_session_setup_spnego_send) cli_session_setup_spnego_send: Connect to WIN-JIE7G4JU4L2.ztest.ad as vsa-000001c7$@ZTEST.AD using SPNEGO [2020/10/27 11:41:44.711051, 5, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec_start.c:739(gensec_start_mech) Starting GENSEC mechanism spnego [2020/10/27 11:41:44.711497, 5, pid=23765, effective(0, 0), real(0, 0), class=auth] ../../auth/gensec/gensec_start.c:739(gensec_start_mech) Starting GENSEC submechanism gse_krb5