[Bug 245688] Nullfs doesn't send release for a file read with 'cat' command (while mounted over a FUSE fs).

Fri Apr 17 10:12:51 UTC 2020

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=245688

            Bug ID: 245688
           Summary: Nullfs doesn't send release for a file read with 'cat'
                    command (while mounted over a FUSE fs).
           Product: Base System
           Version: 12.1-RELEASE
          Hardware: amd64
                OS: Any
            Status: New
          Severity: Affects Some People
          Priority: ---
         Component: kern
          Assignee: bugs at FreeBSD.org
          Reporter: freebsd at moosefs.pro

Scenario:

There is a MooseFS (via FUSE ver 3) filesystem mounted on a FreeBSD 12.1-p2.
There is nullfs mounted over the MooseFS (nullfs is used for jails). We perform
the following operations:

1) Read a file (using "cat [path/filename]") directly on MooseFS and no nullfs
mounted at all:

03.26 15:10:08.014666: uid:0 gid:0 pid:4252 cmd:access (1,0x1): OK
03.26 15:10:08.015150: uid:0 gid:0 pid:4252 cmd:lookup (1,opentest): OK
(1.0,1670,1.0,[drwxr-xr-x:0040755,2,0,0,1585231804,1585231099,1585231099,77100])
03.26 15:10:08.015191: uid:0 gid:0 pid:4252 cmd:access (1670,0x1): OK
03.26 15:10:08.015791: uid:0 gid:0 pid:4252 cmd:lookup (1670,test.sh): OK
(0.0,49302,1.0,[-rwxr-xr-x:0100755,1,0,0,1585231653,1585230529,1585230533,771])
03.26 15:10:08.015825: uid:0 gid:0 pid:4252 cmd:access (49302,0x4): OK
03.26 15:10:08.016033: uid:0 gid:0 pid:4252 cmd:open (49302) (using cached data
from lookup): OK (direct_io:0,keep_cache:0) [handle:0400000C]
03.26 15:10:08.017385: uid:0 gid:0 pid:4252 cmd:read (49302,771,0)
[handle:0400000C]: OK (771)
03.26 15:10:08.017645: uid:0 gid:0 pid:4252 cmd:flush (49302)
[handle:0400000C,uselocks:0,lock_owner:000000000000109C]: OK
03.26 15:10:08.017866: uid:0 gid:0 pid:4252 cmd:release (49302)
[handle:0400000C,uselocks:0,lock_owner:000000000000109C]: OK

2) Read the same file directly on MooseFS with nullfs already mounted:

03.26 15:11:11.219917: uid:0 gid:0 pid:4266 cmd:access (1,0x1): OK
03.26 15:11:11.220632: uid:0 gid:0 pid:4266 cmd:lookup (1,opentest): OK
(1.0,1670,1.0,[drwxr-xr-x:0040755,2,0,0,1585231804,1585231099,1585231099,77100])
03.26 15:11:11.220689: uid:0 gid:0 pid:4266 cmd:access (1670,0x1): OK
03.26 15:11:11.221475: uid:0 gid:0 pid:4266 cmd:lookup (1670,test.sh): OK
(0.0,49302,1.0,[-rwxr-xr-x:0100755,1,0,0,1585231808,1585230529,1585230533,771])
03.26 15:11:11.221511: uid:0 gid:0 pid:4266 cmd:access (49302,0x4): OK
03.26 15:11:11.221749: uid:0 gid:0 pid:4266 cmd:open (49302) (using cached data
from lookup): OK (direct_io:0,keep_cache:0) [handle:0500000C]
03.26 15:11:11.223064: uid:0 gid:0 pid:4266 cmd:read (49302,771,0)
[handle:0500000C]: OK (771)
03.26 15:11:11.223348: uid:0 gid:0 pid:4266 cmd:flush (49302)
[handle:0500000C,uselocks:0,lock_owner:00000000000010AA]: OK
03.26 15:11:11.223582: uid:0 gid:0 pid:4266 cmd:release (49302)
[handle:0500000C,uselocks:0,lock_owner:00000000000010AA]: OK

3) Read the same file via nullfs mount:

03.26 15:11:26.925276: uid:0 gid:0 pid:4105 cmd:access (1670,0x1): OK
03.26 15:11:26.925315: uid:0 gid:0 pid:4105 cmd:lookup (1670,test.sh) (using
open dir cache): OK
(0.0,49302,1.0,[-rwxr-xr-x:0100755,1,0,0,1585231871,1585230529,1585230533,771])
03.26 15:11:27.507740: uid:0 gid:0 pid:4267 cmd:access (1670,0x1): OK
03.26 15:11:27.508235: uid:0 gid:0 pid:4267 cmd:lookup (1670,test.sh): OK
(0.0,49302,1.0,[-rwxr-xr-x:0100755,1,0,0,1585231871,1585230529,1585230533,771])
03.26 15:11:27.508377: uid:0 gid:0 pid:4267 cmd:access (49302,0x4): OK
03.26 15:11:27.508656: uid:0 gid:0 pid:4267 cmd:open (49302) (using cached data
from lookup): OK (direct_io:0,keep_cache:0) [handle:0600000C]
03.26 15:11:27.510012: uid:0 gid:0 pid:4267 cmd:read (49302,771,0)
[handle:0600000C]: OK (771)
03.26 15:11:27.510273: uid:0 gid:0 pid:4267 cmd:flush (49302)
[handle:0600000C,uselocks:0,lock_owner:00000000000010AB]: OK

*There is no release after flush!*

4) Read the same file again directly on MooseFS:

03.26 15:11:35.955262: uid:0 gid:0 pid:4268 cmd:access (1,0x1): OK
03.26 15:11:35.955730: uid:0 gid:0 pid:4268 cmd:lookup (1,opentest): OK
(1.0,1670,1.0,[drwxr-xr-x:0040755,2,0,0,1585231886,1585231099,1585231099,77100])
03.26 15:11:35.955771: uid:0 gid:0 pid:4268 cmd:access (1670,0x1): OK
03.26 15:11:35.956399: uid:0 gid:0 pid:4268 cmd:lookup (1670,test.sh): OK
(0.0,49302,1.0,[-rwxr-xr-x:0100755,1,0,0,1585231887,1585230529,1585230533,771])
03.26 15:11:35.956432: uid:0 gid:0 pid:4268 cmd:access (49302,0x4): OK
03.26 15:11:35.956692: uid:0 gid:0 pid:4268 cmd:open (49302) (using cached data
from lookup): OK (direct_io:0,keep_cache:0) [handle:03000008]
03.26 15:11:35.957949: uid:0 gid:0 pid:4268 cmd:read (49302,771,0)
[handle:03000008]: OK (771)
03.26 15:11:35.958217: uid:0 gid:0 pid:4268 cmd:flush (49302)
[handle:03000008,uselocks:0,lock_owner:00000000000010AC]: OK

*Still no release!*

So it looks like the first time the file is read via nullfs, the kernel no
longer sends release to the filesystem, so the filesystem keeps the file open.
When you perform a lot of reads on files this way, eventually you'll run out of
file descriptors...

Now, since the underlying filesystem is a FUSE filesystem, we don't know "who
is at fault here" and is neglecting to send the release, but it's either nullfs
itself or for some reason FUSE is doing it when the operations come from
nullfs. The operations listed are what actually reaches the filesystem on the
other side of FUSE.

-- 
You are receiving this mail because:
You are the assignee for the bug.