5533 – Winbind cannot connect to ADS

Bug 5533 - Winbind cannot connect to ADS

Summary: Winbind cannot connect to ADS

Status:	RESOLVED FIXED

Alias:	None

Product:	Samba 3.0
Classification:	Unclassified
Component:	winbind (show other bugs)
Version:	3.0.30
Hardware:	x64 Linux

Importance:	P3 regression
Target Milestone:	none
Assignee:	Jeremy Allison
QA Contact:	Samba QA Contact

URL:
Keywords:

Depends on:
Blocks:

Reported:	2008-06-10 05:42 UTC by Hans Lampl
Modified:	2009-12-11 07:58 UTC (History)
CC List:	2 users (show)

See Also:

Attachments
Patch (799 bytes, patch) 2008-06-20 14:47 UTC, Jeremy Allison	no flags	Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Hans Lampl 2008-06-10 05:42:46 UTC

I've recently tried to upgrade from 3.0.14 to 3.0.28 but got stuck with the problem that winbind is obviously unable to connect to the LDAP server (a Win2000 box in my case) in a correct manner. When winbind tries to connect to LDAP server there is always the error message: libads/cldap.c:recv_cldap_netlogon(259) Failed to parse cldap reply.

By the way, net ads usr/group etc. are working correctly.

SYSLOG (I added a dump of the socket communication part)
--------------------------------------------------------
[2008/06/09 16:24:41, 2] lib/interface.c:add_interface(81)
  added interface ip=192.168.0.4 bcast=192.168.127.255 nmask=255.255.128.0
[2008/06/09 16:24:41, 2] lib/interface.c:add_interface(81)
  added interface ip=127.0.0.1 bcast=127.255.255.255 nmask=255.0.0.0
[2008/06/09 16:24:41, 5] lib/util.c:init_names(287)
  Netbios name list:-
  my_netbios_names[0]="FS"
[2008/06/09 16:24:41, 2] lib/interface.c:add_interface(81)
  added interface ip=192.168.0.4 bcast=192.168.127.255 nmask=255.255.128.0
[2008/06/09 16:24:41, 2] lib/interface.c:add_interface(81)
  added interface ip=127.0.0.1 bcast=127.255.255.255 nmask=255.0.0.0
[2008/06/09 16:24:41, 5] lib/gencache.c:gencache_init(61)
  Opening cache file at /usr/local/samba/var/locks/gencache.tdb
[2008/06/09 16:24:41, 5] libsmb/namecache.c:namecache_enable(58)
  namecache_enable: enabling netbios namecache, timeout 660 seconds
[2008/06/09 16:24:41, 10] nsswitch/idmap_cache.c:idmap_cache_init(60)
  Opening cache file at /usr/local/samba/var/locks/idmap_cache.tdb
[2008/06/09 16:24:41, 8] lib/util.c:fcntl_lock(1992)
  fcntl_lock fd=8 op=6 offset=0 count=1 type=1
[2008/06/09 16:24:41, 8] lib/util.c:fcntl_lock(2011)
  fcntl_lock: Lock call successful
[2008/06/09 16:24:41, 4] lib/time.c:TimeInit(1258)
  TimeInit: Serverzone is -7200
[2008/06/09 16:24:41, 2] lib/tallocmsg.c:register_msg_pool_usage(105)
  Registered MSG_REQ_POOL_USAGE
[2008/06/09 16:24:41, 2] lib/dmallocmsg.c:register_dmalloc_msgs(75)
  Registered MSG_REQ_DMALLOC_MARK and LOG_CHANGED
[2008/06/09 16:24:41, 0] nsswitch/winbindd_cache.c:initialize_winbindd_cache(2229)
  initialize_winbindd_cache: clearing cache and re-creating with version number 1
[2008/06/09 16:24:41, 2] nsswitch/winbindd_util.c:add_trusted_domain(171)
  Added domain MUC.DYNAWARE.DE DEV.MUC.DW S-1-5-21-2077719998-1016078350-314601362
[2008/06/09 16:24:41, 10] nsswitch/winbindd_cm.c:set_domain_online_request(417)
  set_domain_online_request: called for domain MUC.DYNAWARE.DE
[2008/06/09 16:24:41, 10] nsswitch/winbindd_cm.c:set_domain_online_request(437)
  set_domain_online_request: domain MUC.DYNAWARE.DE was globally offline.
[2008/06/09 16:24:41, 10] lib/events.c:event_add_timed(129)
  Added timed event "check_domain_online_handler": 555555a5a530
[2008/06/09 16:24:41, 2] nsswitch/winbindd_util.c:add_trusted_domain(171)
  Added domain FS  S-1-5-21-3431906350-358984747-3253572111
[2008/06/09 16:24:41, 2] nsswitch/winbindd_util.c:add_trusted_domain(171)
  Added domain BUILTIN  S-1-5-32
[2008/06/09 16:24:41, 10] nsswitch/winbindd_util.c:open_winbindd_socket(921)
  open_winbindd_socket: opened socket fd 12
[2008/06/09 16:24:41, 10] nsswitch/winbindd_util.c:open_winbindd_priv_socket(933)
  open_winbindd_priv_socket: opened socket fd 13
[2008/06/09 16:24:41, 10] lib/events.c:get_timed_events_timeout(295)
  timed_events_timeout: 4/998650
[2008/06/09 16:24:41, 10] lib/events.c:event_add_timed(129)
  Added timed event "async_request_timeout": 555555a013d0
[2008/06/09 16:24:41, 10] lib/events.c:get_timed_events_timeout(295)
  timed_events_timeout: 4/998556
[2008/06/09 16:24:45, 10] lib/events.c:timed_event_destructor(66)
  Destroying timed event 555555a013d0 "async_request_timeout"
[2008/06/09 16:24:45, 10] nsswitch/winbindd_cache.c:cache_retrieve_response(2307)
  Retrieving response for pid 16421
[2008/06/09 16:24:45, 5] nsswitch/winbindd_util.c:init_child_recv(419)
  Received child initialization response for domain MUC.DYNAWARE.DE
[2008/06/09 16:24:45, 8] nsswitch/winbindd_cm.c:connection_ok(1498)
  connection_ok: Connection to  for domain MUC.DYNAWARE.DE has NULL cli!
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/MUC.DYNAWARE.DE couldn't be found
[2008/06/09 16:24:45, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "MUC.DYNAWARE.DE" domain
[2008/06/09 16:24:45, 10] nsswitch/winbindd_cm.c:cm_open_connection(1368)
  cm_open_connection: dcname is '' for domain MUC.DYNAWARE.DE
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/DEV.MUC.DW, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:45, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for DEV.MUC.DW: "xxxxxxxx"
[2008/06/09 16:24:45, 4] libsmb/namequery_dc.c:ads_dc_name(73)
  ads_dc_name: domain=MUC.DYNAWARE.DE
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/DEV.MUC.DW, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:45, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for DEV.MUC.DW: "xxxxxxxx"
[2008/06/09 16:24:45, 6] libads/ldap.c:ads_find_dc(294)
  ads_find_dc: looking for realm 'DEV.MUC.DW'
[2008/06/09 16:24:45, 8] libsmb/namequery.c:get_sorted_dc_list(1626)
  get_sorted_dc_list: attempting lookup for name DEV.MUC.DW (sitename xxxxxxxx) using [ads]
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/DEV.MUC.DW couldn't be found
[2008/06/09 16:24:45, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "DEV.MUC.DW" domain
[2008/06/09 16:24:45, 3] libsmb/namequery.c:get_dc_list(1489)
  get_dc_list: preferred server list: ", dc1.muc.dynaware.de"
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/MUC.DYNAWARE.DE, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:45, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for MUC.DYNAWARE.DE: "xxxxxxxx"
[2008/06/09 16:24:45, 10] libsmb/namequery.c:internal_resolve_name(1166)
  internal_resolve_name: looking up dc1.muc.dynaware.de#20 (sitename xxxxxxxx)
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = NBT/DC1.MUC.DYNAWARE.DE#20, value = 192.168.16.1:0, timeout = Mon Jun  9 16:35:19 2008
[2008/06/09 16:24:45, 5] libsmb/namecache.c:namecache_fetch(214)
  name dc1.muc.dynaware.de#20 found.
[2008/06/09 16:24:45, 10] libsmb/namequery.c:remove_duplicate_addrs2(435)
  remove_duplicate_addrs2: looking for duplicate address/port pairs
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1599)
  get_dc_list: returning 1 ip addresses in an ordered list
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1600)
  get_dc_list: 192.168.16.1:389 
[2008/06/09 16:24:45, 5] libads/ldap.c:ads_try_connect(180)
  ads_try_connect: sending CLDAP request to 192.168.16.1 (realm: DEV.MUC.DW)

---------------------------
Write length=90
[2008/06/09 16:24:45, 1] lib/util.c:dump_data(2264)
  [000] 30 58 02 01 04 63 53 04  00 0A 01 00 0A 01 00 02  0X...cS. ........
  [010] 01 00 02 01 00 01 01 00  A0 34 A3 17 04 09 44 6E  ........ .4....Dn
  [020] 73 44 6F 6D 61 69 6E 04  0A 44 45 56 2E 4D 55 43  sDomain. .DEV.MUC
  [030] 2E 44 57 A3 0A 04 04 48  6F 73 74 04 02 46 53 A3  .DW....H ost..FS.
  [040] 0D 04 05 4E 74 56 65 72  04 04 06 00 00 00 30 0A  ...NtVer ......0.
  [050] 04 08 4E 65 74 4C 6F 67  6F 6E                    ..NetLog on

---------------------------

---------------------------
Read length=8192
[2008/06/09 16:24:45, 1] lib/util.c:dump_data(2264)
  [000] 30 84 00 00 00 10 02 01  04 65 84 00 00 00 07 0A  0....... .e......
  [010] 01 00 04 00 04 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  [020] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  ... zeros ...	  
  [810] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  [820] 00 00 00 00 00 00 00 00  61 50 00 00 00 00 00 00  ........ aP......
  [830] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  ... zeros ...	
  [1FF0] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........

---------------------------
[2008/06/09 16:24:45, 1] libads/cldap.c:recv_cldap_netlogon(259)
  Failed to parse cldap reply
[2008/06/09 16:24:45, 3] libads/ldap.c:ads_try_connect(189)
  ads_try_connect: CLDAP request 192.168.16.1 failed.
[2008/06/09 16:24:45, 10] libsmb/conncache.c:add_failed_connection_entry(140)
  add_failed_connection_entry: added domain DEV.MUC.DW (192.168.16.1) to failed conn cache
[2008/06/09 16:24:45, 1] libads/ldap.c:ads_find_dc(355)
  ads_find_dc: failed to find a valid DC on our site (xxxxxxxx), trying to find another DC
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_del(173)
  Deleting cache entry (key = NBT/DEV.MUC.DW#1C)
[2008/06/09 16:24:45, 6] libads/ldap.c:ads_find_dc(294)
  ads_find_dc: looking for realm 'DEV.MUC.DW'
[2008/06/09 16:24:45, 8] libsmb/namequery.c:get_sorted_dc_list(1626)
  get_sorted_dc_list: attempting lookup for name DEV.MUC.DW (sitename NULL) using [ads]
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/DEV.MUC.DW couldn't be found
[2008/06/09 16:24:45, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "DEV.MUC.DW" domain
[2008/06/09 16:24:45, 3] libsmb/namequery.c:get_dc_list(1489)
  get_dc_list: preferred server list: ", dc1.muc.dynaware.de"
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/MUC.DYNAWARE.DE, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:45, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for MUC.DYNAWARE.DE: "xxxxxxxx"
[2008/06/09 16:24:45, 10] libsmb/namequery.c:internal_resolve_name(1166)
  internal_resolve_name: looking up dc1.muc.dynaware.de#20 (sitename xxxxxxxx)
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = NBT/DC1.MUC.DYNAWARE.DE#20, value = 192.168.16.1:0, timeout = Mon Jun  9 16:35:19 2008
[2008/06/09 16:24:45, 5] libsmb/namecache.c:namecache_fetch(214)
  name dc1.muc.dynaware.de#20 found.
[2008/06/09 16:24:45, 10] libsmb/conncache.c:check_negative_conn_cache_timeout(86)
  check_negative_conn_cache: returning negative entry for DEV.MUC.DW, 192.168.16.1
[2008/06/09 16:24:45, 5] libsmb/namequery.c:get_dc_list(1577)
  get_dc_list: negative entry dc1.muc.dynaware.de removed from DC list
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1599)
  get_dc_list: returning 0 ip addresses in an ordered list
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1600)
  get_dc_list: 
[2008/06/09 16:24:45, 6] libads/ldap.c:ads_find_dc(294)
  ads_find_dc: looking for domain 'DEV.MUC.DW'
[2008/06/09 16:24:45, 8] libsmb/namequery.c:get_sorted_dc_list(1626)
  get_sorted_dc_list: attempting lookup for name DEV.MUC.DW (sitename NULL) using [wins host bcast]
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/DEV.MUC.DW couldn't be found
[2008/06/09 16:24:45, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "DEV.MUC.DW" domain
[2008/06/09 16:24:45, 3] libsmb/namequery.c:get_dc_list(1489)
  get_dc_list: preferred server list: ", dc1.muc.dynaware.de"
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/MUC.DYNAWARE.DE, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:45, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for MUC.DYNAWARE.DE: "xxxxxxxx"
[2008/06/09 16:24:45, 10] libsmb/namequery.c:internal_resolve_name(1166)
  internal_resolve_name: looking up dc1.muc.dynaware.de#20 (sitename xxxxxxxx)
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = NBT/DC1.MUC.DYNAWARE.DE#20, value = 192.168.16.1:0, timeout = Mon Jun  9 16:35:19 2008
[2008/06/09 16:24:45, 5] libsmb/namecache.c:namecache_fetch(214)
  name dc1.muc.dynaware.de#20 found.
[2008/06/09 16:24:45, 10] libsmb/conncache.c:check_negative_conn_cache_timeout(86)
  check_negative_conn_cache: returning negative entry for DEV.MUC.DW, 192.168.16.1
[2008/06/09 16:24:45, 5] libsmb/namequery.c:get_dc_list(1577)
  get_dc_list: negative entry dc1.muc.dynaware.de removed from DC list
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1599)
  get_dc_list: returning 0 ip addresses in an unordered list
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1600)
  get_dc_list: 
[2008/06/09 16:24:45, 8] libsmb/namequery.c:get_sorted_dc_list(1626)
  get_sorted_dc_list: attempting lookup for name MUC.DYNAWARE.DE (sitename NULL) using [wins host bcast]
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/MUC.DYNAWARE.DE couldn't be found
[2008/06/09 16:24:45, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "MUC.DYNAWARE.DE" domain
[2008/06/09 16:24:45, 3] libsmb/namequery.c:get_dc_list(1489)
  get_dc_list: preferred server list: ", dc1.muc.dynaware.de"
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/MUC.DYNAWARE.DE, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:45, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for MUC.DYNAWARE.DE: "xxxxxxxx"
[2008/06/09 16:24:45, 10] libsmb/namequery.c:internal_resolve_name(1166)
  internal_resolve_name: looking up dc1.muc.dynaware.de#20 (sitename xxxxxxxx)
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = NBT/DC1.MUC.DYNAWARE.DE#20, value = 192.168.16.1:0, timeout = Mon Jun  9 16:35:19 2008
[2008/06/09 16:24:45, 5] libsmb/namecache.c:namecache_fetch(214)
  name dc1.muc.dynaware.de#20 found.
[2008/06/09 16:24:45, 10] libsmb/namequery.c:remove_duplicate_addrs2(435)
  remove_duplicate_addrs2: looking for duplicate address/port pairs
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1599)
  get_dc_list: returning 1 ip addresses in an ordered list
[2008/06/09 16:24:45, 4] libsmb/namequery.c:get_dc_list(1600)
  get_dc_list: 192.168.16.1:389 
[2008/06/09 16:24:45, 10] libsmb/namequery.c:name_status_find(303)
  name_status_find: looking up MUC.DYNAWARE.DE#1c at 192.168.16.1
[2008/06/09 16:24:45, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = NBT/MUC.DYNAWARE.DE#1C.20.192.168.16.1 couldn't be found
[2008/06/09 16:24:45, 5] libsmb/namecache.c:namecache_status_fetch(346)
  namecache_status_fetch: no entry for NBT/MUC.DYNAWARE.DE#1C.20.192.168.16.1 found.
[2008/06/09 16:24:45, 10] lib/util_sock.c:open_socket_in(831)
  bind succeeded on port 0
[2008/06/09 16:24:45, 5] libsmb/nmblib.c:send_udp(779)
  Sending a packet of len 50 to (192.168.16.1) on port 137
[2008/06/09 16:24:47, 5] libsmb/nmblib.c:send_udp(779)
  Sending a packet of len 50 to (192.168.16.1) on port 137
[2008/06/09 16:24:49, 10] libsmb/namequery.c:name_status_find(342)
  name_status_find: name not found
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/DEV.MUC.DW, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:49, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for DEV.MUC.DW: "xxxxxxxx"
[2008/06/09 16:24:49, 8] libsmb/namequery.c:get_sorted_dc_list(1626)
  get_sorted_dc_list: attempting lookup for name DEV.MUC.DW (sitename xxxxxxxx) using [ads]
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/DEV.MUC.DW couldn't be found
[2008/06/09 16:24:49, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "DEV.MUC.DW" domain
[2008/06/09 16:24:49, 3] libsmb/namequery.c:get_dc_list(1489)
  get_dc_list: preferred server list: ", dc1.muc.dynaware.de"
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/MUC.DYNAWARE.DE, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:49, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for MUC.DYNAWARE.DE: "xxxxxxxx"
[2008/06/09 16:24:49, 10] libsmb/namequery.c:internal_resolve_name(1166)
  internal_resolve_name: looking up dc1.muc.dynaware.de#20 (sitename xxxxxxxx)
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = NBT/DC1.MUC.DYNAWARE.DE#20, value = 192.168.16.1:0, timeout = Mon Jun  9 16:35:19 2008
[2008/06/09 16:24:49, 5] libsmb/namecache.c:namecache_fetch(214)
  name dc1.muc.dynaware.de#20 found.
[2008/06/09 16:24:49, 10] libsmb/conncache.c:check_negative_conn_cache_timeout(86)
  check_negative_conn_cache: returning negative entry for DEV.MUC.DW, 192.168.16.1
[2008/06/09 16:24:49, 5] libsmb/namequery.c:get_dc_list(1577)
  get_dc_list: negative entry dc1.muc.dynaware.de removed from DC list
[2008/06/09 16:24:49, 4] libsmb/namequery.c:get_dc_list(1599)
  get_dc_list: returning 0 ip addresses in an ordered list
[2008/06/09 16:24:49, 4] libsmb/namequery.c:get_dc_list(1600)
  get_dc_list: 
[2008/06/09 16:24:49, 8] libsmb/namequery.c:get_sorted_dc_list(1626)
  get_sorted_dc_list: attempting lookup for name DEV.MUC.DW (sitename NULL) using [ads]
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/DEV.MUC.DW couldn't be found
[2008/06/09 16:24:49, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "DEV.MUC.DW" domain
[2008/06/09 16:24:49, 3] libsmb/namequery.c:get_dc_list(1489)
  get_dc_list: preferred server list: ", dc1.muc.dynaware.de"
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/MUC.DYNAWARE.DE, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:49, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for MUC.DYNAWARE.DE: "xxxxxxxx"
[2008/06/09 16:24:49, 10] libsmb/namequery.c:internal_resolve_name(1166)
  internal_resolve_name: looking up dc1.muc.dynaware.de#20 (sitename xxxxxxxx)
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = NBT/DC1.MUC.DYNAWARE.DE#20, value = 192.168.16.1:0, timeout = Mon Jun  9 16:35:19 2008
[2008/06/09 16:24:49, 5] libsmb/namecache.c:namecache_fetch(214)
  name dc1.muc.dynaware.de#20 found.
[2008/06/09 16:24:49, 10] libsmb/conncache.c:check_negative_conn_cache_timeout(86)
  check_negative_conn_cache: returning negative entry for DEV.MUC.DW, 192.168.16.1
[2008/06/09 16:24:49, 5] libsmb/namequery.c:get_dc_list(1577)
  get_dc_list: negative entry dc1.muc.dynaware.de removed from DC list
[2008/06/09 16:24:49, 4] libsmb/namequery.c:get_dc_list(1599)
  get_dc_list: returning 0 ip addresses in an ordered list
[2008/06/09 16:24:49, 4] libsmb/namequery.c:get_dc_list(1600)
  get_dc_list: 
[2008/06/09 16:24:49, 8] libsmb/namequery.c:get_sorted_dc_list(1626)
  get_sorted_dc_list: attempting lookup for name MUC.DYNAWARE.DE (sitename NULL) using [wins host bcast]
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(212)
  Cache entry with key = SAF/DOMAIN/MUC.DYNAWARE.DE couldn't be found
[2008/06/09 16:24:49, 5] libsmb/namequery.c:saf_fetch(133)
  saf_fetch: failed to find server for "MUC.DYNAWARE.DE" domain
[2008/06/09 16:24:49, 3] libsmb/namequery.c:get_dc_list(1489)
  get_dc_list: preferred server list: ", dc1.muc.dynaware.de"
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = AD_SITENAME/DOMAIN/MUC.DYNAWARE.DE, value = xxxxxxxx, timeout = Sun Feb  7 07:28:15 2106
[2008/06/09 16:24:49, 5] libads/dns.c:sitename_fetch(709)
  sitename_fetch: Returning sitename for MUC.DYNAWARE.DE: "xxxxxxxx"
[2008/06/09 16:24:49, 10] libsmb/namequery.c:internal_resolve_name(1166)
  internal_resolve_name: looking up dc1.muc.dynaware.de#20 (sitename xxxxxxxx)
[2008/06/09 16:24:49, 10] lib/gencache.c:gencache_get(226)
  Returning valid cache entry: key = NBT/DC1.MUC.DYNAWARE.DE#20, value = 192.168.16.1:0, timeout = Mon Jun  9 16:35:19 2008
[2008/06/09 16:24:49, 5] libsmb/namecache.c:namecache_fetch(214)
  name dc1.muc.dynaware.de#20 found.
[2008/06/09 16:24:49, 10] libsmb/namequery.c:remove_duplicate_addrs2(435)
  remove_duplicate_addrs2: looking for duplicate address/port pairs
[2008/06/09 16:24:49, 4] libsmb/namequery.c:get_dc_list(1599)
  get_dc_list: returning 1 ip addresses in an ordered list
[2008/06/09 16:24:49, 4] libsmb/namequery.c:get_dc_list(1600)
  get_dc_list: 192.168.16.1:389 
[2008/06/09 16:24:49, 5] libads/ldap.c:ads_try_connect(180)
  ads_try_connect: sending CLDAP request to 192.168.16.1 (realm: DEV.MUC.DW)

---------------------------
Write length=90
[2008/06/09 16:24:49, 1] lib/util.c:dump_data(2264)
  [000] 30 58 02 01 04 63 53 04  00 0A 01 00 0A 01 00 02  0X...cS. ........
  [010] 01 00 02 01 00 01 01 00  A0 34 A3 17 04 09 44 6E  ........ .4....Dn
  [020] 73 44 6F 6D 61 69 6E 04  0A 44 45 56 2E 4D 55 43  sDomain. .DEV.MUC
  [030] 2E 44 57 A3 0A 04 04 48  6F 73 74 04 02 46 53 A3  .DW....H ost..FS.
  [040] 0D 04 05 4E 74 56 65 72  04 04 06 00 00 00 30 0A  ...NtVer ......0.
  [050] 04 08 4E 65 74 4C 6F 67  6F 6E                    ..NetLog on

---------------------------

---------------------------
Read length=8192
[2008/06/09 16:24:49, 1] lib/util.c:dump_data(2264)
  [000] 30 84 00 00 00 10 02 01  04 65 84 00 00 00 07 0A  0....... .e......
  [010] 01 00 04 00 04 00 01 00  A0 34 A3 17 04 09 44 6E  ........ .4....Dn
  [020] 73 44 6F 6D 61 69 6E 04  0A 44 45 56 2E 4D 55 43  sDomain. .DEV.MUC
  [030] 2E 44 57 A3 0A 04 04 48  6F 73 74 04 02 46 53 A3  .DW....H ost..FS.
  [040] 0D 04 05 4E 74 56 65 72  04 04 06 00 00 00 30 0A  ...NtVer ......0.
  [050] 04 08 4E 65 74 4C 6F 67  6F 6E 00 00 00 00 00 00  ..NetLog on......
  [060] 70 00 00 00 00 00 00 00  40 00 00 00 00 00 00 00  p....... @.......
  [070] D0 0A A6 55 55 55 00 00  2F 30 39 20 31 36 3A 32  ...UUU.. /09 16:2
  [080] 34 3A 34 39 2C 20 31 5D  20 6C 69 62 2F 75 74 69  4:49, 1]  lib/uti
  [090] 6C 2E 63 3A 64 75 6D 70  5F 64 61 74 61 28 32 32  l.c:dump _data(22
  [0A0] 36 34 29 0A 00 00 00 00  31 00 00 00 00 00 00 00  64)..... 1.......
  [0B0] 40 61 A5 55 55 55 00 00  80 AB A5 55 55 55 00 00  @a.UUU.. ...UUU..
  [0C0] 2D 2D 2D 2D 2D 2D 2D 2D  2D 2D 2D 2D 0A 00 00 00  -------- ----....
  [0D0] E0 00 00 00 00 00 00 00  50 00 00 00 00 00 00 00  ........ P.......
  [0E0] A0 37 A6 55 55 55 00 00  30 34 20 30 38 20 34 45  .7.UUU.. 04 08 4E
  [0F0] 20 36 35 20 37 34 20 34  43 20 36 46 20 36 37 20   65 74 4 C 6F 67 
  [100] 20 36 46 20 36 45 20 20  20 20 20 20 20 20 20 20   6F 6E           
  [110] 20 20 20 20 20 20 20 20  20 20 2E 2E 4E 65 74 4C             ..NetL
  [120] 6F 67 20 6F 6E 0A 00 2E  C1 16 00 00 00 00 00 00  og on... ........
  [130] 30 32 A6 55 55 55 00 00  00 00 00 00 00 00 00 00  02.UUU.. ........
  [140] 00 00 00 00 00 00 00 00  A1 16 00 00 00 00 00 00  ........ ........
  [150] 0A 2D 2D 2D 2D 2D 2D 2D  2D 2D 2D 2D 2D 2D 2D 2D  .------- --------
  [160] 2D 2D 2D 2D 2D 2D 2D 2D  2D 2D 2D 2D 0A 00 00 00  -------- ----....
  [170] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  [180] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  [190] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  [1A0] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  [1B0] 00 00 00 00 00 00 00 00  31 16 00 00 00 00 00 00  ........ 1.......
  [1C0] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........
  ... zeros ...
  [1FF0] 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  ........ ........

---------------------------
[2008/06/09 16:24:49, 1] libads/cldap.c:recv_cldap_netlogon(259)
  Failed to parse cldap reply
[2008/06/09 16:24:49, 3] libads/ldap.c:ads_try_connect(189)
  ads_try_connect: CLDAP request 192.168.16.1 failed.

SMB.CONF
--------
[global]
        display charset = UTF-8
        unix charset = UTF-8
        dos charset = CP850
        unix extensions = no
        interfaces = eth0 lo
        bind interfaces only = yes
        netbios name = fs
        workgroup = DEV.MUC.DW
        server string = File Server
        security = ADS
        realm = MUC.DYNAWARE.DE
        password server = dc1.muc.dynaware.de
        encrypt passwords = yes
        log level = 10 all:10
        log file = /var/log/samba/samba.log
        max log size = 40960
        name resolve order = wins host bcast
        socket options = TCP_NODELAY SO_RCVBUF=8192 SO_SNDBUF=8192
        use sendfile = no
        large readwrite = no
        max xmit = 16644
        os level = 20
        wins support = no 
        wins server = 192.168.0.2
        dns proxy = no
        idmap uid = 10000-19999
        idmap gid = 10000-19999
        winbind separator = #
        winbind enum users = yes
        winbind enum groups = yes
        inherit acls = Yes
        hosts allow = 192.168., 127.
        map acl inherit = Yes
        store dos attributes = yes
        map archive = no
        map hidden  = no
        map system  = no
        delete readonly = yes
        mangling method = hash2
        lm announce = no
        min protocol = NT1
        deadtime = 15
        dos filetimes = yes
        dos filetime resolution = yes
        ea support = yes
[shares]
...

KRB5.CONF
---------
[libdefaults]
        default_realm = MUC.DYNAWARE.DE
        clockskew = 300

[realms]
        MUC.DYNAWARE.DE = {
                kdc = dc1.muc.dynaware.de:88
                admin_server = dc1.muc.dynaware.de:88
                default_domain = MUC.DYNAWARE.DE     
        }

[domain_realm]
        .muc.dynaware.de = MUC.DYNAWARE.DE
        muc.dynaware.de  = MUC.DYNAWARE.DE

[logging]
        default = FILE:/var/log/krb5libs.log
        kdc = FILE:/var/log/krb5kdc.log
        admin_server = FILE:/var/log/kadmind.log

I investigated that the problem appeared with V3.0.23 (V3.0.22 and before are working well) and it still exists in V3.0.30. The problem seems to be fixed in V3.2.0RC1.

Please guide me what to do.

Thanks in advance
Hans

Comment 1 Guenther Deschner 2008-06-10 06:30:47 UTC

(In reply to comment #0)

> SMB.CONF
> --------
> [global]
>         workgroup = DEV.MUC.DW
>         realm = MUC.DYNAWARE.DE

Are you sure workgroup is set correctly?

What happens (apparently) is that the CLDAP query does not return a Netlogon attribute, which could be related that the search filter DnsDomain=X uses a wrong domain name.

Inspecting the CLDAP traffic in a network trace would reveal this.

So, first of all, can you verify realm and workgroup are set correctly ?

net ads lookup -S 192.168.16.1 should show the correct values.

Comment 2 Hans Lampl 2008-06-10 07:33:25 UTC

(In reply to comment #1)
> (In reply to comment #0)
> > SMB.CONF
> > --------
> > [global]
> >         workgroup = DEV.MUC.DW
> >         realm = MUC.DYNAWARE.DE
> Are you sure workgroup is set correctly?
> What happens (apparently) is that the CLDAP query does not return a Netlogon
> attribute, which could be related that the search filter DnsDomain=X uses a
> wrong domain name.
> Inspecting the CLDAP traffic in a network trace would reveal this.
> So, first of all, can you verify realm and workgroup are set correctly ?
> net ads lookup -S 192.168.16.1 should show the correct values.

We are using DEV.MUC.DW as NT-Workgroup. Net ads lookup -S 192.168.16.1 returns the correct values, I guess.

Net ads lookup -S 192.168.16.1
------------------------------

Information for Domain Controller: 192.168.16.1

Response Type: SAMLOGON
GUID: 75ccfab6-083f-4d56-b2db-78cc0e6d105c
Flags:
        Is a PDC:                                   yes
        Is a GC of the forest:                      yes
        Is an LDAP server:                          yes
        Supports DS:                                yes
        Is running a KDC:                           yes
        Is running time services:                   yes
        Is the closest DC:                          yes
        Is writable:                                yes
        Has a hardware clock:                       no
        Is a non-domain NC serviced by LDAP server: no
Forest:                 muc.dynaware.de
Domain:                 muc.dynaware.de
Domain Controller:      dc1.muc.dynaware.de
Pre-Win2k Domain:       DEV.MUC.DW
Pre-Win2k Hostname:     DC1
Server Site Name :              xxxxxxxx
Client Site Name :              xxxxxxxx
NT Version: 5
LMNT Token: ffff
LM20 Token: ffff

Comment 3 Hans Lampl 2008-06-12 08:38:05 UTC

In the meanwhile I found out what went wrong in my case.

Let's remember the prerequisites first:
1.) I have a workgroup named DEV.MUC.DW and 
2.) a Kerberos realm named MUC.DYNAWARE.DE

When inspecting the trace we can see that there is a problem when calling the function ads_try_connect. The debug output reports that the realm is set to DEV.MUC.DW instead of to the correct value MUC.DYNAWARE.DE. That value comes from the ADS_STRUCT data structure passed as parameter by the dcip_to_name function that initializes that data structure in winbindd_cm.c.

This initialization is made as follows:
ads = ads_init(domain->alt_name, domain->name, NULL);
where domain->alt_name is holding the name of the workgroup (DEV.MUC.DW) and domain->name is holding the name of the domain or realm (MUC.DYNAWARE.DE).

Inspecting the definition of ads_init shows that the first parameter must be the realm and the second must be the workgroup.
ADS_STRUCT *ads_init(const char *realm, const char *workgroup, const char *ldap_server) [ads_struct.c]

Exchanging the parameters to
ads = ads_init(domain->name, domain->alt_name, NULL);
makes everything work correctly.

The same modification must be applied in winbindd_ads.c as well.

Could you please verify I'm right with that analysis.

Comment 4 Jeremy Allison 2008-06-20 13:57:41 UTC

The problem is you have a '.' in your workgroup name. The code that's biting you is in add_trusted_domain():

 150         /* prioritise the short name */
 151         if (strchr_m(domain_name, '.') && alternative_name && *alternative_name) {
 152                 fstrcpy(domain->name, alternative_name);
 153                 fstrcpy(domain->alt_name, domain_name);
 154         } else {
 155                 fstrcpy(domain->name, domain_name);
 156                 if (alternative_name) {
 157                         fstrcpy(domain->alt_name, alternative_name);
 158                 }
 159         }

This detects a '.' in the workgroup name and is swapping the workgroup and realm names. I think this is bogus and may need to be removed. I'll examine more closely first.

Jeremy.

Comment 5 Jeremy Allison 2008-06-20 14:47:14 UTC

Created attachment 3354 [details]
Patch

This should fix the problem.
Jeremy.

Comment 6 Hans Lampl 2008-06-20 15:43:06 UTC

Hi Jeremy,

thank you very much for the patch. I'll try it immediately and let you know if there are further problems with my environment.

Thanks a lot,
Hans

Comment 7 Hans Lampl 2008-06-27 03:33:34 UTC

Unfortunately the bug reported above seems not to be solved completely by the patch provided by Jeremy.

I ran into problems when Windows clients that are not members of the domain want to connect to a shared directory. In this case the users must authenticate themselves by providing the domain name as prefix when using a Windows client 
(in other words they must use <workgroup>\\<username> to connect). This authentication obviously fails if the workgroup name contains periods.

In order to get my system working, I've tried to fix that problem in a brute force manner by initializing the workgroup and the realm in ads_init (ads_struct.c) with the return values of lp_realm() and lp_workgroup(). That seems to work and I hope it doesn't produce any side-effects.

Could you please try to find an appropriate fix for that problem.

Thanks in advance,
Hans

Comment 8 Jeremy Allison 2008-06-27 15:07:43 UTC

Can you send me a debug level 10 of smbd of this failing please. I'd like to understand what is going wrong when these connect to smbd.
Thanks,
Jeremy.

Comment 9 Hans Lampl 2008-07-02 12:39:57 UTC

I couldn't reproduce that effect after having successfully connected to the samba server using my brute-force work-around. Maybe something was wrong in the *.tdb files what was healed when I was connecting successfully for the first time.

I'll upload a dump when I can reproduce the effect.

Thanks,
Hans

Comment 10 Karolin Seeger 2009-12-11 07:58:29 UTC

Closing out bug report.
Please reopen if it's still an issue in a current Samba version.

Thanks!