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
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.
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).
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
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
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?
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
(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.
(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
Created attachment 3359 [details] 2 sambas, 1st computer (works fine)
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. [...]
(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
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|
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|
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
(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
(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
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
Thanks for the feedback! Volker