Volker Lendecke
2015-Jul-09 16:37 UTC
[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
Shyam Kaushik
2015-Jul-10 08:51 UTC
[Samba] Constant error messages about failure to remove oplock
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
Volker Lendecke
2015-Jul-10 08:56 UTC
[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 samba at 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:kontakt at sernet.de