[Samba] Constant error messages about failure to remove oplock

Fri Jul 10 08:51:50 UTC 2015

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.Lendecke at SerNet.DE]
Sent: Thursday, July 09, 2015 10:07 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 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:kontakt at 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