Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

[Samba] Constant error messages about failure to remove oplock

153 views
Skip to first unread message

Shyam Kaushik

unread,
Jul 9, 2015, 1:50:03 AM7/9/15
to
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

--
To unsubscribe from this list go to the following URL and read the
instructions: https://lists.samba.org/mailman/options/samba

Shyam Kaushik

unread,
Jul 9, 2015, 3:50:03 AM7/9/15
to
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....@SerNet.DE]
Sent: Thursday, July 09, 2015 12:51 PM
To: Shyam Kaushik
Cc: sa...@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:kon...@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

Volker Lendecke

unread,
Jul 9, 2015, 3:50:04 AM7/9/15
to
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:kon...@sernet.de

--

Volker Lendecke

unread,
Jul 9, 2015, 12:50:03 PM7/9/15
to
On Thu, Jul 09, 2015 at 01:09:05PM +0530, Shyam Kaushik wrote:
> 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!

No, sorry, not really. If I had a reproducer I'd probably
very quickly be able to see what's going on. The things I'd
look at are the debug level 10 log together with the strace.

With best regards,

Volker

--
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:kon...@sernet.de

--

Volker Lendecke

unread,
Jul 10, 2015, 5:00:03 AM7/10/15
to
On Fri, Jul 10, 2015 at 02:21:50PM +0530, Shyam Kaushik wrote:
> Hi Volker,
>
> Thanks for your reply. When the problem was happening(before we turned off
> level2-oplocks), we had captured one run with smbd debug all:10
> (unfortunately we didn’t setup for other modules like vfs etc). Can you
> please see if this below trace helps? Thanks.

Can you please send the whole logfile? Attachments will be
stripped at sa...@lists.samba.org, we might want to move
this to samba-technical. Or if you have some dropbox-like
thingy I might download it somewhere.

Shyam Kaushik

unread,
Jul 10, 2015, 5:00:03 AM7/10/15
to
Hi Volker,

Thanks for your reply. When the problem was happening(before we turned off
level2-oplocks), we had captured one run with smbd debug all:10
(unfortunately we didn’t setup for other modules like vfs etc). Can you
please see if this below trace helps? Thanks.

[2015/06/25 03:05:30.408432, 3, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/trans2.c:7907(smbd_do_setfilepathinfo)
smbd_do_setfilepathinfo: ~test.pst.tmp (fnum 3983022690) info_level=1020
totdata=8
[2015/06/25 03:05:30.408483, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/trans2.c:6989(smb_set_file_end_of_file_info)
smb_set_file_end_of_file_info: Set end of file info for file ~test.pst.tmp
to 65536
[2015/06/25 03:05:30.408531, 6, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/trans2.c:5904(smb_set_file_size)
smb_set_file_size: size: 65536 smb_set_file_size: file ~test.pst.tmp :
setting new size to 65536
[2015/06/25 03:05:30.413527, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/notify_internal.c:604(notify_tri


[2015/06/25 03:05:30.420741, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/notify_internal.c:604(notify_trigger)
notify_trigger called action=0x3, filter=0x0,
path=/export/home_dirs/~test.pst.tmp
[2015/06/25 03:05:30.420841, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/smb2_server.c:2511(smbd_smb2_request_done_ex)
smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[2] dyn[no:0]
at ../source3/smbd/smb2_setinfo.c:150


[2015/06/25 03:05:30.434676, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/smb2_setinfo.c:185(smbd_smb2_setinfo_send)
smbd_smb2_setinfo_send: ~test.pst.tmp - fnum 3983022690
[2015/06/25 03:05:30.434731, 3, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/trans2.c:7907(smbd_do_setfilepathinfo)
smbd_do_setfilepathinfo: ~test.pst.tmp (fnum 3983022690) info_level=1019
totdata=8
[2015/06/25 03:05:30.434773, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/trans2.c:6891(smb_set_file_allocation_info)
smb_set_file_allocation_info: Set file allocation info for file
~test.pst.tmp to 65536
[2015/06/25 03:05:30.434817, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/trans2.c:6899(smb_set_file_allocation_info)
smb_set_file_allocation_info: file ~test.pst.tmp : setting new allocation
size to 1048576

[2015/06/25 03:05:30.442167, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/notify_internal.c:604(notify_trigger)
notify_trigger called action=0x3, filter=0x0,
path=/export/home_dirs/~test.pst.tmp
[2015/06/25 03:05:30.442381, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/smb2_server.c:2511(smbd_smb2_request_done_ex)
smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[2] dyn[no:0]
at ../source3/smbd/smb2_setinfo.c:150


[2015/06/25 03:05:30.571342, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/smb2_server.c:1885(smbd_smb2_request_dispatch)
smbd_smb2_request_dispatch: opcode[SMB2_OP_WRITE] mid = 417352

[2015/06/25 03:05:30.573456, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/smb2_write.c:271(smbd_smb2_write_send)
smbd_smb2_write: ~test.pst.tmp - fnum 3983022690
[2015/06/25 03:05:30.573615, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/aio.c:939(schedule_aio_smb2_write)
smb2: scheduled aio_write for file ~test.pst.tmp, offset 0, len = 4096
(mid = 417352) outstanding_aio_calls = 1

[2015/06/25 03:05:30.578608, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/aio.c:959(aio_pwrite_smb2_done)
pwrite_recv returned 4096, err = no error
[2015/06/25 03:05:30.578716, 3, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/smb2_write.c:198(smb2_write_complete_internal)
smb2: fnum 3983022690, file ~test.pst.tmp, length=4096 offset=0 wrote=4096
[2015/06/25 03:05:30.578763, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/aio.c:981(aio_pwrite_smb2_done)
smb2: scheduled aio_write completed for file ~test.pst.tmp, offset 0,
requested 4096, written = 4096 (errcode = 0, NTSTATUS = NT_STATUS_OK)
[2015/06/25 03:05:30.578811, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)]
../source3/smbd/smb2_server.c:2511(smbd_smb2_request_done_ex)
smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[16] dyn[yes:0]
at ../source3/smbd/smb2_write.c:150

[2015/06/25 03:05:30.592594, 10, pid=1581, effective(2030299, 2000514),
real(2030299, 0)] ../source3/smbd/smb2_close.c:185(smbd_smb2_close)
smbd_smb2_close: ~test.pst.tmp - fnum 3983022690

[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

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

With best regards,

Volker

-----


No virus found in this message.
Checked by AVG - www.avg.com

Version: 2015.0.6037 / Virus Database: 4365/10191 - Release Date: 07/08/15

Shyam Kaushik

unread,
Jul 10, 2015, 7:40:03 AM7/10/15
to
Hi Volker,

I uploaded partial log file at
https://www.dropbox.com/l/zYF6qyCqPKGZb2zP2sdlOp

Can you please see if it gives better insight? Thanks for your valuable
inputs.

--Shyam

-----Original Message-----
From: Volker Lendecke [mailto:Volker....@SerNet.DE]
Sent: Friday, July 10, 2015 2:26 PM
To: Shyam Kaushik
Cc: sa...@lists.samba.org
Subject: Re: [Samba] Constant error messages about failure to remove oplock

On Fri, Jul 10, 2015 at 02:21:50PM +0530, Shyam Kaushik wrote:
> Hi Volker,
>
> Thanks for your reply. When the problem was happening(before we turned off
> level2-oplocks), we had captured one run with smbd debug all:10
> (unfortunately we didn’t setup for other modules like vfs etc). Can you
> please see if this below trace helps? Thanks.

Can you please send the whole logfile? Attachments will be
stripped at sa...@lists.samba.org, we might want to move
this to samba-technical. Or if you have some dropbox-like
thingy I might download it somewhere.

Volker

--
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:kon...@sernet.de

-----


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

--

0 new messages