I would expect the close unmatched open to be related to the session
being closed (thus all files implicitly closed on the server) but the
session drop overlapping the application closing a file.
On Fri, May 1, 2020 at 2:39 PM Scott M. Lewandowski
<vgerkernel@xxxxxxxxxx> wrote:
>
> I've now got a trace that corresponds to the dmesg output below. I will take a look later, but upon quick glance, this doesn't look like anything that will mean much to me, unfortunately. If someone would like to look at the file I can find a way to get it to you.
>
>
> [53223.099221] CIFS VFS: Send error in read = -4
> [53223.232373] CIFS VFS: Send error in read = -4
> [53254.762914] CIFS VFS: Send error in read = -4
> [53301.403925] CIFS VFS: Send error in read = -4
> [53301.772568] CIFS VFS: Send error in read = -4
> [53301.818566] CIFS VFS: Send error in read = -4
> [53301.885510] CIFS VFS: Send error in read = -4
> [53302.055959] CIFS VFS: Send error in read = -4
> [53302.146337] CIFS VFS: Send error in read = -4
> [53302.236322] CIFS VFS: Send error in read = -4
> [53302.329525] CIFS VFS: Send error in read = -4
> [53303.000869] CIFS VFS: Send error in read = -4
> [53303.106961] CIFS VFS: Send error in read = -4
> [53304.756998] CIFS VFS: Close unmatched open
> [53670.776832] CIFS VFS: Close unmatched open
>
>
> > -----Original Message-----
> > From: Steve French <smfrench@xxxxxxxxx>
> > Sent: Friday, May 1, 2020 10:57 AM
> > To: Scott M. Lewandowski <vgerkernel@xxxxxxxxxx>
> > Cc: Scott M. Lewandowski <scott@xxxxxxxxxxxxxxxxx>; CIFS <linux-
> > cifs@xxxxxxxxxxxxxxx>
> > Subject: Re: issues with CIFS on Ubuntu 20 mounting Windows 2019
> >
> > Are you comfortable with dynamic tracing ("trace-cmd record -e ..."
> > ... the list of trace points can be seen in
> > /sys/kernel/debug/tracing/events/cifs)?
> >
> > On Fri, May 1, 2020 at 10:40 AM Scott M. Lewandowski
> > <vgerkernel@xxxxxxxxxx> wrote:
> > >
> > > I’m also seeing entries like the following mixed in with the other messages:
> > >
> > > [27078.665192] CIFS VFS: \\file1 Cancelling wait for mid 13443257 cmd:
> > > 5
> > >
> > > And
> > >
> > > [31833.351785] CIFS VFS: cifs_invalidate_mapping: could not invalidate
> > > inode 00000000b4733e96
> > >
> > >
> > >
> > >
> > > > -----Original Message-----
> > > > From: Scott M. Lewandowski <vgerkernel@xxxxxxxxxx>
> > > > Sent: Friday, May 1, 2020 12:20 AM
> > > > To: 'Steve French' <smfrench@xxxxxxxxx>
> > > > Cc: CIFS <linux-cifs@xxxxxxxxxxxxxxx>
> > > > Subject: RE: issues with CIFS on Ubuntu 20 mounting Windows 2019
> > > >
> > > > > EINTR on read ... Hundreds of times?! I have seen scp do that by
> > > > > sending signals but in writes not reads
> > > >
> > > > Not using scp at the moment.
> > > >
> > > > > Could an app be sending signals trying to kill the process doing the
> > reads?
> > > >
> > > > Not that I'm aware of. I'm not sure exactly how I'd check that, but
> > > > I will look into it.
> > > >
> > > > One other thing that came to mind that may be helpful is that one of
> > > > the processes doing the most IO is running under mono 6.8.0.105
> > > >
> > > > -scott
> > > >
> > > >
> > > >
> > > >
> > > > From: Steve French <smfrench@xxxxxxxxx>
> > > > Sent: Friday, May 1, 2020 12:07 AM
> > > > To: Scott M. Lewandowski <vgerkernel@xxxxxxxxxx>
> > > > Cc: CIFS <linux-cifs@xxxxxxxxxxxxxxx>
> > > > Subject: Re: issues with CIFS on Ubuntu 20 mounting Windows 2019
> > > >
> > > > EINTR on read ... Hundreds of times?! I have seen scp do that by
> > > > sending signals but in writes not reads
> > > >
> > > > On Thu, Apr 30, 2020, 23:48 Scott M. Lewandowski
> > > > <mailto:vgerkernel@xxxxxxxxxx> wrote:
> > > > I have an Ubuntu 20.04 box mounting shares from a Windows 2019
> > server.
> > > > Both boxes are fully patched. They are resident on the same
> > > > hypervisor and communicating directly via a vSwitch. I have 4 shares
> > > > mounted; here is an example from my fstab (yes, I know I should move
> > the credential file):
> > > >
> > > > //file1/usenet /mnt/usenet cifs
> > > > vers=3.0,uid=scott,credentials=/home/scott/.smbcredentials,noserveri
> > > > no,n
> > > > ounix,iocharset=utf8 0 0
> > > >
> > > > My kernel is 5.4.0-28-generic and mount.cifs version is 6.9. The
> > > > contents of DebugData are included below.
> > > >
> > > > Right after the mount, I see a duplicate cookie reported. It is
> > > > unclear if this is a problem or not. Following that, I periodically
> > > > see messages similar to the following repeated in dmesg:
> > > >
> > > > [ 179.625296] SMB2_read: 9 callbacks suppressed [ 179.625298] CIFS VFS:
> > > > Send error in read = -4 [ 179.704191] CIFS VFS: Send error in read
> > > > = -4 [ 179.847514] CIFS VFS: Send error in read = -4 [ 180.031516]
> > > > CIFS VFS: Send error in read = -4 [ 180.214848] CIFS VFS: Send
> > > > error in read = -4 [ 180.282909] CIFS VFS: Send error in read = -4
> > > > [ 180.474829] CIFS VFS: Send error in read = -4 [ 180.621349] CIFS
> > > > VFS: Send error in read = -4 [ 180.780465] CIFS VFS: Send error in
> > > > read = -4 [ 180.823249] CIFS VFS: Send error in read = -4 [
> > > > 182.339351] CIFS VFS: Close unmatched open [ 182.726829] CIFS VFS:
> > > > Close unmatched open [ 184.292663] CIFS VFS: Close unmatched open [
> > > > 184.501185] CIFS VFS: Close unmatched open [ 191.784922] SMB2_read:
> > 4 callbacks suppressed [ 191.784925] CIFS VFS:
> > > > Send error in read = -4 [ 191.884186] CIFS VFS: Send error in read
> > > > = -4 [ 192.270851] CIFS VFS: Send error in read = -4 [ 192.323467]
> > > > CIFS VFS: Send error in read = -4 [ 192.381336] CIFS VFS: Send
> > > > error in read = -4 [ 192.446711] CIFS VFS: Send error in read = -4
> > > > [ 192.507605] CIFS VFS: Send error in read = -4 [ 193.244397] CIFS
> > > > VFS: Send error in read = -4 [ 193.307588] CIFS VFS: Send error in
> > > > read = -4 [ 193.403410] CIFS VFS: Send error in read = -4 [
> > > > 193.797038] CIFS VFS: Close unmatched open [ 196.784082] CIFS VFS:
> > > > Close unmatched open [ 198.247594] CIFS VFS: Close unmatched open
> > > >
> > > > Here is the duplicate cookie info:
> > > >
> > > > [ 21.713307] FS-Cache: Duplicate cookie detected [ 21.713840] FS-
> > Cache: O-
> > > > cookie c=00000000e8276279 [p=0000000079ef0365 fl=222 nc=0 na=1]
> > > > [ 21.714330] FS-Cache: O-cookie d=00000000173ea0ee
> > n=00000000243f210c
> > > > [ 21.714779] FS-Cache: O-key=[8] '020001bdc0a801af'
> > > > [ 21.715219] FS-Cache: N-cookie c=00000000afb49d9c
> > [p=0000000079ef0365
> > > > fl=2 nc=0 na=1] [ 21.715672] FS-Cache: N-cookie d=00000000173ea0ee
> > > > n=00000000dd1465c5 [ 21.716141] FS-Cache: N-key=[8]
> > '020001bdc0a801af'
> > > > [ 21.716591] FS-Cache: Duplicate cookie detected [ 21.717217] FS-
> > Cache: O-
> > > > cookie c=00000000e8276279 [p=0000000079ef0365 fl=222 nc=0 na=1]
> > > > [ 21.717679] FS-Cache: O-cookie d=00000000173ea0ee
> > n=00000000243f210c
> > > > [ 21.718220] FS-Cache: O-key=[8] '020001bdc0a801af'
> > > > [ 21.718681] FS-Cache: N-cookie c=0000000063665cf7
> > [p=0000000079ef0365
> > > > fl=2 nc=0 na=1] [ 21.719166] FS-Cache: N-cookie d=00000000173ea0ee
> > > > n=00000000e757f917 [ 21.719621] FS-Cache: N-key=[8]
> > '020001bdc0a801af'
> > > > [ 21.720097] FS-Cache: Duplicate cookie detected [ 21.720565] FS-
> > Cache: O-
> > > > cookie c=00000000e8276279 [p=0000000079ef0365 fl=222 nc=0 na=1]
> > > > [ 21.721053] FS-Cache: O-cookie d=00000000173ea0ee
> > n=00000000243f210c
> > > > [ 21.721518] FS-Cache: O-key=[8] '020001bdc0a801af'
> > > > [ 21.721994] FS-Cache: N-cookie c=00000000d479c294
> > [p=0000000079ef0365
> > > > fl=2 nc=0 na=1] [ 21.722476] FS-Cache: N-cookie d=00000000173ea0ee
> > > > n=00000000ca1891fa [ 21.722941] FS-Cache: N-key=[8]
> > '020001bdc0a801af'
> > > >
> > > > Any ideas what could be going on?
> > > >
> > > > Thanks for any help!
> > > >
> > > >
> > > >
> > > >
> > > >
> > > >
> > > > DebugData:
> > > > CIFS Version 2.23
> > > > Features:
> > > >
> > DFS,FSCACHE,STATS,DEBUG,ALLOW_INSECURE_LEGACY,WEAK_PW_HASH,C
> > > > IFS_POSIX,UPCALL(SPNEGO),XATTR,ACL
> > > > CIFSMaxBufSize: 16384
> > > > Active VFS Requests: 0
> > > > Servers:
> > > > Number of credits: 8190 Dialect 0x300
> > > > 1) Name: 192.168.1.175 Uses: 1 Capability: 0x300067 Session Status: 1
> > TCP
> > > > status: 1 Instance: 1
> > > > Local Users To Server: 1 SecMode: 0x1 Req On Wire: 0 SessionId:
> > > > 0x100080000021
> > > > Shares:
> > > > 0) IPC: \\file1\IPC$ Mounts: 1 DevInfo: 0x0 Attributes: 0x0
> > > > PathComponentMax: 0 Status: 1 type: 0 Serial Number: 0x0
> > > > Share Capabilities: None Share Flags: 0x30
> > > > tid: 0x1 Maximal Access: 0x11f01ff
> > > >
> > > > 1) \\file1\XXX Mounts: 1 DevInfo: 0x20020 Attributes: 0x8500df
> > > > PathComponentMax: 255 Status: 1 type: DISK Serial Number:
> > 0xa3c339a0
> > > > Share Capabilities: None Aligned, Partition Aligned, Share Flags: 0x0
> > > > tid: 0x5 Optimal sector size: 0x200 Maximal Access: 0x1f01ff
> > > >
> > > > MIDs:
> > > >
> > > > Server interfaces: 2
> > > > 0) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv6: fe80:0000:0000:0000:71cb:1839:1069:9806
> > > > 1) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv4: 192.168.1.175
> > > > Number of credits: 8190 Dialect 0x300
> > > >
> > > > 2) Name: 192.168.1.175 Uses: 1 Capability: 0x300067 Session Status: 1
> > TCP
> > > > status: 1 Instance: 1
> > > > Local Users To Server: 1 SecMode: 0x1 Req On Wire: 0 SessionId:
> > > > 0x10006c000019
> > > > Shares:
> > > > 0) IPC: \\file1\IPC$ Mounts: 1 DevInfo: 0x0 Attributes: 0x0
> > > > PathComponentMax: 0 Status: 1 type: 0 Serial Number: 0x0
> > > > Share Capabilities: None Share Flags: 0x30
> > > > tid: 0x1 Maximal Access: 0x11f01ff
> > > >
> > > > 1) \\file1\usenet Mounts: 1 DevInfo: 0x20020 Attributes: 0x8500df
> > > > PathComponentMax: 255 Status: 1 type: DISK Serial Number:
> > 0xa3c339a0
> > > > Share Capabilities: None Aligned, Partition Aligned, Share Flags: 0x0
> > > > tid: 0x5 Optimal sector size: 0x200 Maximal Access: 0x1f01ff
> > > >
> > > > MIDs:
> > > >
> > > > Server interfaces: 2
> > > > 0) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv6: fe80:0000:0000:0000:71cb:1839:1069:9806
> > > > 1) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv4: 192.168.1.175
> > > >
> > > >
> > > > 3) Name: 192.168.1.175 Uses: 1 Capability: 0x300067 Session Status: 1
> > TCP
> > > > status: 1 Instance: 1
> > > > Local Users To Server: 1 SecMode: 0x1 Req On Wire: 2 SessionId:
> > > > 0x10007c000061
> > > > Shares:
> > > > 0) IPC: \\file1\IPC$ Mounts: 1 DevInfo: 0x0 Attributes: 0x0
> > > > PathComponentMax: 0 Status: 1 type: 0 Serial Number: 0x0
> > > > Share Capabilities: None Share Flags: 0x30
> > > > tid: 0x1 Maximal Access: 0x11f01ff
> > > >
> > > > 1) \\file1\YYY Mounts: 1 DevInfo: 0x20020 Attributes: 0x8500df
> > > > PathComponentMax: 255 Status: 1 type: DISK Serial Number:
> > 0xa3c339a0
> > > > Share Capabilities: None Aligned, Partition Aligned, Share Flags: 0x0
> > > > tid: 0x5 Optimal sector size: 0x200 Maximal Access: 0x1f01ff
> > > >
> > > > MIDs:
> > > > State: 2 com: 8 pid: 1218 cbdata: 00000000e45c59d2 mid 1211489
> > > > State: 2 com: 8 pid: 1218 cbdata: 0000000018476195 mid
> > > > 1211553
> > > >
> > > > Server interfaces: 2
> > > > 0) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv6: fe80:0000:0000:0000:71cb:1839:1069:9806
> > > > 1) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv4: 192.168.1.175
> > > >
> > > > Number of credits: 8190 Dialect 0x300
> > > > 4) Name: 192.168.1.175 Uses: 1 Capability: 0x300067 Session Status: 1
> > TCP
> > > > status: 1 Instance: 1
> > > > Local Users To Server: 1 SecMode: 0x1 Req On Wire: 0 SessionId:
> > > > 0x10006c000055
> > > > Shares:
> > > > 0) IPC: \\file1\IPC$ Mounts: 1 DevInfo: 0x0 Attributes: 0x0
> > > > PathComponentMax: 0 Status: 1 type: 0 Serial Number: 0x0
> > > > Share Capabilities: None Share Flags: 0x30
> > > > tid: 0x1 Maximal Access: 0x11f01ff
> > > >
> > > > 1) \\file1\ZZZ Mounts: 1 DevInfo: 0x20020 Attributes: 0x8500df
> > > > PathComponentMax: 255 Status: 1 type: DISK Serial Number:
> > 0xa3c339a0
> > > > Share Capabilities: None Aligned, Partition Aligned, Share Flags: 0x0
> > > > tid: 0x5 Optimal sector size: 0x200 Maximal Access: 0x1f01ff
> > > >
> > > > MIDs:
> > > >
> > > > Server interfaces: 2
> > > > 0) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv6: fe80:0000:0000:0000:71cb:1839:1069:9806
> > > > 1) Speed: 10000000000 bps
> > > > Capabilities:
> > > > IPv4: 192.168.1.175
> >
> >
> >
> > --
> > Thanks,
> >
> > Steve
--
Thanks,
Steve
