Situation: I'm seeing lots (~500k per day) of log entries like: smbd[13939]: itlab-pc06 (::ffff:10.51.51.103) couldn't find service it261 In this case, the last character of the request is truncated - it should be it2610 I'm seeing the same/similar issue to http://lists.samba.org/archive/samba/2009-March/147277.html I've dismissed this over the last few weeks as a minor inconvenience, but I'm now convinced that it's affecting the performance of the Windows client machines that are connecting to it - a 30 second operation on local disk, takes upwards of 5 mins over a network connection, generating thousands of entries similar to the above. This isn't unique - over the last 16 business hours (it's in a lab in a university dept.), there have been ~900k similar entries. It's also not just for this particular share, it's on all of the "home" shares that have been accessed, and also all of the 4 "defined" shares in smb.conf. Also, it's across many different hosts, and affecting different Windows OS's. My primary testing has been using Windows7 - I have a lab of 33 machines with this OS, but I believe I've also seen this from Windows XP and Vista hosts. Shares on turing - Dell PE2950 connected to Equalogic PS6000 via iSCSI, 1TB volume formatted EXT3 for /content and seperate 1TB EXT3 volume for /students [it2610] comment = "IT2610 AV1" path = /content/it/it2610 writable = yes browseable = yes create mask = 0600 directory mask = 0700 [homes] comment = Home Directories browseable = no writable = yes create mask = 0604 directory mask = 0704 Also, it's not restricted to this particular host: Turing (RHEL5) - tried versions samba-3.0.33-3.14.el5 samba3x-3.3.5-0.40.el5 Babbage (RHEL4) exhibits the same, samba-3.0.33-0.17.el4 Babbage which has higher use (in the last 48 hours), has seen a total of 150 different host/service combinations from the logs, across different networks with different clients and different OS's. I've got output from "log level = 10" from turing, and I've got a tcpdump from the server end with the communication with one of the mac Please let me know any further debugging steps that are necessary.
/var/log/messages extract to give timeframe reference to other logs: basically, i started the dumps/logging and as soon as the problem (couldn't find service) was encountered, i stopped the logging and packet dump Oct 6 18:39:35 turing kernel: bond1.143: dev_set_promiscuity(master, 1) Oct 6 18:39:35 turing kernel: device eth6 entered promiscuous mode Oct 6 18:39:35 turing kernel: device eth7 entered promiscuous mode Oct 6 18:39:35 turing kernel: device eth8 entered promiscuous mode Oct 6 18:39:35 turing kernel: device eth9 entered promiscuous mode Oct 6 18:39:35 turing kernel: device bond1 entered promiscuous mode Oct 6 18:39:35 turing kernel: device bond1.143 entered promiscuous mode Oct 6 18:39:40 turing smbd[2183]: [2009/10/06 18:39:40, 0] smbd/service.c:make_connection(1288) Oct 6 18:39:40 turing smbd[2183]: itlab-pc11 (::ffff:10.51.51.116) couldn't find service it261 Oct 6 18:39:40 turing smbd[2183]: [2009/10/06 18:39:40, 0] smbd/service.c:make_connection(1288) Oct 6 18:39:40 turing smbd[2183]: itlab-pc11 (::ffff:10.51.51.116) couldn't find service it261 Oct 6 18:39:40 turing dhcpd: DHCPINFORM from 10.51.51.116 via bond1.143 Oct 6 18:39:40 turing dhcpd: DHCPACK to 10.51.51.116 (00:26:18:46:41:37) via bond1.143 Oct 6 18:39:42 turing smbd[2183]: [2009/10/06 18:39:42, 0] smbd/service.c:make_connection(1288) Oct 6 18:39:42 turing smbd[2183]: itlab-pc11 (::ffff:10.51.51.116) couldn't find service it261 Oct 6 18:39:42 turing smbd[2183]: [2009/10/06 18:39:42, 0] smbd/service.c:make_connection(1288) Oct 6 18:39:42 turing smbd[2183]: itlab-pc11 (::ffff:10.51.51.116) couldn't find service it261 Oct 6 18:39:42 turing kernel: bond1.143: dev_set_promiscuity(master, -1) Oct 6 18:39:42 turing kernel: device eth6 left promiscuous mode Oct 6 18:39:42 turing kernel: device eth7 left promiscuous mode Oct 6 18:39:42 turing kernel: device eth8 left promiscuous mode Oct 6 18:39:42 turing kernel: device eth9 left promiscuous mode Oct 6 18:39:42 turing kernel: device bond1 left promiscuous mode Oct 6 18:39:42 turing kernel: device bond1.143 left promiscuous mode
Created attachment 4794 [details] packet capture on server packet capture from server (10.51.51.51)
Created attachment 4795 [details] level 10 log from server level 10 log from server of a client exhibiting problem
The server.pcap you sent shows that Windows tries to connect to it261, not it2610. There is no mention of us sending a reference to it261 like a DFS referral. Lowering the severity to normal, we need more information like a much more complete sniff to prove Samba is at fault, sending a reference to it261 and not it2610. Volker
ah, the machine already had a drive z: that is mapped to \\itlabstorage.cs.missouri.edu\it2610 inside it2610 is the turnin\erw8rc\ directory structure i'll get a bigger packet trace for you.
i've placed a rather larger packet dump at http://alpha345.com/mgd7.pcap.bz2 In this, the user browsed to the share and opened a project using Adobe Premiere in \\turing{.domain}\it2610\turnin\erw8rc\erw8rc_AS
Ok, I took a look at this trace and I see the client making the truncated DFS referral requests - starting at packet #2659. Before that it's making DFS referral requests for the full name. Are you using MSDFS at all ? If not, try setting host msdfs = no and rebooting the client. There seems to be nothing we're doing that would cause the truncated names (none are ever returned to the client) so it might be a Vista or Windows 7 bug based on differences in the way we're giving error messages to dfs-aware clients. I'll look into the MS-DFS docs and see. In the meantime, give this a try. Jeremy.
no change - it's still behaving the same,
(In reply to comment #0) > Situation: > > I'm seeing lots (~500k per day) of log entries like: > smbd[13939]: itlab-pc06 (::ffff:10.51.51.103) couldn't find service it261 confirmed that this is same or similar issue to https://bugzilla.samba.org/show_bug.cgi?id=6862 based on a similar sequence of exchanges that appear in the lvl 10 log after the session is setup and the client is authenticated. the similar portion beigins where the truncated dfs/service name appears the similar sequence start here: [2009/10/06 18:39:40, 10] lib/util_sock.c:read_smb_length_return_keepalive(1187) got smb length of 142 [2009/10/06 18:39:40, 6] smbd/process.c:process_smb(1551) got message type 0x0 of len 0x8e [2009/10/06 18:39:40, 3] smbd/process.c:process_smb(1554) Transaction 146 of length 146 (0 toread) [2009/10/06 18:39:40, 5] lib/util.c:show_msg(645) [2009/10/06 18:39:40, 5] lib/util.c:show_msg(655) size=142 smb_com=0x32 smb_rcls=0 smb_reh=0 smb_err=0 smb_flg=24 smb_flg2=51207 smb_tid=2 smb_pid=2948 smb_uid=100 smb_mid=64450 smt_wct=15 smb_vwv[ 0]= 74 (0x4A) smb_vwv[ 1]= 0 (0x0) smb_vwv[ 2]= 0 (0x0) smb_vwv[ 3]= 4096 (0x1000) smb_vwv[ 4]= 0 (0x0) smb_vwv[ 5]= 0 (0x0) smb_vwv[ 6]= 0 (0x0) smb_vwv[ 7]= 0 (0x0) smb_vwv[ 8]= 0 (0x0) smb_vwv[ 9]= 74 (0x4A) smb_vwv[10]= 68 (0x44) smb_vwv[11]= 0 (0x0) smb_vwv[12]= 0 (0x0) smb_vwv[13]= 1 (0x1) smb_vwv[14]= 16 (0x10) smb_bcc=77 [2009/10/06 18:39:40, 10] lib/util.c:dump_data(2233) [000] 00 00 00 04 00 5C 00 69 00 74 00 6C 00 61 00 62 .....\.i .t.l.a.b [010] 00 73 00 74 00 6F 00 72 00 61 00 67 00 65 00 2E .s.t.o.r .a.g.e.. [020] 00 63 00 73 00 2E 00 6D 00 69 00 73 00 73 00 6F .c.s...m .i.s.s.o [030] 00 75 00 72 00 69 00 2E 00 65 00 64 00 75 00 5C .u.r.i.. .e.d.u.\ [040] 00 69 00 74 00 32 00 36 00 31 00 00 00 .i.t.2.6 .1... [2009/10/06 18:39:40, 3] smbd/process.c:switch_message(1378) switch message SMBtrans2 (pid 2183) conn 0x2ab3bb2d3080 [2009/10/06 18:39:40, 3] smbd/sec_ctx.c:set_sec_ctx(324) setting sec ctx (4666, 600) - sec_ctx_stack_ndx = 0 [2009/10/06 18:39:40, 5] auth/token_util.c:debug_nt_user_token(528) NT user token of user S-1-22-1-4666 contains 7 SIDs SID[ 0]: S-1-22-1-4666 SID[ 1]: S-1-22-2-600 SID[ 2]: S-1-1-0 SID[ 3]: S-1-5-2 SID[ 4]: S-1-5-11 SID[ 5]: S-1-22-2-3186 SID[ 6]: S-1-22-2-3187 SE_PRIV 0x0 0x0 0x0 0x0 [2009/10/06 18:39:40, 5] auth/token_util.c:debug_unix_user_token(548) UNIX token of user 4666 Primary group is 600 and contains 3 supplementary groups Group[ 0]: 600 Group[ 1]: 3186 Group[ 2]: 3187 [2009/10/06 18:39:40, 5] smbd/uid.c:change_to_user(355) change_to_user uid=(0,4666) gid=(0,600) [2009/10/06 18:39:40, 4] smbd/vfs.c:vfs_ChDir(733) vfs_ChDir to /tmp [2009/10/06 18:39:40, 10] smbd/trans2.c:call_trans2getdfsreferral(7277) call_trans2getdfsreferral [2009/10/06 18:39:40, 10] smbd/msdfs.c:parse_dfs_path(108) parse_dfs_path: temp = |itlabstorage.cs.missouri.edu\it261| after trimming \'s [2009/10/06 18:39:40, 10] smbd/msdfs.c:parse_dfs_path(133) parse_dfs_path: hostname: itlabstorage.cs.missouri.edu [2009/10/06 18:39:40, 10] smbd/msdfs.c:parse_dfs_path(175) parse_dfs_path: servicename: it261 [2009/10/06 18:39:40, 7] param/loadparm.c:lp_servicenumber(9073) lp_servicenumber: couldn't find it261 [2009/10/06 18:39:40, 7] param/loadparm.c:lp_servicenumber(9073) lp_servicenumber: couldn't find it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_alloc(133) Finding user it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(77) Trying _Get_Pwnam(), username as lowercase is it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(95) Trying _Get_Pwnam(), username as uppercase is IT261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(104) Checking combinations of 0 uppercase letters in it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(110) Get_Pwnam_internals didn't find user [it261]! [2009/10/06 18:39:40, 3] smbd/service.c:find_service(396) checking for home directory it261 gave (NULL) [2009/10/06 18:39:40, 7] param/loadparm.c:lp_servicenumber(9073) lp_servicenumber: couldn't find printers [2009/10/06 18:39:40, 3] smbd/service.c:find_service(409) checking whether it261 is a valid printer name... [2009/10/06 18:39:40, 3] smbd/service.c:find_service(419) it261 is not a valid printer name [2009/10/06 18:39:40, 3] smbd/service.c:find_service(482) find_service() failed to find service it261 [2009/10/06 18:39:40, 3] smbd/error.c:error_packet_set(61) error packet at smbd/trans2.c(7299) cmd=50 (SMBtrans2) NT_STATUS_NOT_FOUND [2009/10/06 18:39:40, 5] lib/util.c:show_msg(645) [2009/10/06 18:39:40, 5] lib/util.c:show_msg(655) size=35 smb_com=0x32 smb_rcls=37 smb_reh=2 smb_err=49152 smb_flg=136 smb_flg2=51201 smb_tid=2 smb_pid=2948 smb_uid=100 smb_mid=64450 smt_wct=0 smb_bcc=0 [2009/10/06 18:39:40, 10] lib/util_sock.c:read_smb_length_return_keepalive(1187) got smb length of 124 [2009/10/06 18:39:40, 6] smbd/process.c:process_smb(1551) got message type 0x0 of len 0x7c [2009/10/06 18:39:40, 3] smbd/process.c:process_smb(1554) Transaction 147 of length 128 (0 toread) [2009/10/06 18:39:40, 5] lib/util.c:show_msg(645) [2009/10/06 18:39:40, 5] lib/util.c:show_msg(655) size=124 smb_com=0x75 smb_rcls=0 smb_reh=0 smb_err=0 smb_flg=24 smb_flg2=51207 smb_tid=0 smb_pid=65279 smb_uid=100 smb_mid=64514 smt_wct=4 smb_vwv[ 0]= 255 (0xFF) smb_vwv[ 1]= 124 (0x7C) smb_vwv[ 2]= 8 (0x8) smb_vwv[ 3]= 1 (0x1) smb_bcc=81 [2009/10/06 18:39:40, 10] lib/util.c:dump_data(2233) [000] 00 5C 00 5C 00 49 00 54 00 4C 00 41 00 42 00 53 .\.\.I.T .L.A.B.S [010] 00 54 00 4F 00 52 00 41 00 47 00 45 00 2E 00 43 .T.O.R.A .G.E...C [020] 00 53 00 2E 00 4D 00 49 00 53 00 53 00 4F 00 55 .S...M.I .S.S.O.U [030] 00 52 00 49 00 2E 00 45 00 44 00 55 00 5C 00 49 .R.I...E .D.U.\.I [040] 00 54 00 32 00 36 00 31 00 00 00 3F 3F 3F 3F 3F .T.2.6.1 ...????? [050] 00 . [2009/10/06 18:39:40, 3] smbd/process.c:switch_message(1378) switch message SMBtconX (pid 2183) conn 0x0 [2009/10/06 18:39:40, 3] smbd/sec_ctx.c:set_sec_ctx(324) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2009/10/06 18:39:40, 5] auth/token_util.c:debug_nt_user_token(522) NT user token: (NULL) [2009/10/06 18:39:40, 5] auth/token_util.c:debug_unix_user_token(548) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2009/10/06 18:39:40, 5] smbd/uid.c:change_to_root_user(370) change_to_root_user: now uid=(0,0) gid=(0,0) [2009/10/06 18:39:40, 4] smbd/reply.c:reply_tcon_and_X(720) Client requested device type [?????] for share [IT261] [2009/10/06 18:39:40, 7] param/loadparm.c:lp_servicenumber(9073) lp_servicenumber: couldn't find it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_alloc(133) Finding user it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(77) Trying _Get_Pwnam(), username as lowercase is it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(95) Trying _Get_Pwnam(), username as uppercase is IT261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(104) Checking combinations of 0 uppercase letters in it261 [2009/10/06 18:39:40, 5] lib/username.c:Get_Pwnam_internals(110) Get_Pwnam_internals didn't find user [it261]! [2009/10/06 18:39:40, 3] smbd/service.c:find_service(396) checking for home directory it261 gave (NULL) [2009/10/06 18:39:40, 7] param/loadparm.c:lp_servicenumber(9073) lp_servicenumber: couldn't find printers [2009/10/06 18:39:40, 3] smbd/service.c:find_service(409) checking whether it261 is a valid printer name... [2009/10/06 18:39:40, 3] smbd/service.c:find_service(419)
check your clients (in particular if they are HP boxes) for CyberLink Media Libray HP TouchSmart HP MediaSmart basically all the same thing with different names.... One of these was causing the same issue for my server.
so i am having the exact same issue and it's on vista x64 and winxp 32 clients. i don't "think" its a samba issue, but at this stage there was talk about have samba work around it. in my case the client is p4.exe (perforce). i have had a support case open with them on this issue and they are scrathing their heads. but i did narrow it down (in my case), the application p4 is a commandline application and whenever run this truncated error shows up. what i found was that is mattered what the current working directory was: if the current working directory was the samba share then this issue will show up, as soon as i change the working directory to a local drive or a mapped drive the issue went away. This also seems to be affecting performance of the system, since when the errors show up it takes longer for the p4 client to finish, when the error does not show up it's finished immediatly.
*** This bug has been marked as a duplicate of bug 6862 ***