samba - Jul 2015 - Constant error messages about failure to remove oplock

Hi All,

Need your help/inputs on what could be the probable cause/how to debug
this further.

We are using samba-4.0.25 & expose a share that has oplocks enabled & no
kernel-oplocks set. We constantly see these messages in samba logs

	[2015/06/25 03:05:30.593150,  0, pid=1581, class=locking]
../source3/smbd/oplock_linux.c:184(linux_release_kernel_oplock)
	  linux_release_kernel_oplock: Error when removing kernel oplock
on file ~test.pst.tmp, file_id = 10fcbd:4a9ff1c:0, gen_id = 3680654993.
Error was Resource temporarily unavailable

We managed to capture tcpdump corresponding to one such occurrence &
sequence for all such failures are like

SMB2 create request comes with create-option to just open
	222.667201	10.48.66.95	10.6.0.101	SMB2	386
Create Request File: ~test.pst.tmp
		Oplock: No oplock (0x00)
		Impersonation: Impersonation (2)
		Create Flags: 0x0000000000000000
		Access Mask: 0x00000080
			.... .... .... .... .... .... 1... .... = Read
Attributes: READ ATTRIBUTES access
		Create Options: 0x00200000
			.... .... ..1. .... .... .... .... .... = Open
Reparse Point: Open a Reparse Point
		File Attributes: 0x00000000
		Share Access: 0x00000007 SHARE_DELETE SHARE_WRITE
SHARE_READ
		ExtraInfo DHnQ MxAc QFid

This fails with object-not-found
       222.667599	10.6.0.101	10.48.66.95	SMB2	131
Create Response, Error: STATUS_OBJECT_NAME_NOT_FOUND

SMB2 create request comes to create the file with batch-oplock/request
durable handle
	222.681571	10.48.66.95	10.6.0.101	SMB2	386
Create Request File: ~test.pst.tmp
		Oplock: Batch oplock (0x09)
		Impersonation: Anonymous (0)
		Access Mask: 0x0012019f
		.... .... ...1 .... .... .... .... .... = Synchronize: Can
wait on handle to SYNCHRONIZE on completion of I/O
		.... .... .... ..1. .... .... .... .... = Read Control:
READ ACCESS to owner, group and ACL of the SID
		.... .... .... .... .... ...1 .... .... = Write
Attributes: WRITE ATTRIBUTES access
		.... .... .... .... .... .... 1... .... = Read Attributes:
READ ATTRIBUTES access
		.... .... .... .... .... .... ...1 .... = Write EA: WRITE
EXTENDED ATTRIBUTES access
		.... .... .... .... .... .... .... 1... = Read EA: READ
EXTENDED ATTRIBUTES access
		.... .... .... .... .... .... .... .1.. = Append: APPEND
access
		.... .... .... .... .... .... .... ..1. = Write: WRITE
access
		.... .... .... .... .... .... .... ...1 = Read: READ
access
		File Attributes: 0x00000182
		.... .... .... .... .... ...1 .... .... = Temporary: This
is a TEMPORARY file
		.... .... .... .... .... .... 1... .... = Normal: This
file is an ordinary file
		.... .... .... .... .... .... .... ..1. = Hidden: This is
a HIDDEN file
		Share Access: 0x00000003 SHARE_WRITE SHARE_READ
		Disposition: Create (if file exists fail, else create it)
(2)
		ExtraInfo DHnQ MxAc QFid

We don't set "kernel share modes" & so no durable handle is
returned & the
file gets created alright
       222.816196	10.6.0.101	10.48.66.95	SMB2	298
Create Response File: ~test.pst.tmp
		File Id: 3293dc4e-0000-0000-621a-68ed00000000

60-secs later Set-file-info/end-of-file  comes
	282.867285	10.48.66.95	10.6.0.101	SMB2	162
SetInfo Request FILE_INFO/SMB2_FILE_ENDOFFILE_INFO File: ~test.pst.tmp
		InfoLevel: SMB2_FILE_ENDOFFILE_INFO (0x14)
			End Of File: 65536
	282.887473	10.6.0.101	10.48.66.95	SMB2	124
SetInfo Response
		NT Status: STATUS_SUCCESS (0x00000000)

Set-file-info/file-allocation-info comes
	282.900740	10.48.66.95	10.6.0.101	SMB2	162
SetInfo Request FILE_INFO/SMB2_FILE_ALLOCATION_INFO File: ~test.pst.tmp
		InfoLevel: SMB2_FILE_ALLOCATION_INFO (0x13)
			Allocation Size: 65536
	282.909077	10.6.0.101	10.48.66.95	SMB2	124
SetInfo Response
		NT Status: STATUS_SUCCESS (0x00000000)

Write-request comes & we have setup aio-write-size=1byte. So it gets a
status-pending & then write completes
	283.036400	10.48.66.95	10.6.0.101	SMB2	1346
Write Request Len:4096 Off:0 File: ~test.pst.tmp
	283.042592	10.6.0.101	10.48.66.95	SMB2	131
Write Response, Error: STATUS_PENDING
	283.045341	10.6.0.101	10.48.66.95	SMB2	138
Write Response

Request comes to close this file
	283.058606	10.48.66.95	10.6.0.101	SMB2	146
Close Request File: ~test.pst.tmp
	283.063906	10.6.0.101	10.48.66.95	SMB2	182
Close Response
		Allocation Size: 1048576
		End Of File: 65536

When this close request comes in, the oplock error shows up
	[2015/06/25 03:05:30.593150,  0, pid=1581, class=locking]
../source3/smbd/oplock_linux.c:184(linux_release_kernel_oplock)
	  linux_release_kernel_oplock: Error when removing kernel oplock
on file ~test.pst.tmp, file_id = 10fcbd:4a9ff1c:0, gen_id = 3680654993.
Error was Resource temporarily unavailable

essentially meaning close_file() tried a release_file_oplock() which tried
to release lease on underlying file that is not set. We confirmed that
there are no oplock-break or similar request coming in for this file.

Any pointers on where the issue could be? Thanks.

--Shyam

On Thu, Jul 09, 2015 at 10:39:58AM +0530, Shyam Kaushik
wrote:
> Hi All,
> 
> Need your help/inputs on what could be the probable cause/how to debug
> this further.
> 
> We are using samba-4.0.25 & expose a share that has oplocks enabled
& no
> kernel-oplocks set. We constantly see these messages in samba logs
> 
> 	[2015/06/25 03:05:30.593150,  0, pid=1581, class=locking]
> ../source3/smbd/oplock_linux.c:184(linux_release_kernel_oplock)
> 	  linux_release_kernel_oplock: Error when removing kernel oplock
> on file ~test.pst.tmp, file_id = 10fcbd:4a9ff1c:0, gen_id = 3680654993.
> Error was Resource temporarily unavailable
Do you have "kernel oplocks = no" set? Then this is
surprising to see. If you can reproduce it, can you send the
output of

strace -ttT -p <smbd-pid> 

for such an smbd from before opening the file to the error?

Thanks,

Volker Lendecke

-- 
SerNet GmbH, Bahnhofsallee 1b, 37081 Göttingen
phone: +49-551-370000-0, fax: +49-551-370000-9
AG Göttingen, HRB 2816, GF: Dr. Johannes Loxen
http://www.sernet.de, mailto:kontakt at sernet.de

Hi Volker,

Yes this problem happens when we have "kernel oplocks = no". This
happened
constantly in one of production systems & so we disabled level2-oplock
/set kernel-oplocks=yes (to avoid this issue). So unfortunately don’t have
an environment where it reproduces now & cannot capture strace.

I modified smbtorture/smb2 to do a test exactly like the tcpdump trace,
but the problem doesn’t happen. One thing is we don’t have session
create/tree-connect captured for the below problematic case. Do you think
it can have any influence on this (like varied parameters negotiated at
session establish)?

Also one difference b/n the smbtorture/smb2 test that I wrote is, in the
tcpdump I see that when the original problem happened, in SMB2/create
response, samba returned allocation-size=1MB whereas in my test, this is
not returned. I am not sure how this can happen as SMB2 create request in
tcpdump has
	ExtraInfo DHnQ MxAc QFid
(i.e. no ALSI specified in it). Any thoughts?

Thanks for your inputs!

--Shyam

-----Original Message-----
From: Volker Lendecke [mailto:Volker.Lendecke at SerNet.DE]
Sent: Thursday, July 09, 2015 12:51 PM
To: Shyam Kaushik
Cc: samba at lists.samba.org
Subject: Re: [Samba] Constant error messages about failure to remove
oplock

On Thu, Jul 09, 2015 at 10:39:58AM +0530, Shyam Kaushik
wrote:
> Hi All,
>
> Need your help/inputs on what could be the probable cause/how to debug
> this further.
>
> We are using samba-4.0.25 & expose a share that has oplocks enabled
& no
> kernel-oplocks set. We constantly see these messages in samba logs
>
> 	[2015/06/25 03:05:30.593150,  0, pid=1581, class=locking]
> ../source3/smbd/oplock_linux.c:184(linux_release_kernel_oplock)
> 	  linux_release_kernel_oplock: Error when removing kernel oplock
> on file ~test.pst.tmp, file_id = 10fcbd:4a9ff1c:0, gen_id = 3680654993.
> Error was Resource temporarily unavailable
Do you have "kernel oplocks = no" set? Then this is
surprising to see. If you can reproduce it, can you send the
output of

strace -ttT -p <smbd-pid>

for such an smbd from before opening the file to the error?

Thanks,

Volker Lendecke

--
SerNet GmbH, Bahnhofsallee 1b, 37081 Göttingen
phone: +49-551-370000-0, fax: +49-551-370000-9
AG Göttingen, HRB 2816, GF: Dr. Johannes Loxen
http://www.sernet.de, mailto:kontakt at sernet.de

-----
No virus found in this message.
Checked by AVG - www.avg.com
Version: 2015.0.6037 / Virus Database: 4365/10156 - Release Date: 07/04/15