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

[Pavel Shilovsky <piastryyy@gmail.com>]

пт, 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