Bug 5557 - oplocks not breaking
oplocks not breaking
Status: RESOLVED FIXED
Product: Samba 3.0
Classification: Unclassified
Component: File Services
3.0.24
x86 Linux
: P3 normal
: none
Assigned To: Samba Bugzilla Account
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2008-06-22 18:37 UTC by Brian May
Modified: 2008-06-26 01:58 UTC (History)
1 user (show)

See Also:


Attachments
Log file from server (497.59 KB, text/plain)
2008-06-22 18:47 UTC, Brian May
no flags Details
Console log (21.08 KB, text/plain)
2008-06-22 18:51 UTC, Brian May
no flags Details
2 sambas, 1st computer (works fine) (987.32 KB, text/plain)
2008-06-22 23:42 UTC, Brian May
no flags Details
2 sambas, 2nd computer (5.48 KB, text/plain)
2008-06-22 23:45 UTC, Brian May
no flags Details
2 sambas, 1st computer (works fine) (276.94 KB, application/x-gzip)
2008-06-23 00:27 UTC, Brian May
no flags Details
2 sambas, 2nd computer (357.97 KB, application/x-gzip)
2008-06-23 00:28 UTC, Brian May
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Brian May 2008-06-22 18:37:02 UTC
Hello,

As per thread starting from <http://permalink.gmane.org/gmane.network.samba.general/99261>, Samba oplocks are locking other processes (including Samba and other Unix processes) out from accessing certain files.

I was asked to submit a bug report here.

I will see if I can attach the log file after I submit.

Thanks.

Brian May
Comment 1 Brian May 2008-06-22 18:47:01 UTC
Created attachment 3357 [details]
Log file from server

This is the log file of the server process (15808) that presumably creates the oplock/lease for the /var/lib/wpkg/cp_status.cmd file.
Comment 2 Brian May 2008-06-22 18:51:02 UTC
Created attachment 3358 [details]
Console log

After starting the first process, I typed these commands in a second window. If cat didn't return anything, that is because I pushed Ctrl+C to abort.

This particular test case involves a *.cmd file, but the same thing happens to *.xml files too.

Note shown: I also confirmed with smbstatus that process 15808 is the correct process for the log file I attached (also verifiable from the log file).
Comment 3 Brian May 2008-06-22 18:53:23 UTC
Hello,

I started wpkg on the server, which created the Samba log file (attached). I then typed in the commands in the server (see console log, attached) to verify that I get blocked trying to access the file. I think I could also reproduce between two Samba sessions, although this is easier.

Brian May
Comment 4 Volker Lendecke 2008-06-22 22:49:50 UTC
Ok, thanks.

As I wrote in my mail: It is relevant if you have it between two smbds or also with interaction with other unix processes. In the case you list (with console interaction) we need the output of "strace -p <pid>" while the console is trying to break the oplock.

When you type "cat cp_status.cmd" the first time, a signal must be sent to the smbd. If this not the case, then it's a kernel bug.

Volker
Comment 5 Brian May 2008-06-22 23:11:24 UTC
Ok, I assume you want me to strace the samba process, the cat strace isn't very exciting:

open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE[45 second pause]) = 3

In fact the strace of the samba process seems unreasonably dull and boring too. I started strace before running cat, and stopped it after cat eventually finished.

hq:~# cat /proc/locks | grep :0a:
1: LEASE  ACTIVE    WRITE 16100 fd:0a:131 0 EOF
hq:~# strace -o/tmp.out -ff -p 16100
Process 16100 attached - interrupt to quit
Process 16100 detached
hq:~# cat /tmp.out 
select(22, [6 21], NULL, NULL, {30, 424000}) = 0 (Timeout)
time(NULL)                              = 1214193715
geteuid32()                             = 65534
setresuid32(0, 0, -1)                   = 0
geteuid32()                             = 0
geteuid32()                             = 0
getegid32()                             = 65534
setresgid32(-1, 0, -1)                  = 0
getegid32()                             = 0
getegid32()                             = 0
setgroups32(0, [])                      = 0
setresgid32(-1, 0, -1)                  = 0
getegid32()                             = 0
setresuid32(0, 0, -1)                   = 0
geteuid32()                             = 0
geteuid32()                             = 0
fstat64(28, {st_mode=S_IFREG|0644, st_size=557041, ...}) = 0
select(22, [6 21], NULL, NULL, {60, 0} <unfinished ...>

So can we conclude a kernel bug?
Comment 6 Volker Lendecke 2008-06-22 23:17:12 UTC
If according to /proc/locks the oplock is being held, you're trying to access the file and nothing happens in the strace, it does smell like a kernel bug. But as I said, please also provide log files when this happens with two smbds involved. Then we'd need logfiles of both smbds with "debug hires timestamp = yes".

Volker
Comment 7 Brian May 2008-06-22 23:18:29 UTC
(In reply to comment #6)
> If according to /proc/locks the oplock is being held, you're trying to access
> the file and nothing happens in the strace, it does smell like a kernel bug.
> But as I said, please also provide log files when this happens with two smbds
> involved. Then we'd need logfiles of both smbds with "debug hires timestamp =
> yes".

Log files are already attached to the bug report. 

Comment 8 Brian May 2008-06-22 23:19:47 UTC
(In reply to comment #7)
> > But as I said, please also provide log files when this happens with two smbds
> > involved. Then we'd need logfiles of both smbds with "debug hires timestamp =
> > yes".
> 
> Log files are already attached to the bug report. 

Sorry, misread this. Will try to obtain the requested log files.

Brian May
Comment 9 Brian May 2008-06-22 23:42:09 UTC
Created attachment 3359 [details]
2 sambas, 1st computer (works fine)
Comment 10 Brian May 2008-06-22 23:45:17 UTC
Created attachment 3360 [details]
2 sambas, 2nd computer

The wpkg logs might also be useful, at least the top which I have quoted below. Each file takes 30 seconds to open (unlike with cat where it was 45 seconds). This wpkg process is what requested the files from the Windows client computer.

2008-06-23 14:27:54, DEBUG  : Initialized temporary local log file: C:\WINDOWS\TEMP\wpkg-logInit.log
2008-06-23 14:27:54, DEBUG  : Initializing new log file: \\hq\wpkg-status\aquifer.log
2008-06-23 14:27:53, DEBUG  : Reboot-Cmd is standard.
2008-06-23 14:27:54, DEBUG  : WPKG 1.0 starting...
2008-06-23 14:27:54, DEBUG  : Base directory is '\\hq\wpkg\cur'.
2008-06-23 14:27:54, DEBUG  : Log level is 255
2008-06-23 14:27:54, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\profiles.xml
2008-06-23 14:28:24, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\profiles.xml
2008-06-23 14:28:24, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\profiles
2008-06-23 14:28:24, DEBUG  : Reading XML file: //hq/wpkg/cur/profiles/vpac.xml
2008-06-23 14:28:54, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\hosts.xml
2008-06-23 14:29:24, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\hosts.xml
2008-06-23 14:29:24, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\hosts
2008-06-23 14:29:24, DEBUG  : Reading XML file: //hq/wpkg/cur/hosts/vpac.xml
2008-06-23 14:29:54, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\packages.xml
2008-06-23 14:30:24, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\packages.xml
2008-06-23 14:30:24, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\packages
2008-06-23 14:30:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/winscp.xml
2008-06-23 14:30:54, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/java6.xml
2008-06-23 14:31:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/reader.xml
2008-06-23 14:31:54, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/thunderbird.xml
2008-06-23 14:32:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/firefox.xml
2008-06-23 14:32:54, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/windows.xml
2008-06-23 14:33:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/7zip.xml
2008-06-23 14:33:54, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/certificates.xml
2008-06-23 14:34:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/ctupdate4.xml
2008-06-23 14:34:54, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/openvpn.xml
2008-06-23 14:35:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/pdfcreator.xml
2008-06-23 14:35:54, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/pidgin.xml
2008-06-23 14:36:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/putty.xml
2008-06-23 14:36:54, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/ooo.xml
2008-06-23 14:37:24, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/wpkg.xml
2008-06-23 14:37:54, DEBUG  : Profiles applying to the current host:|laptop|
2008-06-23 14:37:54, DEBUG  : Reading settings file: C:\WINDOWS\system32\wpkg.xml
2008-06-23 14:37:54, DEBUG  : Trying to read XML file: C:\WINDOWS\system32\wpkg.xml
2008-06-23 14:37:54, DEBUG  : Successfully loaded XML file: C:\WINDOWS\system32\wpkg.xml
2008-06-23 14:37:54, DEBUG  : Getting profiles which apply to this node.
[...]
Comment 11 Brian May 2008-06-22 23:55:17 UTC
(In reply to comment #10)
> Created an attachment (id=3360) [edit]
> 2 sambas, 2nd computer

I just noticed this file was auto-rotated, and doesn't include the required information. Will have to do that again I guess. The other file is OK though.

Brian May
Comment 12 Brian May 2008-06-23 00:27:09 UTC
Created attachment 3361 [details]
2 sambas, 1st computer (works fine)

2008-06-23 15:08:55, DEBUG  : Initialized temporary local log file: C:\WINDOWS\TEMP\wpkg-logInit.log
2008-06-23 15:08:55, DEBUG  : Initializing new log file: \\hq\wpkg-status\dell002.log
2008-06-23 15:08:55, DEBUG  : Reboot-Cmd is standard.
2008-06-23 15:08:55, DEBUG  : WPKG 1.0 starting...
2008-06-23 15:08:55, DEBUG  : Base directory is '\\hq\wpkg\cur'.
2008-06-23 15:08:55, DEBUG  : Log level is 255
2008-06-23 15:08:55, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\profiles.xml
2008-06-23 15:08:55, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\profiles.xml
2008-06-23 15:08:55, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\profiles
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/profiles/vpac.xml
2008-06-23 15:08:56, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\hosts.xml
2008-06-23 15:08:56, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\hosts.xml
2008-06-23 15:08:56, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\hosts
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/hosts/vpac.xml
2008-06-23 15:08:56, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\packages.xml
2008-06-23 15:08:56, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\packages.xml
2008-06-23 15:08:56, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\packages
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/winscp.xml
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/java6.xml
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/reader.xml
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/thunderbird.xml
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/firefox.xml
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/windows.xml
2008-06-23 15:08:56, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/7zip.xml
2008-06-23 15:08:57, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/certificates.xml
2008-06-23 15:08:57, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/ctupdate4.xml
2008-06-23 15:08:57, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/openvpn.xml
2008-06-23 15:08:57, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/pdfcreator.xml
2008-06-23 15:08:57, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/pidgin.xml
2008-06-23 15:08:57, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/putty.xml
2008-06-23 15:08:57, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/ooo.xml
2008-06-23 15:08:58, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/wpkg.xml
2008-06-23 15:08:58, DEBUG  : Profiles applying to the current host:|laptop|
Comment 13 Brian May 2008-06-23 00:28:48 UTC
Created attachment 3362 [details]
2 sambas, 2nd computer

2008-06-23 15:10:32, DEBUG  : Initialized temporary local log file: C:\WINDOWS\TEMP\wpkg-logInit.log
2008-06-23 15:10:32, DEBUG  : Initializing new log file: \\hq\wpkg-status\aquifer.log
2008-06-23 15:10:31, DEBUG  : Reboot-Cmd is standard.
2008-06-23 15:10:32, DEBUG  : WPKG 1.0 starting...
2008-06-23 15:10:32, DEBUG  : Base directory is '\\hq\wpkg\cur'.
2008-06-23 15:10:32, DEBUG  : Log level is 255
2008-06-23 15:10:32, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\profiles.xml
2008-06-23 15:11:02, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\profiles.xml
2008-06-23 15:11:02, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\profiles
2008-06-23 15:11:02, DEBUG  : Reading XML file: //hq/wpkg/cur/profiles/vpac.xml
2008-06-23 15:11:32, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\hosts.xml
2008-06-23 15:12:02, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\hosts.xml
2008-06-23 15:12:02, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\hosts
2008-06-23 15:12:02, DEBUG  : Reading XML file: //hq/wpkg/cur/hosts/vpac.xml
2008-06-23 15:12:32, DEBUG  : Trying to read XML file: \\hq\wpkg\cur\packages.xml
2008-06-23 15:13:02, DEBUG  : Successfully loaded XML file: \\hq\wpkg\cur\packages.xml
2008-06-23 15:13:02, DEBUG  : Trying to read XML files from directory: \\hq\wpkg\cur\packages
2008-06-23 15:13:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/winscp.xml
2008-06-23 15:13:32, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/java6.xml
2008-06-23 15:14:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/reader.xml
2008-06-23 15:14:32, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/thunderbird.xml
2008-06-23 15:15:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/firefox.xml
2008-06-23 15:15:32, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/windows.xml
2008-06-23 15:16:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/7zip.xml
2008-06-23 15:16:32, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/certificates.xml
2008-06-23 15:17:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/ctupdate4.xml
2008-06-23 15:17:32, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/openvpn.xml
2008-06-23 15:18:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/pdfcreator.xml
2008-06-23 15:18:32, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/pidgin.xml
2008-06-23 15:19:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/putty.xml
2008-06-23 15:19:32, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/ooo.xml
2008-06-23 15:20:02, DEBUG  : Reading XML file: //hq/wpkg/cur/packages/wpkg.xml
2008-06-23 15:20:32, DEBUG  : Profiles applying to the current host:|laptop|
Comment 14 Volker Lendecke 2008-06-23 00:33:09 UTC
Hmmmm. Looks all normal, we request the client on log.dell002 to release its oplock, but it does not. Is DELL002 at this point still alive? If yes, it might be a client problem that a sniff might show. If DELL002 has died, this is normal, expected behaviour.

Volker
Comment 15 Brian May 2008-06-23 00:48:29 UTC
(In reply to comment #14)
> Hmmmm. Looks all normal, we request the client on log.dell002 to release its
> oplock, but it does not. Is DELL002 at this point still alive? If yes, it might
> be a client problem that a sniff might show.

DELL002 is alive.

It is a Dell Latitude D610. Windows XP SP2, all updates (excluding SP3).

I guess I will need to see if I can reproduce this problem without DELL002. 

I think I have done just this in the past, but can't be absolutely sure.


> If DELL002 has died, this is normal, expected behaviour.

In this case will Samba eventually wake up and realise that the client died and release the oplocks? Or does each oplock have to be broken individually, one at a time?


Brian May
Comment 16 Brian May 2008-06-23 01:08:54 UTC
(In reply to comment #15)
> DELL002 is alive.

Damn. I really wanted to believe that the problem was a dying hard disk on Dell002. It was making sounds when idle that made me wonder.

Only I managed to reproduce the problem with aquifer (as first computer) and another computer (Cmi006). Dell002 wasn't involved in form, and was switched off for the test.

If this was a genuine bug with Windows, I would have expected other people would experience the same thing...

Brian May
Comment 17 Brian May 2008-06-26 01:32:49 UTC
Hello,

Thanks for your help.

Just a followup: Every indication seems to be that it is the firewall in the virus scanner we use, F-Secure, that prevents Windows from releasing oplocks properly. After turning off the firewall, the oplocks get released and there is no problem. Possibly related to the timing of wpkg being invoked before system logons too.

Might be time to consider another virus scanner/firewall solution.

Marking this bug as fixed.

Brian May 
Comment 18 Volker Lendecke 2008-06-26 01:58:16 UTC
Thanks for the feedback!

Volker