[Samba] Constant error messages about failure to remove oplock

[Shyam Kaushik]

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