Winbind connection problem w. local samba

jjulian+samba at julianfamily.org jjulian+samba at julianfamily.org
Mon May 3 20:00:25 GMT 2004 

I'm running a small network, and using ntlm_auth with squid to filter
the kids logins both running on the same box as samba which is my PDC
(Strabo). Frequently I'm getting dialog boxes from IE asking for
authentication. I was all ready to blame MS, but this time it wasn't
them as I can duplicate the problem using wbinfo -t.
 
This problem started occurring with 3.0. I've gone through each
iteration of 3.0 with identical results. I'm currently running 3.0.3-1
(from the fedora srpm) on fedora with the 2.6.5 kernel. I've done
everything I can think of, but I'm stumped.
 
Here's some of the debug 10 logs, where I think the problem is. Here
winbindd has determined which machine is the domain server, and it
trying to open a connection to it:
 
log.winbindd:
[2004/05/03 10:28:59, 3] libsmb/cliconnect.c:cli_start_connection(1369)
  Connecting to host=STRABO
[2004/05/03 10:28:59, 3] lib/util_sock.c:open_socket_out(733)
  Connecting to 10.0.0.2 at port 445
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_KEEPALIVE = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_REUSEADDR = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_BROADCAST = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option TCP_NODELAY = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option IPTOS_LOWDELAY = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option IPTOS_THROUGHPUT = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDBUF = 16384
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVBUF = 16384
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDLOWAT = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVLOWAT = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDTIMEO = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVTIMEO = 0
[2004/05/03 10:28:59, 6] lib/util_sock.c:write_socket(430)
  write_socket(24,183)
[2004/05/03 10:28:59, 6] lib/util_sock.c:write_socket(433)
  write_socket(24,183) wrote 183
[2004/05/03 10:29:09, 10] lib/util_sock.c:read_socket_with_timeout(286)
  read_socket_with_timeout: timeout read. select timed out.
[2004/05/03 10:29:09, 10] lib/util_sock.c:receive_smb_raw(537)
  receive_smb_raw: length < 0!
[2004/05/03 10:29:09, 10] libsmb/clientgen.c:client_receive_smb(65)
  client_receive_smb failed

***
A tcpdump for port 445 (from a different occurrance, but each time it's
identical):
11:46:19.628650 strabo.julianfamily.org.33749 >
strabo.julianfamily.org.microsoft-ds: S 1135626887:1135626887(0) win
32767 <mss 16396,nop,nop,sackOK,nop,wscale 0> (DF)
11:46:19.628726 strabo.julianfamily.org.microsoft-ds >
strabo.julianfamily.org.33749: S 1127254014:1127254014(0) ack 1135626888
win 12288 <mss 16396,nop,nop,sackOK,nop,wscale 0> (DF)
11:46:19.628772 strabo.julianfamily.org.33749 >
strabo.julianfamily.org.microsoft-ds: . ack 1 win 32767 (DF)
11:46:19.642231 strabo.julianfamily.org.33749 >
strabo.julianfamily.org.microsoft-ds: P 1:184(183) ack 1 win 32767 (DF)
11:46:19.642305 strabo.julianfamily.org.microsoft-ds >
strabo.julianfamily.org.33749: . ack 184 win 12105 (DF)
11:46:29.641332 strabo.julianfamily.org.33749 >
strabo.julianfamily.org.microsoft-ds: F 184:184(0) ack 1 win 32767 (DF)

***
log.smbd:
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_KEEPALIVE = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_REUSEADDR = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_BROADCAST = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option TCP_NODELAY = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option IPTOS_LOWDELAY = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option IPTOS_THROUGHPUT = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDBUF = 16384
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVBUF = 16384
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDLOWAT = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVLOWAT = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDTIMEO = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVTIMEO = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_KEEPALIVE = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_REUSEADDR = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_BROADCAST = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option TCP_NODELAY = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option IPTOS_LOWDELAY = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option IPTOS_THROUGHPUT = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDBUF = 16384
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVBUF = 16384
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDLOWAT = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVLOWAT = 1
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_SNDTIMEO = 0
[2004/05/03 10:28:59, 5] lib/util_sock.c:print_socket_options(128)
  socket option SO_RCVTIMEO = 0
[2004/05/03 10:28:59, 5]
passdb/pdb_interface.c:make_pdb_context_list(763)
  Trying to load: ldapsam:ldap://ldap.julianfamily.org
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(93)
  Attempting to register passdb backend ldapsam
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(106)
  Successfully added passdb backend 'ldapsam'
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(93)
  Attempting to register passdb backend ldapsam_compat
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(106)
  Successfully added passdb backend 'ldapsam_compat'
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(93)
  Attempting to register passdb backend smbpasswd
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(106)
  Successfully added passdb backend 'smbpasswd'
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(93)
  Attempting to register passdb backend tdbsam
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(106)
  Successfully added passdb backend 'tdbsam'
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(93)
  Attempting to register passdb backend guest
[2004/05/03 10:28:59, 5] passdb/pdb_interface.c:smb_register_passdb(106)
  Successfully added passdb backend 'guest'
[2004/05/03 10:28:59, 5]
passdb/pdb_interface.c:make_pdb_methods_name(648)
  Attempting to find an passdb backend to match
ldapsam:ldap://ldap.julianfamily.org (ldapsam)
[2004/05/03 10:28:59, 5]
passdb/pdb_interface.c:make_pdb_methods_name(669)
  Found pdb backend ldapsam
[2004/05/03 10:28:59, 2] lib/smbldap.c:smbldap_search_domain_info(1344)
  Searching for:[(&(objectClass=sambaDomain)(sambaDomainName=JULIAN))]
[2004/05/03 10:28:59, 5] lib/smbldap.c:smbldap_search(932)
  smbldap_search: base => [dc=julianfamily,dc=org], filter =>
[(&(objectClass=sambaDomain)(sambaDomainName=JUL
IAN))], scope => [2]
[2004/05/03 10:28:59, 10] lib/smbldap.c:smbldap_open_connection(543)
  smbldap_open_connection: ldap://ldap.julianfamily.org
[2004/05/03 10:28:59, 2] lib/smbldap.c:smbldap_open_connection(639)
  smbldap_open_connection: connection opened
[2004/05/03 10:28:59, 10] lib/smbldap.c:smbldap_connect_system(771)
  ldap_connect_system: Binding to ldap server
ldap://ldap.julianfamily.org as "cn=private,dc=julianfamily,dc=org"

***
My ldap logs show:
strabo slapd[10102]: conn=5 fd=8 ACCEPT from IP=24.17.201.127:33936
(IP=0.0.0.0:389)
strabo slapd[10102]: conn=5 op=0 BIND
dn="cn=private,dc=julianfamily,dc=org" method=128
strabo slapd[10102]: conn=5 op=0 BIND
dn="cn=private,dc=julianfamily,dc=org" mech=simple ssf=0
strabo slapd[10102]: conn=5 op=0 RESULT tag=97 err=0 text=
strabo slapd[10102]: conn=5 op=1 SRCH base="dc=julianfamily,dc=org"
scope=2 filter="(&(objectClass=sambaDomain)(sambaDomainName=JULIAN))"
strabo slapd[10102]: conn=5 op=1 SRCH attr=sambaDomainName sambaNextRid
sambaNextUserRid sambaNextGroupRid sambaSID sambaAlgorithmicRidBase
objectClass
strabo slapd[10102]: conn=5 op=1 SEARCH RESULT tag=101 err=0 nentries=1
text=
strabo slapd[10102]: conn=5 fd=8 closed

***
log.10.0.0.2:
 
[2004/05/03 10:29:09, 6] param/loadparm.c:lp_file_list_changed(2665)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Mon
May  3 09:27:46 2004
 
[2004/05/03 10:29:09, 3] smbd/oplock.c:init_oplocks(1226)
  open_oplock_ipc: opening loopback UDP socket.
[2004/05/03 10:29:09, 10] lib/util_sock.c:open_socket_in(698)
  bind succeeded on port 0
[2004/05/03 10:29:09, 3]
smbd/oplock_linux.c:linux_init_kernel_oplocks(303)
  Linux kernel oplocks enabled
[2004/05/03 10:29:09, 3] smbd/oplock.c:init_oplocks(1257)
  open_oplock ipc: pid = 9032, global_oplock_port = 35586
[2004/05/03 10:29:09, 4] lib/time.c:get_serverzone(122)
  Serverzone is 25200
[2004/05/03 10:29:09, 10] lib/smbldap.c:smbldap_idle_fn(1143)
  ldap connection not idle...
[2004/05/03 10:29:09, 10]
lib/util_sock.c:read_smb_length_return_keepalive(486)
  got smb length of 179
[2004/05/03 10:29:09, 3] lib/access.c:check_access(313)
  check_access: no hostnames in host allow/deny list.
[2004/05/03 10:29:09, 2] lib/access.c:check_access(324)
  Allowed connection from  (10.0.0.2)
[2004/05/03 10:29:09, 6] smbd/process.c:process_smb(889)
  got message type 0x0 of len 0xb3
[2004/05/03 10:29:09, 3] smbd/process.c:process_smb(890)
  Transaction 0 of length 183
[2004/05/03 10:29:09, 5] lib/util.c:show_msg(456)
[2004/05/03 10:29:09, 5] lib/util.c:show_msg(466)
  size=179
  smb_com=0x72
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=8
  smb_flg2=51201
  smb_tid=0
  smb_pid=8891
  smb_uid=0
  smb_mid=1
  smt_wct=0
  smb_bcc=144
[2004/05/03 10:29:09, 10] lib/util.c:dump_data(1864)
  [000] 02 50 43 20 4E 45 54 57  4F 52 4B 20 50 52 4F 47  .PC NETW ORK
PROG
  [010] 52 41 4D 20 31 2E 30 00  02 4D 49 43 52 4F 53 4F  RAM 1.0.
.MICROSO
  [020] 46 54 20 4E 45 54 57 4F  52 4B 53 20 31 2E 30 33  FT NETWO RKS
1.03
  [030] 00 02 4D 49 43 52 4F 53  4F 46 54 20 4E 45 54 57  ..MICROS OFT
NETW
  [040] 4F 52 4B 53 20 33 2E 30  00 02 4C 41 4E 4D 41 4E  ORKS 3.0
..LANMAN
  [050] 31 2E 30 00 02 4C 4D 31  2E 32 58 30 30 32 00 02  1.0..LM1
.2X002..
  [060] 44 4F 53 20 4C 41 4E 4D  41 4E 32 2E 31 00 02 53  DOS LANM
AN2.1..S
  [070] 61 6D 62 61 00 02 4E 54  20 4C 41 4E 4D 41 4E 20  amba..NT
LANMAN
  [080] 31 2E 30 00 02 4E 54 20  4C 4D 20 30 2E 31 32 00  1.0..NT  LM
0.12.
[2004/05/03 10:29:09, 3] smbd/process.c:switch_message(685)
  switch message SMBnegprot (pid 9032)
[2004/05/03 10:29:09, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2004/05/03 10:29:09, 5] auth/auth_util.c:debug_nt_user_token(486)
  NT user token: (NULL)
[2004/05/03 10:29:09, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2004/05/03 10:29:09, 5] smbd/uid.c:change_to_root_user(282)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [PC NETWORK PROGRAM 1.0]
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [MICROSOFT NETWORKS 1.03]
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [MICROSOFT NETWORKS 3.0]
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [LANMAN1.0]
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [LM1.2X002]
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [DOS LANMAN2.1]
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(455)
  Requested protocol [Samba]
[2004/05/03 10:29:09, 10] lib/util.c:set_remote_arch(1839)
  set_remote_arch: Client arch is 'Samba'
[2004/05/03 10:29:09, 6] param/loadparm.c:lp_file_list_changed(2665)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Mon
May  3 09:27:46 2004
 
[2004/05/03 10:29:09, 6] param/loadparm.c:lp_file_list_changed(2665)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Mon
May  3 09:27:46 2004
 
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_nt1(329)
  using SPNEGO
[2004/05/03 10:29:09, 3] smbd/negprot.c:reply_negprot(532)
  Selected protocol NT LANMAN 1.0
[2004/05/03 10:29:09, 5] smbd/negprot.c:reply_negprot(538)
  negprot index=7
[2004/05/03 10:29:09, 5] lib/util.c:show_msg(456)
[2004/05/03 10:29:09, 5] lib/util.c:show_msg(466)
  size=127
  smb_com=0x72
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=136
  smb_flg2=51201
  smb_tid=0
  smb_pid=8891
  smb_uid=0
  smb_mid=1
  smt_wct=17
  smb_vwv[ 0]=    7 (0x7)
  smb_vwv[ 1]=12803 (0x3203)
  smb_vwv[ 2]=  256 (0x100)
  smb_vwv[ 3]= 1024 (0x400)
  smb_vwv[ 4]=   65 (0x41)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=  256 (0x100)
  smb_vwv[ 7]=18432 (0x4800)
  smb_vwv[ 8]=   35 (0x23)
  smb_vwv[ 9]=64768 (0xFD00)
  smb_vwv[10]=32995 (0x80E3)
  smb_vwv[11]=32896 (0x8080)
  smb_vwv[12]=18528 (0x4860)
  smb_vwv[13]=13348 (0x3424)
  smb_vwv[14]=50225 (0xC431)
  smb_vwv[15]=41985 (0xA401)
  smb_vwv[16]=14849 (0x3A01)
  smb_bcc=58
[2004/05/03 10:29:09, 10] lib/util.c:dump_data(1864)
  [000] 73 74 72 61 62 6F 00 00  00 00 00 00 00 00 00 00  strabo..
........
  [010] 60 28 06 06 2B 06 01 05  05 02 A0 1E 30 1C A0 0E  `(..+...
....0...
  [020] 30 0C 06 0A 2B 06 01 04  01 82 37 02 02 0A A3 0A  0...+...
..7.....
  [030] 30 08 A0 06 1B 04 4E 4F  4E 45                    0.....NO NE
[2004/05/03 10:29:09, 6] lib/util_sock.c:write_socket(430)
  write_socket(5,131)
[2004/05/03 10:29:09, 6] lib/util_sock.c:write_socket(433)
  write_socket(5,131) wrote 131
[2004/05/03 10:29:09, 10] lib/util_sock.c:read_socket_data(359)
  read_socket_data: recv of 4 returned 0. Error = Success
[2004/05/03 10:29:09, 10] lib/util_sock.c:receive_smb_raw(537)
  receive_smb_raw: length < 0!
[2004/05/03 10:29:09, 3] smbd/process.c:timeout_processing(1104)
  timeout_processing: End of file from client (client has disconnected).
[2004/05/03 10:29:09, 5] lib/gencache.c:gencache_shutdown(88)
  Closing cache file
[2004/05/03 10:29:09, 5] libsmb/namecache.c:namecache_shutdown(79)
  namecache_shutdown: netbios namecache closed successfully.
[2004/05/03 10:29:09, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2004/05/03 10:29:09, 5] auth/auth_util.c:debug_nt_user_token(486)
  NT user token: (NULL)
[2004/05/03 10:29:09, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2004/05/03 10:29:09, 5] smbd/uid.c:change_to_root_user(282)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2004/05/03 10:29:09, 2] smbd/server.c:exit_server(568)
  Closing connections
[2004/05/03 10:29:09, 3] smbd/connection.c:yield_connection(69)
  Yielding connection to
[2004/05/03 10:29:09, 3] smbd/connection.c:yield_connection(76)
  yield_connection: tdb_delete for name  failed with error Record does
not exist.
[2004/05/03 10:29:09, 5] smbd/oplock.c:receive_local_message(107)
  receive_local_message: doing select with timeout of 1 ms
[2004/05/03 10:29:09, 3] smbd/server.c:exit_server(611)
  Server exit (normal exit)

***
 
Then everything repeats.

More information about the samba-technical mailing list