Bug 5321 - Random "Access Denied" when accessing files on server
Random "Access Denied" when accessing files on server
Status: NEW
Product: Samba 3.0
Classification: Unclassified
Component: File Services
3.0.25b
x86 Linux
: P3 normal
: none
Assigned To: Samba Bugzilla Account
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2008-03-12 12:02 UTC by Paul Bijnens
Modified: 2008-03-17 08:37 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Paul Bijnens 2008-03-12 12:02:25 UTC
On some of our WinXP sp2 PC's we get random "Access Denied" errors when trying
to open files from the server.  When you get the error, and try again, it usually works, without any changing in permissions or whatever.

  Samba version:  samba-3.0.25b-1.el5_1.4
  OS: CentOS 5 with kernel 2.6.18-53.1.6.el5 (SMP)

I have a debuglevel 10 logfile of the problem, together with a complete tcpdump
network trace of the same traffic.
However it's too large to attach here (logfile 8MB, network trace 19 MB).
However feel free to contact me, and I can deliver it.

My own investigation in this problem noticed the following differences in 
the log file.

When the access succeeds, I find sequences like this in the log:

[2008/03/12 13:10:04, 10] smbd/open.c:fd_open(67)
  fd_open: name Invoicing_xxxx.xls, flags = 00 mode = 0775, fd = 26.
[2008/03/12 13:10:04, 2] smbd/open.c:open_file(391)
  Nathalie opened file Invoicing_xxxx.xls read=Yes write=No (numopen=1)
[2008/03/12 13:10:04, 3] smbd/oplock_linux.c:linux_set_kernel_oplock(180)
  linux_set_kernel_oplock: got kernel oplock on file Invoicing_xxxx.xls, dev = fd02, inode = 103023223, file_id = 7 
[2008/03/12 13:10:04, 5] smbd/oplock.c:set_file_oplock(126)
  set_file_oplock: granted oplock on file Invoicing_xxxx.xls, 0xfd02/103023223/7, tv_sec = 47d7c81c, tv_usec = 20b96
[2008/03/12 13:10:04, 10] locking/locking.c:unparse_share_modes(665)
  unparse_share_modes: del: 0, tok = 0, num: 1
[2008/03/12 13:10:04, 10] locking/locking.c:print_share_mode_table(482)
  print_share_mode_table: share_mode_entry[0]:  pid = 13174, share_access = 0x7, private_options = 0x840, access_mask = 0x20189, mid = 0x0, type= 0x3, file_id = 7, uid = 1030, flags = 0, dev = 0xfd02, inode = 103023223


[2008/03/12 13:10:05, 10] smbd/open.c:fd_open(67)
  fd_open: name Invoicing_xxxx.xls, flags = 00 mode = 0775, fd = 27.
[2008/03/12 13:10:05, 2] smbd/open.c:open_file(391)
  Nathalie opened file Invoicing_xxxx.xls read=Yes write=No (numopen=2)
[2008/03/12 13:10:05, 3] smbd/oplock_linux.c:linux_set_kernel_oplock(173)
  linux_set_kernel_oplock: Refused oplock on file Invoicing_xxxx.xls, fd = 27, dev = fd02, inode = 103023223. (Resource temporarily unavailable)
[2008/03/12 13:10:05, 10] locking/locking.c:unparse_share_modes(665)
  unparse_share_modes: del: 0, tok = 0, num: 2
[2008/03/12 13:10:05, 10] locking/locking.c:print_share_mode_table(482)
  print_share_mode_table: share_mode_entry[0]:  pid = 13174, share_access = 0x3, private_options = 0x40, access_mask = 0x2019f, mid = 0x0, type= 0x0, file_id = 11, uid = 1030, flags = 0, dev = 0xfd02, inode = 103023223
[2008/03/12 13:10:05, 10] locking/locking.c:print_share_mode_table(482)
  print_share_mode_table: share_mode_entry[1]:  pid = 13174, share_access = 0x3, private_options = 0x200044, access_mask = 0x20089, mid = 0x0, type= 0x0, file_id = 13, uid = 1030, flags = 0, dev = 0xfd02, inode = 103023223

Note that the oplock can be granted or refused, but both times, the ultimate open succeeds and the file is opened in the application on the PC.

Sometimes however, the open() fails and the user gets the error message 
"Access Denied" on his PC (this was with Excel 2007).
The logs then show this sequence:

[2008/03/12 13:11:48, 4] smbd/open.c:open_file_ntcreate(1605)
  calling open_file with flags=0x0 flags2=0x0 mode=0775, access_mask = 0x20089, open_access_mask = 0x20089
[2008/03/12 13:11:48, 10] smbd/open.c:fd_open(67)
  fd_open: name Invoicing_xxxx.xls, flags = 00 mode = 0775, fd = -1. Resource temporarily unavailable
[2008/03/12 13:11:48, 3] smbd/open.c:open_file(301)
  Error opening file Invoicing_xxxx.xls (NT_STATUS_ACCESS_DENIED) (local_flags=0) (flags=0)
[2008/03/12 13:11:48, 5] smbd/files.c:file_free(454)
  freed files structure 9418 (1 used)
[2008/03/12 13:11:48, 3] smbd/error.c:error_packet_set(106)
  error packet at smbd/nttrans.c(817) cmd=162 (SMBntcreateX) NT_STATUS_ACCESS_DENIED

It seems that there is some timing problem with oplocks.
Resulting in the open failing (while in the other case the open succeeded, 
but the oplock was granted or refused in the step after it).

For experimenting, I added "kernel oplock = no" to the smb.conf file.
Since then I cannot reproduce the problem anymore (while I could reproduce
it within 1 minute before).

Is this an oplock problem in samba?  Or linux kernel oplock problem?
Or something completely different?
Comment 1 Volker Lendecke 2008-03-14 16:04:09 UTC
This very much seems to be a problem with kernel oplocks. Is this a pure Samba serving local file systems, or do you for example re-export an NFS import, or a GFS file system? What other applications are running on the box?

Volker
Comment 2 Paul Bijnens 2008-03-17 08:37:41 UTC
It is indeed a local filesystem (ext3) that is shared by samba.
No NFS involved (although the filesystem itself is exported by NFS as well,
and can be accessed by some Linux workstations, although that is not the normal
path of access to the files).
The server is primarily a samba fileserver, running only a few scripts that
manipulate some files in the tree on request.  Simple perl scripts, no locking
involved. (And the files where the problem manifests, are not under that categorie.)

Since two weeks we also have another -- which I thought was unrelated -- weird problem on the same server:
When saving a mail or an attachment from Thunderbird into the samba share,
some people frequently get "File already exists", but they do not see it (can't
be -- it was in a new folder they created).  It seems however that Thunderbird 
on Windows always creates a 0-byte file, deletes it, and then prompts the user for the name to store.  The 0-byte file exists only milliseconds at most.
But it seems that here too, there is a some kind of timing problem or race condition, which results in the client seeing the presence of the file, while 
it should have been deleted already.

It is an SMP kernel, so maybe I should investigate more in the Unix-kernel for
race conditions or asynchronous events etc.