Winbind connection problem w. local samba (solved)
jjulian+samba at julianfamily.org
jjulian+samba at julianfamily.org
Mon May 10 14:56:17 GMT 2004
Oddly, the solution to this problem was changing from
"printcap=/etc/printcap" to "printcap=cups & printing=cups",
installing the cups-devel rpm and rebuilding from the SRPM again.
I don't know how that could have caused the timeouts I was seeing
but changing from legacy printing to built-in cups printing was
the solution.
> -----Original Message-----
> From:
> samba-technical-bounces+jjulian+samba=julianfamily.org at lists.s
> amba.org
> [mailto:samba-technical-bounces+jjulian+samba=julianfamily.org
> @lists.samba.org] On Behalf Of jjulian+samba at julianfamily.org
> Sent: Monday, May 03, 2004 1:00 PM
> To: samba-technical at lists.samba.org
> Subject: Winbind connection problem w. local samba
>
>
> 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