Bug 6782 - Log entries with truncated service names
Log entries with truncated service names
Status: NEW
Product: Samba 3.3
Classification: Unclassified
Component: File services
3.3.5
x64 Linux
: P3 normal
: ---
Assigned To: Volker Lendecke
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2009-10-06 21:55 UTC by Matthew Dickinson
Modified: 2009-12-04 11:45 UTC (History)
2 users (show)

See Also:


Attachments
packet capture on server (23.24 KB, application/octet-stream)
2009-10-06 21:59 UTC, Matthew Dickinson
no flags Details
level 10 log from server (52.50 KB, application/octet-stream)
2009-10-06 22:00 UTC, Matthew Dickinson
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Matthew Dickinson 2009-10-06 21:55:00 UTC
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.
Comment 1 Matthew Dickinson 2009-10-06 21:57:52 UTC
/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
Comment 2 Matthew Dickinson 2009-10-06 21:59:12 UTC
Created attachment 4794 [details]
packet capture on server

packet capture from server (10.51.51.51)
Comment 3 Matthew Dickinson 2009-10-06 22:00:01 UTC
Created attachment 4795 [details]
level 10 log from server

level 10 log from server of a client exhibiting problem
Comment 4 Volker Lendecke 2009-10-08 01:41:47 UTC
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
Comment 5 Matthew Dickinson 2009-10-08 07:56:11 UTC
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.
Comment 6 Matthew Dickinson 2009-10-08 16:02:17 UTC
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

Comment 7 Jeremy Allison 2009-10-28 19:32:45 UTC
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.
Comment 8 Matthew Dickinson 2009-10-29 10:22:56 UTC
no change - it's still behaving the same,
Comment 9 Brian Bayorgeon 2009-10-31 15:15:20 UTC
(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)
Comment 10 Brian Bayorgeon 2009-11-09 21:51:58 UTC
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.
Comment 11 Tony Hardie 2009-12-04 11:45:20 UTC
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.