From: Moritz M <mailinglist@moritzmueller.ee>
To: Pavel Shilovsky <piastryyy@gmail.com>
Cc: linux-cifs <linux-cifs@vger.kernel.org>
Subject: Re: Possible timeout problem when opening a file twice on a SMB mount
Date: Wed, 30 Oct 2019 14:26:35 +0100 [thread overview]
Message-ID: <6492326ef9d8d1a9401fac243160646f@moritzmueller.ee> (raw)
In-Reply-To: <CAKywueQ8woeupNRqspAuOqL8rG1hNpWN_hwLCjFUpkk4mXeCvQ@mail.gmail.com>
[-- Attachment #1: Type: text/plain, Size: 511 bytes --]
Pavel,
meanwhile I updated to the supported kernels. The strange thing is, in
the kernel 5.2.21 in my distro (Manjaro) it works.
While it is not working with 5.3.7.
I checked the kernel sources of my distro and the patch is included
there.
I've attached a pcap and the dmesg output when using my small demo tool.
Can you check if it is the same issue as before or something different?
$ uname -r
5.3.7-2-MANJARO
$ mount.cifs -V
mount.cifs version: 6.8
$ samba --version
Version 4.10.8
Thanks
Moritz
[-- Attachment #2: smb_.pcapng --]
[-- Type: application/vnd.tcpdump.pcap, Size: 5839 bytes --]
[-- Attachment #3: dmesg.txt --]
[-- Type: text/plain, Size: 11286 bytes --]
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: CIFS VFS: in cifs_revalidate_dentry_attr as Xid: 1508 with uid: 0
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: name: \lyxtest
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: Update attributes: \lyxtest inode 0x000000000a4764d5 count 1 dentry: 0x00000000dd299c47 d_time 4299666705 jiffies 4299671571
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: Getting info on \lyxtest
[Mi Okt 30 14:12:29 2019] fs/cifs/transport.c: Sending smb: smb_len=356
[Mi Okt 30 14:12:29 2019] fs/cifs/connect.c: RFC1002 header 0x210
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 data length 56 offset 152
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 len 208
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 data length 116 offset 72
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 len 188
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: Calculated size 188 length 192 mismatch mid 1716
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: Calculated size 124 length 128 mismatch mid 1717
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2ops.c: add 3 credits total=512
[Mi Okt 30 14:12:29 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=1715 state=4
[Mi Okt 30 14:12:29 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=1716 state=4
[Mi Okt 30 14:12:29 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=1717 state=4
[Mi Okt 30 14:12:29 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:29 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:29 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 564914
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: cifs_revalidate_cache: invalidating inode 564914 mapping
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate_dentry_attr (xid = 1508) rc = 0
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: CIFS VFS: in cifs_atomic_open as Xid: 1509 with uid: 0
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: parent inode = 0x000000000a4764d5 name is: foo.txt and dentry = 0x000000001759cc20
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: name: \foo.txt
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: name: \lyxtest\foo.txt
[Mi Okt 30 14:12:29 2019] SMB2_open: 362 callbacks suppressed
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2pdu.c: create/open
[Mi Okt 30 14:12:29 2019] fs/cifs/transport.c: Sending smb: smb_len=220
[Mi Okt 30 14:12:29 2019] fs/cifs/connect.c: RFC1002 header 0xd0
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 data length 56 offset 152
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 len 208
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mi Okt 30 14:12:29 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=1718 state=4
[Mi Okt 30 14:12:29 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2pdu.c: parse query id context 0x8f319 0x100007
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: Getting info on \lyxtest\foo.txt
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: looking for uniqueid=586521
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 586521
[Mi Okt 30 14:12:29 2019] fs/cifs/inode.c: cifs_revalidate_cache: inode 586521 is new
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2ops.c: Batch Oplock granted on inode 00000000497f1344
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: CIFS VFS: leaving cifs_atomic_open (xid = 1509) rc = 0
[Mi Okt 30 14:12:29 2019] fs/cifs/file.c: CIFS VFS: in cifs_open as Xid: 1510 with uid: 0
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: name: \foo.txt
[Mi Okt 30 14:12:29 2019] fs/cifs/dir.c: name: \lyxtest\foo.txt
[Mi Okt 30 14:12:29 2019] fs/cifs/file.c: inode = 0x00000000497f1344 file flags are 0x8241 for \lyxtest\foo.txt
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2pdu.c: create/open
[Mi Okt 30 14:12:29 2019] fs/cifs/transport.c: Sending smb: smb_len=220
[Mi Okt 30 14:12:29 2019] fs/cifs/connect.c: RFC1002 header 0x58
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 len 88
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: Checking for oplock break
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: oplock level 0x0
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: No matching file for oplock break
[Mi Okt 30 14:12:29 2019] fs/cifs/connect.c: Received oplock break
[Mi Okt 30 14:12:29 2019] fs/cifs/connect.c: RFC1002 header 0x49
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
[Mi Okt 30 14:12:29 2019] fs/cifs/smb2misc.c: SMB2 len 73
[Mi Okt 30 14:12:59 2019] fs/cifs/connect.c: RFC1002 header 0xd0
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 data length 56 offset 152
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 208
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 0 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=1719 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2pdu.c: parse query id context 0x8f319 0x100007
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: Getting info on \lyxtest\foo.txt
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 586521
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: cifs_revalidate_cache: inode 586521 is oplocked
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: R Lease granted on inode 00000000497f1344
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_open (xid = 1510) rc = 0
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: CIFS VFS: in cifs_setattr_nounix as Xid: 1511 with uid: 0
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: setattr on file foo.txt attrs->ia_valid 0xa068
[Mi Okt 30 14:12:59 2019] fs/cifs/dir.c: name: \foo.txt
[Mi Okt 30 14:12:59 2019] fs/cifs/dir.c: name: \lyxtest\foo.txt
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2pdu.c: Flush
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: Sending smb: smb_len=92
[Mi Okt 30 14:12:59 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=1720 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: Sending smb: smb_len=108
[Mi Okt 30 14:12:59 2019] fs/cifs/connect.c: RFC1002 header 0x42
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 66
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=17 mid=1721 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: SetFSize for attrs rc = 0
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: CIFS - CTIME changed
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: Sending smb: smb_len=404
[Mi Okt 30 14:12:59 2019] fs/cifs/connect.c: RFC1002 header 0x198
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 data length 56 offset 152
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 208
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 66
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: Calculated size 66 length 72 mismatch mid 1723
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: Calculated size 124 length 128 mismatch mid 1724
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 3 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=1722 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=17 mid=1723 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=1724 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:59 2019] fs/cifs/inode.c: CIFS VFS: leaving cifs_setattr_nounix (xid = 1511) rc = 0
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 1512 with uid: 0
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 1512) rc = 0
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: Flush inode 00000000497f1344 file 000000008a463d7f rc 0
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: CIFS VFS: in _cifsFileInfo_put as Xid: 1513 with uid: 0
[Mi Okt 30 14:12:59 2019] SMB2_close_flags: 379 callbacks suppressed
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2pdu.c: Close
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: Sending smb: smb_len=92
[Mi Okt 30 14:12:59 2019] fs/cifs/connect.c: RFC1002 header 0x7c
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=1725 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 1514 with uid: 0
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 1514) rc = 0
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: Flush inode 00000000497f1344 file 0000000042aa1dc0 rc 0
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: closing last open instance for inode 00000000497f1344
[Mi Okt 30 14:12:59 2019] fs/cifs/file.c: CIFS VFS: in _cifsFileInfo_put as Xid: 1515 with uid: 0
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2pdu.c: Close
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: Sending smb: smb_len=92
[Mi Okt 30 14:12:59 2019] fs/cifs/connect.c: RFC1002 header 0x7c
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mi Okt 30 14:12:59 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mi Okt 30 14:12:59 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=1726 state=4
[Mi Okt 30 14:12:59 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mi Okt 30 14:13:15 2019] fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 1516 with uid: 0
[Mi Okt 30 14:13:15 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mi Okt 30 14:13:15 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mi Okt 30 14:13:15 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 1516) rc = 0
[Mi Okt 30 14:13:59 2019] fs/cifs/smb2pdu.c: In echo request
[Mi Okt 30 14:13:59 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mi Okt 30 14:13:59 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mi Okt 30 14:13:59 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mi Okt 30 14:13:59 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mi Okt 30 14:15:00 2019] fs/cifs/smb2pdu.c: In echo request
[Mi Okt 30 14:15:00 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mi Okt 30 14:15:00 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mi Okt 30 14:15:00 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mi Okt 30 14:15:00 2019] fs/cifs/smb2ops.c: add 1 credits total=512
next prev parent reply other threads:[~2019-10-30 13:26 UTC|newest]
Thread overview: 15+ messages / expand[flat|nested] mbox.gz Atom feed top
2019-09-20 10:57 Possible timeout problem when opening a file twice on a SMB mount Moritz M
2019-09-20 23:26 ` Pavel Shilovsky
2019-09-23 14:04 ` Moritz M
2019-09-24 18:11 ` ronnie sahlberg
2019-09-24 19:05 ` Pavel Shilovsky
2019-09-24 21:06 ` Pavel Shilovsky
2019-09-25 19:23 ` Moritz M
2019-09-25 20:54 ` Pavel Shilovsky
2019-09-26 10:53 ` Moritz M
2019-09-26 18:58 ` Pavel Shilovsky
2019-10-30 13:26 ` Moritz M [this message]
2019-10-30 21:51 ` Pavel Shilovsky
2019-10-31 9:20 ` Moritz M
2019-10-31 21:01 ` Pavel Shilovsky
2019-09-24 19:33 ` Moritz M
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=6492326ef9d8d1a9401fac243160646f@moritzmueller.ee \
--to=mailinglist@moritzmueller.ee \
--cc=linux-cifs@vger.kernel.org \
--cc=piastryyy@gmail.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox