Attachment 12326 Details for Bug 12127 – winbindd log in plain text.

winbindd log in plain text.

log.wb-TESTDOM1.txt (text/plain), 72.24 KB, created by Hemanth on 2016-08-08 21:19:28 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Hemanth

Created: 2016-08-08 21:19:28 UTC

Size: 72.24 KB

patch

obsolete

>[2016/08/07 22:49:55.982474,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 33 - private_data=(nil)
>[2016/08/07 22:49:55.982494,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 13 - private_data=(nil)
>[2016/08/07 22:49:55.982502,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1028 - private_data=(nil)
>[2016/08/07 22:49:55.982510,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1027 - private_data=(nil)
>[2016/08/07 22:49:55.982517,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1029 - private_data=(nil)
>[2016/08/07 22:49:55.982523,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1280 - private_data=(nil)
>[2016/08/07 22:49:55.982530,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1033 - private_data=(nil)
>[2016/08/07 22:49:55.982536,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1 - private_data=(nil)
>[2016/08/07 22:49:55.982543,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1036 - private_data=(nil)
>[2016/08/07 22:49:55.982549,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister)
>  Deregistering messaging pointer for type 1035 - private_data=(nil)
>[2016/08/07 22:49:55.982580,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register)
>  Registering messaging pointer for type 1028 - private_data=(nil)
>[2016/08/07 22:49:55.982589,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register)
>  Registering messaging pointer for type 1027 - private_data=(nil)
>[2016/08/07 22:49:55.982597,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register)
>  Registering messaging pointer for type 1280 - private_data=(nil)
>[2016/08/07 22:49:55.982603,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register)
>  Registering messaging pointer for type 1 - private_data=(nil)
>[2016/08/07 22:49:55.982610,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register)
>  Registering messaging pointer for type 1034 - private_data=(nil)
>[2016/08/07 22:49:55.982616,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:461(messaging_register)
>  Overriding messaging pointer for type 1034 - private_data=(nil)
>[2016/08/07 22:49:55.982628, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:566(set_domain_online_request)
>  set_domain_online_request: called for domain testdom1
>[2016/08/07 22:49:55.982655, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:601(set_domain_online_request)
>  set_domain_online_request: domain testdom1 was globally offline.
>
>[2016/08/07 22:49:55.990031, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1018(calculate_next_machine_pwd_change)
>  password last changed 2016/08/07 17:54:28
>  password valid until 2016/08/14 17:54:28
>[2016/08/07 22:49:55.990069, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1026(calculate_next_machine_pwd_change)
>  machine password still valid until: Sun, 14 Aug 2016 17:54:28 PDT
>[2016/08/07 22:49:55.990114, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:74(child_read_request)
>  Need to read 48 extra bytes
>[2016/08/07 22:49:55.990127,  4, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1406(child_handler)
>  child daemon request 59
>[2016/08/07 22:49:55.990138, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:517(child_process_request)
>  child_process_request: request fn NDRCMD
>[2016/08/07 22:49:55.990154, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual_ndr.c:315(winbindd_dual_ndrcmd)
>  winbindd_dual_ndrcmd: Running command WBINT_LOOKUPNAME (testdom1)
>[2016/08/07 22:49:55.990196,  1, pid=10391, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug)
>       wbint_LookupName: struct wbint_LookupName
>          in: struct wbint_LookupName
>              domain                   : *
>                  domain                   : 'testdom1'
>              name                     : *
>                  name                     : 'ROOT'
>              flags                    : 0x00000008 (8)
>
>[2016/08/07 22:49:55.990244,  5, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:170(get_cache)
>  get_cache: Setting ADS methods for domain testdom1
>[2016/08/07 22:49:55.990297, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:467(fetch_cache_seqnum)
>  fetch_cache_seqnum: success [testdom1][4294967295 @ 1470635395]
>[2016/08/07 22:49:55.990309,  3, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_ads.c:1488(sequence_number)
>  ads: fetch sequence_number for testdom1
>[2016/08/07 22:49:55.990317, 10, pid=10391, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_ads.c:230(ads_cached_connection)
>  ads_cached_connection
>
>[2016/08/07 22:49:55.995548,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:55.995566,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery_dc.c:77(ads_dc_name)
>  ads_dc_name: domain=testdom1
>[2016/08/07 22:49:55.995585,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:55.995593,  6, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:409(resolve_and_ping_dns)
>  resolve_and_ping_dns: (cldap) looking for realm 'testdom1.test.exp.domain.com'
>[2016/08/07 22:49:55.995600,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3346(get_sorted_dc_list)
>  get_sorted_dc_list: attempting lookup for name testdom1.test.exp.domain.com (sitename Default-First-Site-Name)
>[2016/08/07 22:49:55.995623,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:49:55.995635,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:49:55.995647, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#1c (sitename Default-First-Site-Name)
>[2016/08/07 22:49:55.995662,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name testdom1.test.exp.domain.com#1C found.
>[2016/08/07 22:49:55.995726, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:55.995742,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:49:55.995763,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:55.995772, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:49:55.995815,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:49:55.995861, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:55.995900,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:55.995916,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:55.995924, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:55.995932,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:49:55.995939,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:389 
>[2016/08/07 22:49:55.995952,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:55.995961,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:254(ads_try_connect)
>  ads_try_connect: sending CLDAP request to 10.x.y.z (realm: testdom1.test.exp.domain.com)
>[2016/08/07 22:49:56.007107,  1, pid=10391, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(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              : 0x000033fd (13309)
>                 1: 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
>                 1: 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
>                 0: NBT_SERVER_DS_8
>                 0: NBT_SERVER_HAS_DNS_NAME
>                 0: NBT_SERVER_IS_DEFAULT_NC
>                 0: NBT_SERVER_FOREST_ROOT
>          domain_uuid              : d5f2a508-0806-4f0c-abc3-b63a3ce9ca42
>          forest                   : 'testdom1.test.exp.domain.com'
>          dns_domain               : 'testdom1.test.exp.domain.com'
>          pdc_dns_name             : 'DRTNASDCPROD01.testdom1.test.exp.domain.com'
>          domain_name              : 'testdom1'
>          pdc_name                 : 'DRTNASDCPROD01'
>          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)
>
>[2016/08/07 22:49:56.007327, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:49:56.007350, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1, we already got it
>[2016/08/07 22:49:56.007372, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1.test.exp.domain.com], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:49:56.007384, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1.test.exp.domain.com, we already got it
>[2016/08/07 22:49:56.007396,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:618(ads_connect)
>  Successfully contacted LDAP server 10.x.y.z
>[2016/08/07 22:49:56.007411,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.007421, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:212(ads_closest_dc)
>  ads_closest_dc: NBT_SERVER_CLOSEST flag set
>[2016/08/07 22:49:56.007442, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:874(create_local_private_krb5_conf_for_domain)
>  create_local_private_krb5_conf_for_domain: fname = /home/samba/lock/smb_krb5/krb5.conf.testdom1, realm = testdom1.test.exp.domain.com, domain = testdom1
>[2016/08/07 22:49:56.007461,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:49:56.007473,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:49:56.007484, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#dcdc (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.007495,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2464(resolve_ads)
>  resolve_ads: Attempting to resolve KDCs for testdom1.test.exp.domain.com using DNS
>[2016/08/07 22:49:56.018351,  4, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:435(ads_dns_lookup_srv)
>  ads_dns_lookup_srv: 1 records returned in the answer section.
>[2016/08/07 22:49:56.018409, 10, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:216(ads_dns_parse_rr_srv)
>  ads_dns_parse_rr_srv: Parsed drtnasdcprod01.testdom1.test.exp.domain.com [0, 100, 88]
>[2016/08/07 22:49:56.018440, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.018459, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2823(internal_resolve_name)
>  internal_resolve_name: returning 1 addresses: 10.x.y.z:88 
>[2016/08/07 22:49:56.018481,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:49:56.018533,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.018553, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.018609,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:49:56.018685, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.018704,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.018716,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.018723, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.018730,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:49:56.018736,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:88 
>[2016/08/07 22:49:56.018744, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:706(get_kdc_ip_string)
>  got 1 addresses from site Default-First-Site-Name search
>[2016/08/07 22:49:56.018757,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:49:56.018766,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:49:56.018775, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#dcdc (sitename (null))
>[2016/08/07 22:49:56.018800,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2464(resolve_ads)
>  resolve_ads: Attempting to resolve KDCs for testdom1.test.exp.domain.com using DNS
>[2016/08/07 22:49:56.028686,  4, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:435(ads_dns_lookup_srv)
>  ads_dns_lookup_srv: 1 records returned in the answer section.
>[2016/08/07 22:49:56.028722, 10, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:216(ads_dns_parse_rr_srv)
>  ads_dns_parse_rr_srv: Parsed drtnasdcprod01.testdom1.test.exp.domain.com [0, 100, 88]
>[2016/08/07 22:49:56.028746, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.028759, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2823(internal_resolve_name)
>  internal_resolve_name: returning 1 addresses: 10.x.y.z:88 
>[2016/08/07 22:49:56.028773,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:49:56.028831,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.028851, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.028876,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:49:56.028959, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.028992,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.029023,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.029064, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.029083,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:49:56.029095,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:88 
>[2016/08/07 22:49:56.029110, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:712(get_kdc_ip_string)
>  got 1 addresses from site-less search
>[2016/08/07 22:49:56.029123, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:744(get_kdc_ip_string)
>  0 additional KDCs to test
>[2016/08/07 22:49:56.029135, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:804(get_kdc_ip_string)
>  get_kdc_ip_string: Returning 		kdc = 10.x.y.z
>  
>[2016/08/07 22:49:56.029313,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:966(create_local_private_krb5_conf_for_domain)
>  create_local_private_krb5_conf_for_domain: wrote file /home/samba/lock/smb_krb5/krb5.conf.testdom1 with realm testdom1.test.exp.domain.com KDC list = 		kdc = 10.x.y.z
>  
>[2016/08/07 22:49:56.029346,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery_dc.c:151(ads_dc_name)
>  ads_dc_name: using server='DRTNASDCPROD01.testdom1.test.exp.domain.com' IP=10.x.y.z
>[2016/08/07 22:49:56.029359,  6, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:486(ads_find_dc)
>  ads_find_dc: (ldap) looking for realm 'testdom1.test.exp.domain.com' and falling back to domain 'testdom1'
>[2016/08/07 22:49:56.029380,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.029392,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery_dc.c:77(ads_dc_name)
>  ads_dc_name: domain=testdom1
>[2016/08/07 22:49:56.029404,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.029413,  6, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:409(resolve_and_ping_dns)
>  resolve_and_ping_dns: (cldap) looking for realm 'testdom1.test.exp.domain.com'
>[2016/08/07 22:49:56.029421,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3346(get_sorted_dc_list)
>  get_sorted_dc_list: attempting lookup for name testdom1.test.exp.domain.com (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.029437,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:49:56.029448,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:49:56.029459, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#1c (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.029485,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name testdom1.test.exp.domain.com#1C found.
>[2016/08/07 22:49:56.029527, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.029539,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:49:56.029558,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.029566, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.029578,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:49:56.029611, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.029629,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.029642,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.029650, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.029658,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:49:56.029665,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:389 
>[2016/08/07 22:49:56.029677,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.029686,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:254(ads_try_connect)
>  ads_try_connect: sending CLDAP request to 10.x.y.z (realm: testdom1.test.exp.domain.com)
>[2016/08/07 22:49:56.039653,  1, pid=10391, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(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              : 0x000033fd (13309)
>                 1: 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
>                 1: 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
>                 0: NBT_SERVER_DS_8
>                 0: NBT_SERVER_HAS_DNS_NAME
>                 0: NBT_SERVER_IS_DEFAULT_NC
>                 0: NBT_SERVER_FOREST_ROOT
>          domain_uuid              : d5f2a508-0806-4f0c-abc3-b63a3ce9ca42
>          forest                   : 'testdom1.test.exp.domain.com'
>          dns_domain               : 'testdom1.test.exp.domain.com'
>          pdc_dns_name             : 'DRTNASDCPROD01.testdom1.test.exp.domain.com'
>          domain_name              : 'testdom1'
>          pdc_name                 : 'DRTNASDCPROD01'
>          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)
>[2016/08/07 22:49:56.039845, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:49:56.039869, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1, we already got it
>[2016/08/07 22:49:56.039878, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1.test.exp.domain.com], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:49:56.039889, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1.test.exp.domain.com, we already got it
>[2016/08/07 22:49:56.039899,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:618(ads_connect)
>  Successfully contacted LDAP server 10.x.y.z
>[2016/08/07 22:49:56.039912,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.039922, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:212(ads_closest_dc)
>  ads_closest_dc: NBT_SERVER_CLOSEST flag set
>[2016/08/07 22:49:56.039938, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:874(create_local_private_krb5_conf_for_domain)
>  create_local_private_krb5_conf_for_domain: fname = /home/samba/lock/smb_krb5/krb5.conf.testdom1, realm = testdom1.test.exp.domain.com, domain = testdom1
>[2016/08/07 22:49:56.039955,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:49:56.039964,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:49:56.039975, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#dcdc (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.039984,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2464(resolve_ads)
>  resolve_ads: Attempting to resolve KDCs for testdom1.test.exp.domain.com using DNS
>[2016/08/07 22:49:56.050981,  4, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:435(ads_dns_lookup_srv)
>  ads_dns_lookup_srv: 1 records returned in the answer section.
>[2016/08/07 22:49:56.051055, 10, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:216(ads_dns_parse_rr_srv)
>  ads_dns_parse_rr_srv: Parsed drtnasdcprod01.testdom1.test.exp.domain.com [0, 100, 88]
>[2016/08/07 22:49:56.051088, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.051107, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2823(internal_resolve_name)
>  internal_resolve_name: returning 1 addresses: 10.x.y.z:88 
>[2016/08/07 22:49:56.051129,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:49:56.051181,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.051202, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.051232,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:49:56.051321, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.051358,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.051370,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.051377, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.051384,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:49:56.051390,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:88 
>[2016/08/07 22:49:56.051398, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:706(get_kdc_ip_string)
>  got 1 addresses from site Default-First-Site-Name search
>[2016/08/07 22:49:56.051411,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:49:56.051420,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:49:56.051429, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#dcdc (sitename (null))
>[2016/08/07 22:49:56.051438,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2464(resolve_ads)
>  resolve_ads: Attempting to resolve KDCs for testdom1.test.exp.domain.com using DNS
>[2016/08/07 22:49:56.060962,  4, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:435(ads_dns_lookup_srv)
>  ads_dns_lookup_srv: 1 records returned in the answer section.
>[2016/08/07 22:49:56.061062, 10, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:216(ads_dns_parse_rr_srv)
>  ads_dns_parse_rr_srv: Parsed drtnasdcprod01.testdom1.test.exp.domain.com [0, 100, 88]
>[2016/08/07 22:49:56.061097, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.061117, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2823(internal_resolve_name)
>  internal_resolve_name: returning 1 addresses: 10.x.y.z:88 
>[2016/08/07 22:49:56.061138,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:49:56.061190,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:49:56.061211, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:49:56.061241,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:49:56.061308, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.061327,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.061339,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:49:56.061346, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:49:56.061353,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:49:56.061360,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:88 
>[2016/08/07 22:49:56.061367, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:712(get_kdc_ip_string)
>  got 1 addresses from site-less search
>[2016/08/07 22:49:56.061374, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:744(get_kdc_ip_string)
>  0 additional KDCs to test
>[2016/08/07 22:49:56.061380, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:804(get_kdc_ip_string)
>  get_kdc_ip_string: Returning 		kdc = 10.x.y.z
>  
>[2016/08/07 22:49:56.061460,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:966(create_local_private_krb5_conf_for_domain)
>  create_local_private_krb5_conf_for_domain: wrote file /home/samba/lock/smb_krb5/krb5.conf.testdom1 with realm testdom1.test.exp.domain.com KDC list = 		kdc = 10.x.y.z
>  
>[2016/08/07 22:49:56.061480,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery_dc.c:151(ads_dc_name)
>  ads_dc_name: using server='DRTNASDCPROD01.testdom1.test.exp.domain.com' IP=10.x.y.z
>[2016/08/07 22:49:56.061489,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:254(ads_try_connect)
>  ads_try_connect: sending CLDAP request to 10.x.y.z (realm: testdom1.test.exp.domain.com)
>[2016/08/07 22:49:56.070918,  1, pid=10391, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(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              : 0x000033fd (13309)
>                 1: 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
>                 1: 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
>                 0: NBT_SERVER_DS_8
>                 0: NBT_SERVER_HAS_DNS_NAME
>                 0: NBT_SERVER_IS_DEFAULT_NC
>                 0: NBT_SERVER_FOREST_ROOT
>          domain_uuid              : d5f2a508-0806-4f0c-abc3-b63a3ce9ca42
>          forest                   : 'testdom1.test.exp.domain.com'
>          dns_domain               : 'testdom1.test.exp.domain.com'
>          pdc_dns_name             : 'DRTNASDCPROD01.testdom1.test.exp.domain.com'
>          domain_name              : 'testdom1'
>          pdc_name                 : 'DRTNASDCPROD01'
>          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)
>
>
>[2016/08/07 22:49:56.071105, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:49:56.071128, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1, we already got it
>[2016/08/07 22:49:56.071137, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1.test.exp.domain.com], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:49:56.071148, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1.test.exp.domain.com, we already got it
>[2016/08/07 22:49:56.071160,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:618(ads_connect)
>  Successfully contacted LDAP server 10.x.y.z
>[2016/08/07 22:49:56.071169, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:73(ldap_open_with_timeout)
>  Opening connection to LDAP server '10.x.y.z:389', timeout 15 seconds
>[2016/08/07 22:49:56.071842, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:108(ldap_open_with_timeout)
>  Initialized connection for LDAP server 'ldap://10.x.y.z:389'
>[2016/08/07 22:49:56.071862,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:661(ads_connect)
>  Connected to LDAP server DRTNASDCPROD01.testdom1.test.exp.domain.com
>[2016/08/07 22:49:56.071879, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:212(ads_closest_dc)
>  ads_closest_dc: NBT_SERVER_CLOSEST flag set
>[2016/08/07 22:49:56.071893, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:88(saf_store)
>  saf_store: domain = [testdom1], server = [DRTNASDCPROD01.testdom1.test.exp.domain.com], expire = [1470636296]
>[2016/08/07 22:49:56.071906, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for SAF/DOMAIN/testdom1, we already got it
>[2016/08/07 22:49:56.071915, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:88(saf_store)
>  saf_store: domain = [testdom1.test.exp.domain.com], server = [DRTNASDCPROD01.testdom1.test.exp.domain.com], expire = [1470636296]
>[2016/08/07 22:49:56.071924, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for SAF/DOMAIN/testdom1.test.exp.domain.com, we already got it
>[2016/08/07 22:49:56.090672,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:2970(ads_current_time)
>  KDC time offset is 0 seconds
>[2016/08/07 22:49:56.100318,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:1082(ads_sasl_bind)
>  Found SASL mechanism GSS-SPNEGO
>[2016/08/07 22:49:56.110235,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.30
>[2016/08/07 22:49:56.110279,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.48018.1.2.2
>[2016/08/07 22:49:56.110287,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2
>[2016/08/07 22:49:56.110293,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2.3
>[2016/08/07 22:49:56.110299,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.10
>[2016/08/07 22:49:56.110366,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'gssapi_spnego' registered
>[2016/08/07 22:49:56.110382,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'gssapi_krb5' registered
>[2016/08/07 22:49:56.110390,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'gssapi_krb5_sasl' registered
>[2016/08/07 22:49:56.110397,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'spnego' registered
>[2016/08/07 22:49:56.110404,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'schannel' registered
>[2016/08/07 22:49:56.110411,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'naclrpc_as_system' registered
>[2016/08/07 22:49:56.110418,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'sasl-EXTERNAL' registered
>[2016/08/07 22:49:56.110427,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'ntlmssp' registered
>[2016/08/07 22:49:56.110434,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'ntlmssp_resume_ccache' registered
>[2016/08/07 22:49:56.110441,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'http_basic' registered
>[2016/08/07 22:49:56.110447,  3, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:907(gensec_register)
>  GENSEC backend 'http_ntlm' registered
>[2016/08/07 22:49:56.110840,  5, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC mechanism spnego
>[2016/08/07 22:49:56.110873,  5, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC submechanism gse_krb5
>[2016/08/07 22:49:56.110992,  3, pid=10391, effective(0, 0), real(0, 0)] ../lib/krb5_wrap/krb5_samba.c:2502(kerberos_get_principal_from_service_hostname)
>  kerberos_get_principal_from_service_hostname: cannot get realm from, desthost drtnasdcprod01.testdom1.test.exp.domain.com or default ccache. Using default smb.conf realm testdom1.test.exp.domain.com
>[2016/08/07 22:49:56.111391,  0, pid=10391, effective(0, 0), real(0, 0)] ../source3/librpc/crypto/gse.c:341(gse_get_client_auth_token)
>  gss_init_sec_context failed with [Unspecified GSS failure.  Minor code may provide more information: No credentials cache found]
>[2016/08/07 22:49:56.111550,  1, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/spnego.c:619(gensec_spnego_create_negTokenInit)
>  SPNEGO(gse_krb5) creating NEG_TOKEN_INIT failed: NT_STATUS_INTERNAL_ERROR
>[2016/08/07 22:49:56.111626, 10, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/spnego.c:672(gensec_spnego_create_negTokenInit)
>  Failed to setup SPNEGO negTokenInit request: NT_STATUS_INTERNAL_ERROR
>[2016/08/07 22:49:56.111650, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:761(ads_sasl_spnego_bind)
>  ads_sasl_spnego_gensec_bind(KRB5) failed with: An internal error occurred., calling kinit
>[2016/08/07 22:49:56.111725, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:217(kerberos_kinit_password_ext)
>  kerberos_kinit_password: as H435$@testdom1.test.exp.domain.com using [MEMORY:winbind_ccache] as ccache and config [/home/samba/lock/smb_krb5/krb5.conf.testdom1]
>[2016/08/07 22:49:56.225879,  5, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC mechanism spnego
>[2016/08/07 22:49:56.225921,  5, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC submechanism gse_krb5
>[2016/08/07 22:49:56.226012,  3, pid=10391, effective(0, 0), real(0, 0)] ../lib/krb5_wrap/krb5_samba.c:2502(kerberos_get_principal_from_service_hostname)
>  kerberos_get_principal_from_service_hostname: cannot get realm from, desthost drtnasdcprod01.testdom1.test.exp.domain.com or default ccache. Using default smb.conf realm testdom1.test.exp.domain.com
>
>
>
>[2016/08/07 22:50:11.324867,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:981(ads_do_paged_search_args)
>  ads_do_paged_search_args: ldap_search_with_timeout((objectclass=*)) -> Time limit exceeded
>[2016/08/07 22:50:11.324938,  1, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap_utils.c:91(ads_do_search_retry_internal)
>  Reducing LDAP page size from 1000 to 500 due to IO_TIMEOUT
>[2016/08/07 22:50:11.324949,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap_utils.c:100(ads_do_search_retry_internal)
>  Reopening ads connection to realm 'testdom1.test.exp.domain.com' after error Time limit exceeded
>[2016/08/07 22:50:11.325056,  6, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:486(ads_find_dc)
>  ads_find_dc: (ldap) looking for realm 'testdom1.test.exp.domain.com' and falling back to domain 'testdom1'
>[2016/08/07 22:50:11.325120,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:50:11.325136,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery_dc.c:77(ads_dc_name)
>  ads_dc_name: domain=testdom1
>[2016/08/07 22:50:11.325149,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:50:11.325156,  6, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:409(resolve_and_ping_dns)
>  resolve_and_ping_dns: (cldap) looking for realm 'testdom1.test.exp.domain.com'
>[2016/08/07 22:50:11.325163,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3346(get_sorted_dc_list)
>  get_sorted_dc_list: attempting lookup for name testdom1.test.exp.domain.com (sitename Default-First-Site-Name)
>[2016/08/07 22:50:11.325184,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:50:11.325196,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:50:11.325208, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#1c (sitename Default-First-Site-Name)
>[2016/08/07 22:50:11.325224,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name testdom1.test.exp.domain.com#1C found.
>[2016/08/07 22:50:11.325301, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.325315,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:50:11.325335,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:50:11.325343, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:50:11.325383,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:50:11.325424, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.325447,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:50:11.325459,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:50:11.325467, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.325474,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:50:11.325481,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:389 
>[2016/08/07 22:50:11.325493,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:50:11.325501,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:254(ads_try_connect)
>  ads_try_connect: sending CLDAP request to 10.x.y.z (realm: testdom1.test.exp.domain.com)
>[2016/08/07 22:50:11.333921,  1, pid=10391, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug)
>       &response->data.nt5_ex: struct NETLOGON_SAM_LOGON_RESPONSE_EX
>          command                  : LOGON_SAM_LOGON_RESPONSE_EX (23)
>--
>[2016/08/07 22:50:11.334133, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:50:11.334161, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1, we already got it
>[2016/08/07 22:50:11.334171, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1.test.exp.domain.com], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:50:11.334182, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1.test.exp.domain.com, we already got it
>[2016/08/07 22:50:11.334194,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:618(ads_connect)
>  Successfully contacted LDAP server 10.x.y.z
>[2016/08/07 22:50:11.334208,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:50:11.334220, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:212(ads_closest_dc)
>  ads_closest_dc: NBT_SERVER_CLOSEST flag set
>[2016/08/07 22:50:11.334243, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:874(create_local_private_krb5_conf_for_domain)
>  create_local_private_krb5_conf_for_domain: fname = /home/samba/lock/smb_krb5/krb5.conf.testdom1, realm = testdom1.test.exp.domain.com, domain = testdom1
>[2016/08/07 22:50:11.334262,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:50:11.334273,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:50:11.334282, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#dcdc (sitename Default-First-Site-Name)
>[2016/08/07 22:50:11.334293,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2464(resolve_ads)
>  resolve_ads: Attempting to resolve KDCs for testdom1.test.exp.domain.com using DNS
>[2016/08/07 22:50:11.342387,  4, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:435(ads_dns_lookup_srv)
>  ads_dns_lookup_srv: 1 records returned in the answer section.
>[2016/08/07 22:50:11.342417, 10, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:216(ads_dns_parse_rr_srv)
>  ads_dns_parse_rr_srv: Parsed drtnasdcprod01.testdom1.test.exp.domain.com [0, 100, 88]
>[2016/08/07 22:50:11.342432, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.342439, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2823(internal_resolve_name)
>  internal_resolve_name: returning 1 addresses: 10.x.y.z:88 
>[2016/08/07 22:50:11.342448,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:50:11.342486,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:50:11.342499, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:50:11.342512,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:50:11.342556, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.342578,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:50:11.342591,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:50:11.342598, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.342605,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:50:11.342612,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:88 
>[2016/08/07 22:50:11.342620, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:706(get_kdc_ip_string)
>  got 1 addresses from site Default-First-Site-Name search
>[2016/08/07 22:50:11.342633,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:213(saf_fetch)
>  saf_fetch: Returning "DRTNASDCPROD01.testdom1.test.exp.domain.com" for "testdom1.test.exp.domain.com" domain
>[2016/08/07 22:50:11.342643,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3151(get_dc_list)
>  get_dc_list: preferred server list: "DRTNASDCPROD01.testdom1.test.exp.domain.com, *"
>[2016/08/07 22:50:11.342652, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up testdom1.test.exp.domain.com#dcdc (sitename (null))
>[2016/08/07 22:50:11.342661,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2464(resolve_ads)
>  resolve_ads: Attempting to resolve KDCs for testdom1.test.exp.domain.com using DNS
>[2016/08/07 22:50:11.351504,  4, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:435(ads_dns_lookup_srv)
>  ads_dns_lookup_srv: 1 records returned in the answer section.
>[2016/08/07 22:50:11.351533, 10, pid=10391, effective(0, 0), real(0, 0)] ../lib/addns/dnsquery.c:216(ads_dns_parse_rr_srv)
>  ads_dns_parse_rr_srv: Parsed drtnasdcprod01.testdom1.test.exp.domain.com [0, 100, 88]
>[2016/08/07 22:50:11.351547, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.351555, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2823(internal_resolve_name)
>  internal_resolve_name: returning 1 addresses: 10.x.y.z:88 
>[2016/08/07 22:50:11.351564,  8, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3173(get_dc_list)
>  Adding 1 DC's from auto lookup
>[2016/08/07 22:50:11.351588,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:105(sitename_fetch)
>  sitename_fetch: Returning sitename for testdom1.test.exp.domain.com: "Default-First-Site-Name"
>[2016/08/07 22:50:11.351611, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:2644(internal_resolve_name)
>  internal_resolve_name: looking up DRTNASDCPROD01.testdom1.test.exp.domain.com#20 (sitename Default-First-Site-Name)
>[2016/08/07 22:50:11.351628,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namecache.c:165(namecache_fetch)
>  name DRTNASDCPROD01.testdom1.test.exp.domain.com#20 found.
>[2016/08/07 22:50:11.351673, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.351695,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:50:11.351708,  9, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/conncache.c:150(check_negative_conn_cache)
>  check_negative_conn_cache returning result 0 for domain testdom1.test.exp.domain.com server 10.x.y.z
>[2016/08/07 22:50:11.351715, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:1141(remove_duplicate_addrs2)
>  remove_duplicate_addrs2: looking for duplicate address/port pairs
>[2016/08/07 22:50:11.351723,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3296(get_dc_list)
>  get_dc_list: returning 1 ip addresses in an ordered list
>[2016/08/07 22:50:11.351729,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:3297(get_dc_list)
>  get_dc_list: 10.x.y.z:88 
>[2016/08/07 22:50:11.351737, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:712(get_kdc_ip_string)
>  got 1 addresses from site-less search
>[2016/08/07 22:50:11.351743, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:744(get_kdc_ip_string)
>  0 additional KDCs to test
>[2016/08/07 22:50:11.351750, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:804(get_kdc_ip_string)
>  get_kdc_ip_string: Returning 		kdc = 10.x.y.z
>  
>[2016/08/07 22:50:11.351898,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/kerberos.c:966(create_local_private_krb5_conf_for_domain)
>  create_local_private_krb5_conf_for_domain: wrote file /home/samba/lock/smb_krb5/krb5.conf.testdom1 with realm testdom1.test.exp.domain.com KDC list = 		kdc = 10.x.y.z
>  
>[2016/08/07 22:50:11.351934,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery_dc.c:151(ads_dc_name)
>  ads_dc_name: using server='DRTNASDCPROD01.testdom1.test.exp.domain.com' IP=10.x.y.z
>[2016/08/07 22:50:11.351944,  5, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:254(ads_try_connect)
>  ads_try_connect: sending CLDAP request to 10.x.y.z (realm: testdom1.test.exp.domain.com)
>[2016/08/07 22:50:11.359873,  1, pid=10391, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug)
>       &response->data.nt5_ex: struct NETLOGON_SAM_LOGON_RESPONSE_EX
>          command                  : LOGON_SAM_LOGON_RESPONSE_EX (23)
>--
>[2016/08/07 22:50:11.360089, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:50:11.360117, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1, we already got it
>[2016/08/07 22:50:11.360128, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sitename_cache.c:70(sitename_store)
>  sitename_store: realm = [testdom1.test.exp.domain.com], sitename = [Default-First-Site-Name], expire = [2085923199]
>[2016/08/07 22:50:11.360140, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for AD_SITENAME/DOMAIN/testdom1.test.exp.domain.com, we already got it
>[2016/08/07 22:50:11.360153,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:618(ads_connect)
>  Successfully contacted LDAP server 10.x.y.z
>[2016/08/07 22:50:11.360161, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:73(ldap_open_with_timeout)
>  Opening connection to LDAP server '10.x.y.z:389', timeout 15 seconds
>[2016/08/07 22:50:11.360196, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:108(ldap_open_with_timeout)
>  Initialized connection for LDAP server 'ldap://10.x.y.z:389'
>[2016/08/07 22:50:11.360208,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:661(ads_connect)
>  Connected to LDAP server DRTNASDCPROD01.testdom1.test.exp.domain.com
>[2016/08/07 22:50:11.360215, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:212(ads_closest_dc)
>  ads_closest_dc: NBT_SERVER_CLOSEST flag set
>[2016/08/07 22:50:11.360228, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:88(saf_store)
>  saf_store: domain = [testdom1], server = [DRTNASDCPROD01.testdom1.test.exp.domain.com], expire = [1470636311]
>[2016/08/07 22:50:11.360240, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for SAF/DOMAIN/testdom1, we already got it
>[2016/08/07 22:50:11.360249, 10, pid=10391, effective(0, 0), real(0, 0)] ../source3/libsmb/namequery.c:88(saf_store)
>  saf_store: domain = [testdom1.test.exp.domain.com], server = [DRTNASDCPROD01.testdom1.test.exp.domain.com], expire = [1470636311]
>[2016/08/07 22:50:11.360258, 10, pid=10391, effective(0, 0), real(0, 0), class=tdb] ../source3/lib/gencache.c:302(gencache_set_data_blob)
>  Did not store value for SAF/DOMAIN/testdom1.test.exp.domain.com, we already got it
>[2016/08/07 22:50:11.375089,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/ldap.c:2970(ads_current_time)
>  KDC time offset is 0 seconds
>[2016/08/07 22:50:11.382838,  4, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:1082(ads_sasl_bind)
>  Found SASL mechanism GSS-SPNEGO
>[2016/08/07 22:50:11.390103,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.30
>[2016/08/07 22:50:11.390127,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.48018.1.2.2
>[2016/08/07 22:50:11.390135,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2
>[2016/08/07 22:50:11.390142,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2.3
>[2016/08/07 22:50:11.390149,  3, pid=10391, effective(0, 0), real(0, 0)] ../source3/libads/sasl.c:732(ads_sasl_spnego_bind)
>  ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.10
>[2016/08/07 22:50:11.390342,  5, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC mechanism spnego
>[2016/08/07 22:50:11.390390,  5, pid=10391, effective(0, 0), real(0, 0)] ../auth/gensec/gensec_start.c:680(gensec_start_mech)
>  Starting GENSEC submechanism gse_krb5
>[2016/08/07 22:50:11.390503,  3, pid=10391, effective(0, 0), real(0, 0)] ../lib/krb5_wrap/krb5_samba.c:2502(kerberos_get_principal_from_service_hostname)
>  kerberos_get_principal_from_service_hostname: cannot get realm from, desthost drtnasdcprod01.testdom1.test.exp.domain.com or default ccache. Using default smb.conf realm testdom1.test.exp.domain.com
>

Actions: View

Attachments on bug 12127: 12323 | 12326 | 12327