Possible timeout problem when opening a file twice on a SMB mount

Possible timeout problem when opening a file twice on a SMB mount

[Moritz M]

Hello,

I've some trouble with saving files with a particular software, LyX[0] 
in this case.
The problem is that saving a file on a SMB share makes the programm 
freeze for 30 s
due to creating an empty temp file.

While investigating I created a small python script which mimics 
(compared the strace output)
the LyX behaviour and also freezes the python script for 30 s.
That makes me believe that it could be a cifs problem.

The python script is:

#!/usr/bin/env python3

import os, sys

fd = os.open( "/mnt/share/foo.txt", 
os.O_RDWR|os.O_CREAT|os.O_EXCL|os.O_CLOEXEC, 0o600 )
fd = os.access( "/mnt/share/foo.txt", os.F_OK )
fd = os.chmod( "/mnt/share/foo.txt", 0o755 )
fd = os.open( "/mnt/share/foo.txt", os.O_WRONLY|os.O_CREAT|os.O_TRUNC, 
0o666 )

# Close opened file
os.close( fd )


Stracing it with

strace -f -t -T -e trace=openat,close,chmod,access python open.py

gives

23:18:52 openat(AT_FDCWD, "/mnt/share/foo.txt", 
O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 3 <0.002434>
23:18:52 access("/mnt/share/foo.txt", F_OK) = 0 <0.000091>
23:18:52 chmod("/mnt/share/foo.txt", 0755) = 0 <0.000168>
23:18:52 openat(AT_FDCWD, "/mnt/share/foo.txt", 
O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 4 <30.033585>

The second openat call takes 30 s and freezes the script.

When doing a os.close( fd ) after first open in the python script it 
works as expected:

23:22:11 openat(AT_FDCWD, "/mnt/share/foo.txt", 
O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 3 <0.002464>
23:22:11 close(3)                       = 0 <0.001652>
23:22:11 access("/mnt/share/foo.txt", F_OK) = 0 <0.000082>
23:22:11 chmod("/mnt/share/foo.txt", 0755) = 0 <0.000175>
23:22:11 openat(AT_FDCWD, "/mnt/share/foo.txt", 
O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 3 <0.003221>

My setup ist (server is a Synology Diskstation):

$ uname -r
5.1.21-1-MANJARO

$ mount.cifs -V
mount.cifs version: 6.8

$ samba --version
Version 4.4.16


Display Internal CIFS Data Structures for Debugging
---------------------------------------------------
CIFS Version 2.19
Features: 
DFS,FSCACHE,STATS,DEBUG,ALLOW_INSECURE_LEGACY,CIFS_POSIX,UPCALL(SPNEGO),XATTR,ACL
CIFSMaxBufSize: 16384
Active VFS Requests: 0
Servers:
Number of credits: 510 Dialect 0x311
1) Name: x.x.x.x Uses: 1 Capability: 0x300045	Session Status: 1 TCP 
status: 1 Instance: 1
	Local Users To Server: 1 SecMode: 0x1 Req On Wire: 0 SessionId: 
0x14e3311d
	Shares:
	0) IPC: \\server\IPC$ Mounts: 1 DevInfo: 0x0 Attributes: 0x0
	PathComponentMax: 0 Status: 1 type: 0 Serial Number: 0x0
	Share Capabilities: None	Share Flags: 0x0
	tid: 0xf1884345	Maximal Access: 0x1f00a9

	1) \\server\share Mounts: 1 DevInfo: 0x20 Attributes: 0x5006f
	PathComponentMax: 255 Status: 1 type: DISK Serial Number: 0x1dc3f115
	Share Capabilities: None Aligned, Partition Aligned,	Share Flags: 0x800
	tid: 0xe3ad48c8	Optimal sector size: 0x200	Maximal Access: 0x1f01ff

	MIDs:



Does anybody has a clue why it takes exactly 30 s when opening a file 
twice?
Even more important: how can I prevent it?
Any help is appreciated.

Thanks
Moritz

[0]: https://www.lyx.org/

Re: Possible timeout problem when opening a file twice on a SMB mount

[Pavel Shilovsky]

пт, 20 сент. 2019 г. в 12:11, Moritz M <mailinglist@moritzmueller.ee>:
>
> Hello,
>
> I've some trouble with saving files with a particular software, LyX[0]
> in this case.
> The problem is that saving a file on a SMB share makes the programm
> freeze for 30 s
> due to creating an empty temp file.
>
> While investigating I created a small python script which mimics
> (compared the strace output)
> the LyX behaviour and also freezes the python script for 30 s.
> That makes me believe that it could be a cifs problem.
>
> The python script is:
>
> #!/usr/bin/env python3
>
> import os, sys
>
> fd = os.open( "/mnt/share/foo.txt",
> os.O_RDWR|os.O_CREAT|os.O_EXCL|os.O_CLOEXEC, 0o600 )
> fd = os.access( "/mnt/share/foo.txt", os.F_OK )
> fd = os.chmod( "/mnt/share/foo.txt", 0o755 )
> fd = os.open( "/mnt/share/foo.txt", os.O_WRONLY|os.O_CREAT|os.O_TRUNC,
> 0o666 )
>
> # Close opened file
> os.close( fd )
>
>
> Stracing it with
>
> strace -f -t -T -e trace=openat,close,chmod,access python open.py
>
> gives
>
> 23:18:52 openat(AT_FDCWD, "/mnt/share/foo.txt",
> O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 3 <0.002434>
> 23:18:52 access("/mnt/share/foo.txt", F_OK) = 0 <0.000091>
> 23:18:52 chmod("/mnt/share/foo.txt", 0755) = 0 <0.000168>
> 23:18:52 openat(AT_FDCWD, "/mnt/share/foo.txt",
> O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 4 <30.033585>
>
> The second openat call takes 30 s and freezes the script.
>
> When doing a os.close( fd ) after first open in the python script it
> works as expected:
>
> 23:22:11 openat(AT_FDCWD, "/mnt/share/foo.txt",
> O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 3 <0.002464>
> 23:22:11 close(3)                       = 0 <0.001652>
> 23:22:11 access("/mnt/share/foo.txt", F_OK) = 0 <0.000082>
> 23:22:11 chmod("/mnt/share/foo.txt", 0755) = 0 <0.000175>
> 23:22:11 openat(AT_FDCWD, "/mnt/share/foo.txt",
> O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 3 <0.003221>
>
> My setup ist (server is a Synology Diskstation):
>
> $ uname -r
> 5.1.21-1-MANJARO
>
> $ mount.cifs -V
> mount.cifs version: 6.8
>
> $ samba --version
> Version 4.4.16
>
>
> Display Internal CIFS Data Structures for Debugging
> ---------------------------------------------------
> CIFS Version 2.19
> Features:
> DFS,FSCACHE,STATS,DEBUG,ALLOW_INSECURE_LEGACY,CIFS_POSIX,UPCALL(SPNEGO),XATTR,ACL
> CIFSMaxBufSize: 16384
> Active VFS Requests: 0
> Servers:
> Number of credits: 510 Dialect 0x311
> 1) Name: x.x.x.x Uses: 1 Capability: 0x300045   Session Status: 1 TCP
> status: 1 Instance: 1
>         Local Users To Server: 1 SecMode: 0x1 Req On Wire: 0 SessionId:
> 0x14e3311d
>         Shares:
>         0) IPC: \\server\IPC$ Mounts: 1 DevInfo: 0x0 Attributes: 0x0
>         PathComponentMax: 0 Status: 1 type: 0 Serial Number: 0x0
>         Share Capabilities: None        Share Flags: 0x0
>         tid: 0xf1884345 Maximal Access: 0x1f00a9
>
>         1) \\server\share Mounts: 1 DevInfo: 0x20 Attributes: 0x5006f
>         PathComponentMax: 255 Status: 1 type: DISK Serial Number: 0x1dc3f115
>         Share Capabilities: None Aligned, Partition Aligned,    Share Flags: 0x800
>         tid: 0xe3ad48c8 Optimal sector size: 0x200      Maximal Access: 0x1f01ff
>
>         MIDs:
>
>
>
> Does anybody has a clue why it takes exactly 30 s when opening a file
> twice?
> Even more important: how can I prevent it?
> Any help is appreciated.
>
> Thanks
> Moritz
>
> [0]: https://www.lyx.org/


Hi Moritz,

Thanks for reporting the problem. From the 1st glance It looks like a
problem with SMB leases - probably a server sent a lease break and the
client didn't ack it in a timely manner.

Could you please enable debugging logging
(https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Enabling_Debugging),
reproduce the problem and send us the kernel logs? A network capture
of a repro could also be useful
(https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Wire_Captures).

--
Best regards,
Pavel Shilovsky

Re: Possible timeout problem when opening a file twice on a SMB mount

[Moritz M]

[-- Attachment #1: Type: text/plain, Size: 398 bytes --]

Hi Pavel,
> 
> 
> Could you please enable debugging logging
> (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Enabling_Debugging),
> reproduce the problem and send us the kernel logs? A network capture
> of a repro could also be useful
> (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Wire_Captures).

see the debug output and the pcap file attached.

Best regards
Moritz


[-- Attachment #2: smb_.pcapng --]
[-- Type: application/vnd.tcpdump.pcap, Size: 8653 bytes --]

[-- Attachment #3: dmesg.txt --]
[-- Type: text/plain, Size: 15847 bytes --]

[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: CIFS VFS: in cifs_revalidate_dentry_attr as Xid: 5974 with uid: 0
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: name: \lyxtest
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: Update attributes: \lyxtest inode 0x0000000076dd84e4 count 1 dentry: 0x00000000dac65130 d_time 4300248876 jiffies 4300437570
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: Getting info on \lyxtest
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: Sending smb: smb_len=332
[Mo Sep 23 14:15:39 2019] fs/cifs/connect.c: RFC1002 header 0x1d8
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 len 153
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: Calculated size 153 length 152 mismatch mid 30814
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 data length 116 offset 72
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 len 188
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: Calculated size 188 length 192 mismatch mid 30815
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: Calculated size 124 length 128 mismatch mid 30816
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2ops.c: add 3 credits total=512
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=30814 state=4
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=30815 state=4
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=30816 state=4
[Mo Sep 23 14:15:39 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:15:39 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:15:39 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 564914
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: cifs_revalidate_cache: inode 564914 is unchanged
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate_dentry_attr (xid = 5974) rc = 0
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: CIFS VFS: in cifs_atomic_open as Xid: 5975 with uid: 0
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: parent inode = 0x0000000076dd84e4 name is: foo.txt and dentry = 0x0000000050d144db
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: name: \foo.txt
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: name: \lyxtest\foo.txt
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2pdu.c: create/open
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: Sending smb: smb_len=196
[Mo Sep 23 14:15:39 2019] fs/cifs/connect.c: RFC1002 header 0x98
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 len 153
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: Calculated size 153 length 152 mismatch mid 30817
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=30817 state=4
[Mo Sep 23 14:15:39 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2pdu.c: Query Info
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: Sending smb: smb_len=108
[Mo Sep 23 14:15:39 2019] fs/cifs/connect.c: RFC1002 header 0x50
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 data length 8 offset 72
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 len 80
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=30818 state=4
[Mo Sep 23 14:15:39 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: Getting info on \lyxtest\foo.txt
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: looking for uniqueid=568378
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 568378
[Mo Sep 23 14:15:39 2019] fs/cifs/inode.c: cifs_revalidate_cache: inode 568378 is new
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2ops.c: R Lease granted on inode 000000006d274c21
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: CIFS VFS: leaving cifs_atomic_open (xid = 5975) rc = 0
[Mo Sep 23 14:15:39 2019] fs/cifs/file.c: CIFS VFS: in cifs_open as Xid: 5976 with uid: 0
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: name: \foo.txt
[Mo Sep 23 14:15:39 2019] fs/cifs/dir.c: name: \lyxtest\foo.txt
[Mo Sep 23 14:15:39 2019] fs/cifs/file.c: inode = 0x000000006d274c21 file flags are 0x8241 for \lyxtest\foo.txt
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2pdu.c: create/open
[Mo Sep 23 14:15:39 2019] fs/cifs/transport.c: Sending smb: smb_len=196
[Mo Sep 23 14:15:39 2019] fs/cifs/connect.c: RFC1002 header 0x58
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 len 88
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: Checking for oplock break
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: oplock level 0x0
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: file id match, oplock break
[Mo Sep 23 14:15:39 2019] fs/cifs/connect.c: Received oplock break
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2ops.c: None Lease granted on inode 000000006d274c21
[Mo Sep 23 14:15:39 2019] fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 5977 with uid: 0
[Mo Sep 23 14:15:39 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 5977) rc = 0
[Mo Sep 23 14:15:39 2019] fs/cifs/file.c: Oplock flush inode 000000006d274c21 rc 0
[Mo Sep 23 14:15:39 2019] fs/cifs/connect.c: RFC1002 header 0x49
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
[Mo Sep 23 14:15:39 2019] fs/cifs/smb2misc.c: SMB2 len 73
[Mo Sep 23 14:15:52 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:15:52 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:15:52 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:15:52 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:15:52 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:15:52 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:15:52 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:15:52 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:15:52 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:15:54 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:15:54 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:15:54 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:15:54 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:15:54 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:15:54 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:15:54 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:15:54 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/connect.c: RFC1002 header 0x98
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 153
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: Calculated size 153 length 152 mismatch mid 30819
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 0 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=30819 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2pdu.c: Query Info
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: Sending smb: smb_len=108
[Mo Sep 23 14:16:09 2019] fs/cifs/connect.c: RFC1002 header 0x50
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 data length 8 offset 72
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 80
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=30820 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: Getting info on \lyxtest\foo.txt
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 568378
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: cifs_revalidate_cache: inode 568378 is unchanged
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: R Lease granted on inode 000000006d274c21
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_open (xid = 5976) rc = 0
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: CIFS VFS: in cifs_setattr_nounix as Xid: 5978 with uid: 0
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: setattr on file foo.txt attrs->iavalid 0xa068
[Mo Sep 23 14:16:09 2019] fs/cifs/dir.c: name: \foo.txt
[Mo Sep 23 14:16:09 2019] fs/cifs/dir.c: name: \lyxtest\foo.txt
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2pdu.c: Flush
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: Sending smb: smb_len=92
[Mo Sep 23 14:16:09 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=30821 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: Sending smb: smb_len=108
[Mo Sep 23 14:16:09 2019] fs/cifs/connect.c: RFC1002 header 0x42
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 66
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=17 mid=30822 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: SetFSize for attrs rc = 0
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: CIFS - CTIME changed
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: Sending smb: smb_len=380
[Mo Sep 23 14:16:09 2019] fs/cifs/connect.c: RFC1002 header 0x160
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 153
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: Calculated size 153 length 152 mismatch mid 30823
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 66
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: Calculated size 66 length 72 mismatch mid 30824
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: Calculated size 124 length 128 mismatch mid 30825
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 3 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=30823 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=17 mid=30824 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=30825 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/inode.c: CIFS VFS: leaving cifs_setattr_nounix (xid = 5978) rc = 0
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 5979 with uid: 0
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 5979) rc = 0
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: Flush inode 000000006d274c21 file 00000000a2792fc7 rc 0
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: CIFS VFS: in _cifsFileInfo_put as Xid: 5980 with uid: 0
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2pdu.c: Close
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: Sending smb: smb_len=92
[Mo Sep 23 14:16:09 2019] fs/cifs/connect.c: RFC1002 header 0x7c
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=30826 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 5981 with uid: 0
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 5981) rc = 0
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: Flush inode 000000006d274c21 file 0000000017700d9b rc 0
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: closing last open instance for inode 000000006d274c21
[Mo Sep 23 14:16:09 2019] fs/cifs/file.c: CIFS VFS: in _cifsFileInfo_put as Xid: 5982 with uid: 0
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2pdu.c: Close
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: Sending smb: smb_len=92
[Mo Sep 23 14:16:09 2019] fs/cifs/connect.c: RFC1002 header 0x7c
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2misc.c: SMB2 len 124
[Mo Sep 23 14:16:09 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:09 2019] fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=30827 state=4
[Mo Sep 23 14:16:09 2019] fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
[Mo Sep 23 14:16:25 2019] fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 5983 with uid: 0
[Mo Sep 23 14:16:25 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mo Sep 23 14:16:25 2019] fs/cifs/smb2ops.c: add 64 credits total=512
[Mo Sep 23 14:16:25 2019] fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 5983) rc = 0
[Mo Sep 23 14:16:54 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:16:54 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:16:54 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:16:54 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:16:54 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:16:54 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:16:54 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:54 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:16:54 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:16:54 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:16:56 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:16:56 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:16:56 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:16:56 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:56 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:56 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2ops.c: add 1 credits total=512
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2pdu.c: In echo request
[Mo Sep 23 14:16:56 2019] fs/cifs/transport.c: Sending smb: smb_len=72
[Mo Sep 23 14:16:56 2019] fs/cifs/connect.c: RFC1002 header 0x44
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2misc.c: SMB2 len 68
[Mo Sep 23 14:16:56 2019] fs/cifs/smb2ops.c: add 1 credits total=512

Re: Possible timeout problem when opening a file twice on a SMB mount

[ronnie sahlberg]

That pcap shows a problem with the lease break.

I just tried your python reproducer with the current cifs upstream
kernel and the problem does not manifest.
There were oplock related fixes in the cifs.ko module a while ago that
might have fixed the problem you see.

Which kernel version are you using ?


On Tue, Sep 24, 2019 at 10:53 AM Moritz M <mailinglist@moritzmueller.ee> wrote:
>
> Hi Pavel,
> >
> >
> > Could you please enable debugging logging
> > (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Enabling_Debugging),
> > reproduce the problem and send us the kernel logs? A network capture
> > of a repro could also be useful
> > (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Wire_Captures).
>
> see the debug output and the pcap file attached.
>
> Best regards
> Moritz
>

Re: Possible timeout problem when opening a file twice on a SMB mount

[Pavel Shilovsky]

Thanks Moritz for providing this information.

It seems like a new long-term bug in the client code. The client
requested a lease but the server responded with a batch Oplock value
(0x9). Since the mount is SMB3.1.1 the client assumes that the server
always responds with a lease thus interprets this as a Lease State -
0x9 matches in the bit mask only a READ lease flag (0x1). Later on
when the client receives an oplock break from the server caused by the
second OPEN, it looks at the caching level which is READ and skips the
OPLOCK BREAK ACK step (according to the spec). That's why the app
hangs waiting for the oplock break to be timed out.

In order to fix it, we would need to tech the client to recognize
Oplocks on SMB3+ mounts assuming that the server may return both
Oplocks and Leases in response to CREATE command.

Ronnie, what is the version of Samba are you using? It is up to the
server to decide if Oplock or Lease is returned.

--
Best regards,
Pavel Shilovsky

вт, 24 сент. 2019 г. в 11:12, ronnie sahlberg <ronniesahlberg@gmail.com>:
>
> That pcap shows a problem with the lease break.
>
> I just tried your python reproducer with the current cifs upstream
> kernel and the problem does not manifest.
> There were oplock related fixes in the cifs.ko module a while ago that
> might have fixed the problem you see.
>
> Which kernel version are you using ?
>
>
> On Tue, Sep 24, 2019 at 10:53 AM Moritz M <mailinglist@moritzmueller.ee> wrote:
> >
> > Hi Pavel,
> > >
> > >
> > > Could you please enable debugging logging
> > > (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Enabling_Debugging),
> > > reproduce the problem and send us the kernel logs? A network capture
> > > of a repro could also be useful
> > > (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Wire_Captures).
> >
> > see the debug output and the pcap file attached.
> >
> > Best regards
> > Moritz
> >

Re: Possible timeout problem when opening a file twice on a SMB mount

[Moritz M]

Am 2019-09-24 20:11, schrieb ronnie sahlberg:
> That pcap shows a problem with the lease break.
> 
> I just tried your python reproducer with the current cifs upstream
> kernel and the problem does not manifest.
> There were oplock related fixes in the cifs.ko module a while ago that
> might have fixed the problem you see.
> 
> Which kernel version are you using ?

5.1.21-1-MANJARO with mount.cifs version: 6.8

Samba on the server side is version 4.4.16

> 
> 
> On Tue, Sep 24, 2019 at 10:53 AM Moritz M 
> <mailinglist@moritzmueller.ee> wrote:
>> 
>> Hi Pavel,
>> >
>> >
>> > Could you please enable debugging logging
>> > (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Enabling_Debugging),
>> > reproduce the problem and send us the kernel logs? A network capture
>> > of a repro could also be useful
>> > (https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Wire_Captures).
>> 
>> see the debug output and the pcap file attached.
>> 
>> Best regards
>> Moritz
>> 

Re: Possible timeout problem when opening a file twice on a SMB mount

[Pavel Shilovsky]

вт, 24 сент. 2019 г. в 12:05, Pavel Shilovsky <piastryyy@gmail.com>:
>
> Thanks Moritz for providing this information.
>
> It seems like a new long-term bug in the client code. The client
> requested a lease but the server responded with a batch Oplock value
> (0x9). Since the mount is SMB3.1.1 the client assumes that the server
> always responds with a lease thus interprets this as a Lease State -
> 0x9 matches in the bit mask only a READ lease flag (0x1). Later on
> when the client receives an oplock break from the server caused by the
> second OPEN, it looks at the caching level which is READ and skips the
> OPLOCK BREAK ACK step (according to the spec). That's why the app
> hangs waiting for the oplock break to be timed out.
>
> In order to fix it, we would need to tech the client to recognize
> Oplocks on SMB3+ mounts assuming that the server may return both
> Oplocks and Leases in response to CREATE command.
>
> Ronnie, what is the version of Samba are you using? It is up to the
> server to decide if Oplock or Lease is returned.
>

Moritz,

Could you try the following patch in your setup to see if it fixes the problem?

diff --git a/fs/cifs/smb2ops.c b/fs/cifs/smb2ops.c
index 047066493832..00d2ac80cd6e 100644
--- a/fs/cifs/smb2ops.c
+++ b/fs/cifs/smb2ops.c
@@ -3314,6 +3314,11 @@ smb21_set_oplock_level(struct cifsInodeInfo
*cinode, __u32 oplock,
        if (oplock == SMB2_OPLOCK_LEVEL_NOCHANGE)
                return;

+       /* Check if the server granted an oplock rather than a lease */
+       if (oplock & SMB2_OPLOCK_LEVEL_EXCLUSIVE)
+               return smb2_set_oplock_level(cinode, oplock, epoch,
+                                            purge_cache);
+
        if (oplock & SMB2_LEASE_READ_CACHING_HE) {
                new_oplock |= CIFS_CACHE_READ_FLG;
                strcat(message, "R");


--
Best regards,
Pavel Shilovsky

Re: Possible timeout problem when opening a file twice on a SMB mount

[Moritz M]

Thanks Pavel.
After messing around with the Kernel build procedure on my distro and
adapting the patch slightly (filenumbers did not match) I got a working
cifs module. And it solved the issue at least for the python test.

I'll check tomorrow the other software where it occured.

>> 
> Could you try the following patch in your setup to see if it fixes the 
> problem?
> 
> diff --git a/fs/cifs/smb2ops.c b/fs/cifs/smb2ops.c
> index 047066493832..00d2ac80cd6e 100644
> --- a/fs/cifs/smb2ops.c
> +++ b/fs/cifs/smb2ops.c
> @@ -3314,6 +3314,11 @@ smb21_set_oplock_level(struct cifsInodeInfo
> *cinode, __u32 oplock,
>         if (oplock == SMB2_OPLOCK_LEVEL_NOCHANGE)
>                 return;
> 
> +       /* Check if the server granted an oplock rather than a lease */
> +       if (oplock & SMB2_OPLOCK_LEVEL_EXCLUSIVE)
> +               return smb2_set_oplock_level(cinode, oplock, epoch,
> +                                            purge_cache);
> +
>         if (oplock & SMB2_LEASE_READ_CACHING_HE) {
>                 new_oplock |= CIFS_CACHE_READ_FLG;
>                 strcat(message, "R");
> 
> 
> --
> Best regards,
> Pavel Shilovsky

Re: Possible timeout problem when opening a file twice on a SMB mount

[Pavel Shilovsky]

Thanks for testing it!

Please update the thread once you verify the patch with the other
software you mentioned. If it works fine, I will prepare a formal
patch for the mainline and active stable kernels.

--
Best regards,
Pavel Shilovsky

ср, 25 сент. 2019 г. в 12:23, Moritz M <mailinglist@moritzmueller.ee>:
>
>
> Thanks Pavel.
> After messing around with the Kernel build procedure on my distro and
> adapting the patch slightly (filenumbers did not match) I got a working
> cifs module. And it solved the issue at least for the python test.
>
> I'll check tomorrow the other software where it occured.
>
> >>
> > Could you try the following patch in your setup to see if it fixes the
> > problem?
> >
> > diff --git a/fs/cifs/smb2ops.c b/fs/cifs/smb2ops.c
> > index 047066493832..00d2ac80cd6e 100644
> > --- a/fs/cifs/smb2ops.c
> > +++ b/fs/cifs/smb2ops.c
> > @@ -3314,6 +3314,11 @@ smb21_set_oplock_level(struct cifsInodeInfo
> > *cinode, __u32 oplock,
> >         if (oplock == SMB2_OPLOCK_LEVEL_NOCHANGE)
> >                 return;
> >
> > +       /* Check if the server granted an oplock rather than a lease */
> > +       if (oplock & SMB2_OPLOCK_LEVEL_EXCLUSIVE)
> > +               return smb2_set_oplock_level(cinode, oplock, epoch,
> > +                                            purge_cache);
> > +
> >         if (oplock & SMB2_LEASE_READ_CACHING_HE) {
> >                 new_oplock |= CIFS_CACHE_READ_FLG;
> >                 strcat(message, "R");
> >
> >
> > --
> > Best regards,
> > Pavel Shilovsky

Re: Possible timeout problem when opening a file twice on a SMB mount

[Moritz M]

> Please update the thread once you verify the patch with the other
> software you mentioned.

It works as expected. Issue is gone. Thanks a lot.

> If it works fine, I will prepare a formal
> patch for the mainline and active stable kernels.

As I'm not familiar with the kernel development cycle: how long will
it usually take for a patch to be included in the kernel?

Which are the active stable kernels?

Best Regards
Moritz

> ср, 25 сент. 2019 г. в 12:23, Moritz M <mailinglist@moritzmueller.ee>:
>> 
>> 
>> Thanks Pavel.
>> After messing around with the Kernel build procedure on my distro and
>> adapting the patch slightly (filenumbers did not match) I got a 
>> working
>> cifs module. And it solved the issue at least for the python test.
>> 
>> I'll check tomorrow the other software where it occured.
>> 
>> >>
>> > Could you try the following patch in your setup to see if it fixes the
>> > problem?
>> >
>> > diff --git a/fs/cifs/smb2ops.c b/fs/cifs/smb2ops.c
>> > index 047066493832..00d2ac80cd6e 100644
>> > --- a/fs/cifs/smb2ops.c
>> > +++ b/fs/cifs/smb2ops.c
>> > @@ -3314,6 +3314,11 @@ smb21_set_oplock_level(struct cifsInodeInfo
>> > *cinode, __u32 oplock,
>> >         if (oplock == SMB2_OPLOCK_LEVEL_NOCHANGE)
>> >                 return;
>> >
>> > +       /* Check if the server granted an oplock rather than a lease */
>> > +       if (oplock & SMB2_OPLOCK_LEVEL_EXCLUSIVE)
>> > +               return smb2_set_oplock_level(cinode, oplock, epoch,
>> > +                                            purge_cache);
>> > +
>> >         if (oplock & SMB2_LEASE_READ_CACHING_HE) {
>> >                 new_oplock |= CIFS_CACHE_READ_FLG;
>> >                 strcat(message, "R");
>> >
>> >
>> > --
>> > Best regards,
>> > Pavel Shilovsky

Re: Possible timeout problem when opening a file twice on a SMB mount

[Pavel Shilovsky]

чт, 26 сент. 2019 г. в 03:58, Moritz M <mailinglist@moritzmueller.ee>:
>
> > Please update the thread once you verify the patch with the other
> > software you mentioned.
>
> It works as expected. Issue is gone. Thanks a lot.

Thanks for validating the patch, I will proceed with creating a formal
patch then.

>
> > If it works fine, I will prepare a formal
> > patch for the mainline and active stable kernels.
>
> As I'm not familiar with the kernel development cycle: how long will
> it usually take for a patch to be included in the kernel?
>
> Which are the active stable kernels?

Since this is a fix not a new functionality it can be merged in the
mainline pretty quickly. It will be tagged for Stable kernels, so, it
will be automatically picked up for the stable kernels. Right now the
active stable kernels are: v4.19.x, v5.2.x and v5.3.x. The v5.1.x that
you are using doesn't receive updates any more, so, I would recommend
you to update you kernel to one of those.

--
Best regards,
Pavel Shilovsky

Re: Possible timeout problem when opening a file twice on a SMB mount

[Moritz M]

[-- 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

Re: Possible timeout problem when opening a file twice on a SMB mount

[Pavel Shilovsky]

Hi Moritz,

I think there is a difference in your setup between v5.2.21 and v5.3.7
kernels. I found the issue in oplock break processing that can happen
if you have several shares from the same server mounted on the client.
We put such shares in the list and any new share is being attached to
the beginning of the list. There is a bug in the code that causes the
client to process only the 1st share in the list skipping all the
others. I could repro it by mounting two shares in the order (test and
test2) and then doing two subsequent opens like in your original
repro. I doesn't repro if only one share is mounted for the reasons
mentioned before.

Could you test the patch to see if it works for your environment?

diff --git a/fs/cifs/smb2misc.c b/fs/cifs/smb2misc.c
index 8db6201b18ba..527c9efd3de0 100644
--- a/fs/cifs/smb2misc.c
+++ b/fs/cifs/smb2misc.c
@@ -664,10 +664,10 @@ smb2_is_valid_oplock_break(char *buffer, struct
TCP_Server_Info *server)
        spin_lock(&cifs_tcp_ses_lock);
        list_for_each(tmp, &server->smb_ses_list) {
                ses = list_entry(tmp, struct cifs_ses, smb_ses_list);
+
                list_for_each(tmp1, &ses->tcon_list) {
                        tcon = list_entry(tmp1, struct cifs_tcon, tcon_list);

-                       cifs_stats_inc(&tcon->stats.cifs_stats.num_oplock_brks);
                        spin_lock(&tcon->open_file_lock);
                        list_for_each(tmp2, &tcon->openFileList) {
                                cfile = list_entry(tmp2, struct cifsFileInfo,
@@ -679,6 +679,8 @@ smb2_is_valid_oplock_break(char *buffer, struct
TCP_Server_Info *server)
                                        continue;

                                cifs_dbg(FYI, "file id match, oplock break\n");
+                               cifs_stats_inc(
+                                   &tcon->stats.cifs_stats.num_oplock_brks);
                                cinode = CIFS_I(d_inode(cfile->dentry));
                                spin_lock(&cfile->file_info_lock);
                                if (!CIFS_CACHE_WRITE(cinode) &&
@@ -702,9 +704,6 @@ smb2_is_valid_oplock_break(char *buffer, struct
TCP_Server_Info *server)
                                return true;
                        }
                        spin_unlock(&tcon->open_file_lock);
-                       spin_unlock(&cifs_tcp_ses_lock);
-                       cifs_dbg(FYI, "No matching file for oplock break\n");
-                       return true;
                }
        }
        spin_unlock(&cifs_tcp_ses_lock);


--
Best regards,
Pavel Shilovsky

ср, 30 окт. 2019 г. в 06:26, Moritz M <mailinglist@moritzmueller.ee>:
>
> 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

Re: Possible timeout problem when opening a file twice on a SMB mount

[Moritz M]

Hi Pavel,

Am 2019-10-30 22:51, schrieb Pavel Shilovsky:
> I think there is a difference in your setup between v5.2.21 and v5.3.7
> kernels. I found the issue in oplock break processing that can happen
> if you have several shares from the same server mounted on the client.

I think you are right. Usually I mount multiple shares from one server.
It could had happened that I tested it with just one share mounted when 
using the
v5.2 Kernel.


> Could you test the patch to see if it works for your environment?

I did and it worked ;)

Thanks.

Re: Possible timeout problem when opening a file twice on a SMB mount

[Pavel Shilovsky]

чт, 31 окт. 2019 г. в 02:20, Moritz M <mailinglist@moritzmueller.ee>:
>
> Hi Pavel,
>
> Am 2019-10-30 22:51, schrieb Pavel Shilovsky:
> > I think there is a difference in your setup between v5.2.21 and v5.3.7
> > kernels. I found the issue in oplock break processing that can happen
> > if you have several shares from the same server mounted on the client.
>
> I think you are right. Usually I mount multiple shares from one server.
> It could had happened that I tested it with just one share mounted when
> using the
> v5.2 Kernel.
>
>
> > Could you test the patch to see if it works for your environment?
>
> I did and it worked ;)
>
> Thanks.

Thanks for verifying the fix! I will post the patch to the list soon.

--
Best regards,
Pavel Shilovsky