Attachment 16312 Details for Bug 14554 – winbindd logs

winbindd logs

log.wb-ZTEST.txt (text/plain), 123.60 KB, created by Lev on 2020-10-27 12:41:47 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Lev

Created: 2020-10-27 12:41:47 UTC

Size: 123.60 KB

patch

obsolete

>[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: <NONE>
>  
>[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: <NONE>
>  
>[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: <rootDSE>
>   scope: base
>   expr: (objectClass=*)
>   attr: rootDomainNamingContext
>   attr: configurationNamingContext
>   attr: schemaNamingContext
>   attr: defaultNamingContext
>   control: <NONE>
>  
>[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: <ALL>
>   control: <NONE>
>  
>[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: <NONE>
>  
>[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: <NONE>
>  
>[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: <rootDSE>
>   scope: base
>   expr: (objectClass=*)
>   attr: rootDomainNamingContext
>   attr: configurationNamingContext
>   attr: schemaNamingContext
>   attr: defaultNamingContext
>   control: <NONE>
>  
>[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: <ALL>
>   control: <NONE>
>  
>[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

Actions: View

Attachments on bug 14554: 16312