Co-author: navytux

Thanks to rfjakob for general feedback.

Next:
- add refctr like libfuse. Use it to implement persistent nodes 

TODO
- context for PID/caller
- Opendir

Open questions: grep for NOSUBMIT/TODO
- how many interfaces?
- explode SetAttr ?

In practice, this only triggers for RENAME_EXCHANGE, as the kernel
issues the RENAME opcode in case of a normal rename or a
RENAME_NOREPLACE.

We have always advertised rename2 support (protocol v23), but it returned
ENOSYS always. Instead, rename RenameIn => Rename1In, and add Flags to
RenameIn.

For raw filesystems that want to support rename2 should examine
RenameIn.Flags and check for syscall.RENAME_XXX.

For fuse/nodefs, we return ENOSYS in case of Rename2, since we lack
API surface to propagate the flags.

It is currently failing. Reported as
https://github.com/libfuse/libfuse/issues/362

After Linux VFS was enhanced to be able to do several lookups and
readdirs in parallel, FUSE client in Linux, in fear to break existing
filesystems, explicitly reverted it back to be serial in FUSE exchange
and requested filesystems to indicate via CAP_PARALLEL_DIROPS flag that
the filesystem server is ready to handle parallel lookup and readdir
requests.

	https://git.kernel.org/linus/5c672ab3f0

We should be ready to handle and we provide MountOptions.SingleThreaded
for those filesystems, which are not ready to handle requests in
parallel.

The first 3 are present since

CAP_ABORT_ERROR is present since Linux 4.17:

	https://git.kernel.org/linus/3b7008b226

CAP_MAX_PAGES & CAP_CACHE_SYMLINKS are present since Linux 4.20:

	https://git.kernel.org/linus/5da784cce4
	https://git.kernel.org/linus/5571f1e654

CAP_NO_OPENDIR_SUPPORT will be present in Linux 5.1:

	https://git.kernel.org/pub/scm/linux/kernel/git/mszeredi/fuse.git/commit?id=d9a9ea94f7

- They were printed with CAP_ prefix, whereas other CAP_* are printed
  without that prefix;
- CAP_HANDLE_KILLPRIV was printed as "CAP_PARALLEL_DIROPS".

There was a typo, seemingly, because in linux/fuse.h these constants are
defined as

	#define FUSE_HANDLE_KILLPRIV	(1 << 19)
	#define FUSE_POSIX_ACL		(1 << 20)

(https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/include/uapi/linux/fuse.h?id=v5.0-rc6-46-gcb5b020a8d38#n282)

It turned out that:

1. Linux kernel cannot send data in chunks bigger than what was
   configured as MaxWrite on init, and

2. if we ask for more, and that more, after capping to kernel write
   maxium, is more than configured MaxWrite, the kernel will simply drop
   NOTIFY_REPLY message. This, hopefully, will be fixed

	https://marc.info/?l=linux-fsdevel&m=155000277921155&w=2

   but we cannot count on this fix to be present on older kernels, and
   even if it is there, we still won't get more than MaxWrite data.

-> Rework InodeRetrieveCache to retrieve the data in chunks.

NOTE1: we do not load users with this FUSE exchange details and instead
of returning less content than requested, try to retrieve it all.

NOTE2: without changes to fuse/server.go, added test will get stuck (see
details in above link to linux-fsdevel patch).

For example

	15:12:42.711011 tx 0: NOTIFY_INVAL_ENTRY, {parent i1 sz 8} "file.txt"

instead of

	15:12:42.711011 tx 0: NOTIFY_INVAL_ENTRY, {parent 1 sz 8} "file.txt"

using iX fits into our general logging scheme and makes logs more
self-descriptive.

Test that READDIR works even if the directory is renamed after the OPENDIR.
This checks that the fix for https://github.com/hanwen/go-fuse/issues/252
does not break this case.

Without patch "nodefs: delay directory read till ReadDir":

	go-fuse/fuse/test$ go test
	13:56:23.932743 Unimplemented opcode INTERRUPT
	13:56:23.932902 writer: Write/Writev failed, err: 2=no such file or directory. opcode: INTERRUPT
	--- FAIL: TestReaddir (0.02s)
	    loopback_test.go:578: Wrong number of directory entries: want=2 have=1
	FAIL
	exit status 1
	FAIL	github.com/hanwen/go-fuse/fuse/test	1.970s

With patch "nodefs: delay directory read till ReadDir":

	go-fuse/fuse/test$ go test
	13:57:03.848021 Unimplemented opcode INTERRUPT
	13:57:03.848159 writer: Write/Writev failed, err: 2=no such file or directory. opcode: INTERRUPT
	PASS
	ok  	github.com/hanwen/go-fuse/fuse/test	1.960s

https://github.com/hanwen/go-fuse/issues/252

We used to read the directory already on OpenDir, which means that
we missed changes in the directory between a user's open() and
readdir() call.

https://github.com/hanwen/go-fuse/issues/252

For all operations that can be applied on file descriptors, we have
special treatment to permit the File to be nil. In that case, operations
are called against the Node object instead.

This check currently seems missing from SetAttr(), causing invocations
of the truncate(1) command line tool to cause a crash:

        panic: runtime error: invalid memory address or nil pointer dereference
        [signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0xa30d0d]

        goroutine 12 [running]:
        github.com/hanwen/go-fuse/fuse/nodefs.(*rawBridge).SetAttr(0xc00013ecc0, 0xc0003a8000, 0xc0003ba0f0, 0xa27b98)
                external/com_github_hanwen_go_fuse/fuse/nodefs/fsops.go:203 +0x58d
        github.com/hanwen/go-fuse/fuse.doSetattr(0xc0003a4000, 0xc0003ba000)
                external/com_github_hanwen_go_fuse/fuse/opcode.go:171 +0x64
        github.com/hanwen/go-fuse/fuse.(*Server).handleRequest(0xc0003a4000, 0xc0003ba000, 0xc0003ba000)
                external/com_github_hanwen_go_fuse/fuse/server.go:431 +0x26b
        github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0003a4000, 0xc00000b101)
                external/com_github_hanwen_go_fuse/fuse/server.go:403 +0x18f
        created by github.com/hanwen/go-fuse/fuse.(*Server).readRequest
                external/com_github_hanwen_go_fuse/fuse/server.go:291 +0x2d8

Add a lock that prevents LOOKUP and FORGET from running concurrently.

Locking at this level is a big hammer, but makes sure we don't return
forgotten nodes to the kernel. Problems solved by this lock:

https://github.com/hanwen/go-fuse/issues/168
https://github.com/rfjakob/gocryptfs/issues/322

Helps to track where things went wrong when looking at debug
logs.

- casting fuse.AttrOut.Attr to fuse.Attr is noop
- casting fileSystemMount.options.Owner to fuse.Owner is noop
- casting fuse.ReadIn.Context to fuse.Context is noop

The timed cache expires after some time, so if the test ran slowly, we
cannot reliably test the cache's functionality.

Fixes a race condition.

Node numbers are now written as "i1234" everywhere except in the
BATCH_FORGET output, fix that. Also show the transaction number
so we can follow where each forget comes from.

As a normal FORGET looks like this:

	2019/01/27 14:38:07 rx 1488: FORGET i822 {Nlookup=1}

with the new output, "grep FORGET i1234 " will catch both single forgets
and batch forgets.

Before:

	2019/01/20 18:15:31 rx 1372: BATCH_FORGET i0 {Count=3}  48b
	2019/01/20 18:15:31 doBatchForget: forgetting 1 of 3: NodeId: 40, Nlookup: 1
	2019/01/20 18:15:31 doBatchForget: forgetting 2 of 3: NodeId: 41, Nlookup: 1
	2019/01/20 18:15:31 doBatchForget: forgetting 3 of 3: NodeId: 42, Nlookup: 1

After:

	2019/01/27 14:48:35 rx 2982: BATCH_FORGET i0 {Count=2}  32b
	2019/01/27 14:48:35 doBatchForget: rx 2982 1/2: FORGET i804 {Nlookup=1}
	2019/01/27 14:48:35 doBatchForget: rx 2982 2/2: FORGET i803 {Nlookup=1}

Since https://git.kernel.org/linus/7678ac5061 FUSE filesystems were allowed to
return ENOSYS from open and, open seeing this, the kernel will not send any
open request anymore and just use Fh=0 for all opened files. This is handy for
filesystems that don't have any per-opened-file state.

However if there is at least one node for which opened files should have
their own state, it is not correct to return ENOSYS from open _ever_, as that
would prevent the kernel to call open on all nodes - in particular on the node
where open needs to create a state associated with the file handle(*).

It is already explicitly documented that Node.Open can return File=nil
in which case filesystem operations like Read and Write will be called
on the node directly. This way a filesystem could try to simulate an
Open that was returning ENOSYS with Open that returns File=nil. However
it is not the same as ENOSYS open also prevents the kernel from dropping
the file cache:

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/fs/fuse/file.c?id=v5.0-rc3-241-g7c2614bf7a1f#n131

From this point of view Opens that were returning ENOSYS should be
replaced with Open that returns WithFlags{File=nil, flags=FOPEN_KEEP_CACHE}.

Unfortunately if one tries to do that, go-fuse segfaults as the test
included in this patch demonstrates:

	13:36:53.238706 rx 13: LOOKUP i1 ["world.txt"] 10b
	13:36:53.238745 tx 13:     OK, {i4 g3 tE=1s tA=1s {M0100644 SZ=5 L=1 1000:1000 B0*0 i0:4 A 0.000000 M 0.000000 C 0.000000}}
	13:36:53.238780 rx 14: OPEN i4 {O_RDONLY,0x8000}
	13:36:53.238791 tx 14:     OK, {Fh 2 CACHE}				<-- NOTE Fh != 0
	13:36:53.238706 rx 12: RELEASE i3 {Fh 0 NONBLOCK,0x8000  L0}
	13:36:53.238804 tx 12:     OK
	13:36:53.238823 rx 15: READ i4 {Fh 2 [0 +4096)  L 0 NONBLOCK,0x8000}
	13:36:53.238830 tx 15:     OK,  5b data "world"
	13:36:53.238846 rx 16: GETATTR i4 {Fh 2}
	13:36:53.238865 tx 16:     OK, {tA=1s {M0100644 SZ=5 L=1 1000:1000 B0*0 i0:4 A 0.000000 M 0.000000 C 0.000000}}
	13:36:53.238879 rx 17: FLUSH i4 {Fh 2}
	panic: runtime error: invalid memory address or nil pointer dereference
	[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x539f9f]

	goroutine 6 [running]:
	github.com/hanwen/go-fuse/fuse/nodefs.(*rawBridge).Flush(0xc000010960, 0xc000104180, 0x0)
	        /home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/nodefs/fsops.go:490 +0x6f
	github.com/hanwen/go-fuse/fuse.doFlush(0xc0000de000, 0xc000104000)
	        /home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/opcode.go:373 +0x42
	github.com/hanwen/go-fuse/fuse.(*Server).handleRequest(0xc0000de000, 0xc000104000, 0xc000104000)
	        /home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:431 +0x26b
	github.com/hanwen/go-fuse/fuse.(*Server).loop(0xc0000de000, 0x0)
	        /home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:403 +0x18f
	github.com/hanwen/go-fuse/fuse.(*Server).Serve(0xc0000de000)
	        /home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/server.go:331 +0x6d
	created by github.com/hanwen/go-fuse/fuse/test.TestNoFile
	        /home/kirr/src/neo/src/github.com/hanwen/go-fuse/fuse/test/nofile_test.go:73 +0x442

Fix it by teaching registerFileHandle not to register any handle at all
and return Fh=0, if the inner file (file itself, or the file that was wrapped
with WithFlags) is nil.

After the patch the trace for world.txt open/read (that is opened with
WithFlags{File=nil, Flags=FOPEN_KEEP_CACHE} is as follows.

	14:59:31.714048 rx 13: LOOKUP i1 ["world.txt"] 10b
	14:59:31.714062 tx 13:     OK, {i4 g3 tE=1s tA=1s {M0100644 SZ=5 L=1 1000:1000 B0*0 i0:4 A 0.000000 M 0.000000 C 0.000000}}
	14:59:31.714081 rx 14: OPEN i4 {O_RDONLY,0x8000}
	14:59:31.714091 tx 14:     OK, {Fh 0 CACHE}				<-- NOTE Fh = 0
	14:59:31.714123 rx 15: READ i4 {Fh 0 [0 +4096)  L 0 NONBLOCK,0x8000}
	14:59:31.714132 tx 15:     OK,  5b data "world"
	14:59:31.714150 rx 16: GETATTR i4 {Fh 0}
	14:59:31.714159 tx 16:     OK, {tA=1s {M0100644 SZ=5 L=1 1000:1000 B0*0 i0:4 A 0.000000 M 0.000000 C 0.000000}}
	14:59:31.714181 rx 17: FLUSH i4 {Fh 0}
	14:59:31.714186 tx 17:     OK
	14:59:31.714202 rx 18: RELEASE i4 {Fh 0 NONBLOCK,0x8000  L0}
	14:59:31.714208 tx 18:     OK

(*) my particular case is filesystem where many nodes are just data, but
additionally there are files that behave like sockets - for every client
who opens such file the filesystem establishes separate bidirectional
channel for control exchange via that stream:

https://lab.nexedi.com/kirr/wendelin.core/blob/a50da567fd/wcfs/misc.go#L205

This fixes race conditions found by the race detector.

If we call AddEntry/RemoveEntry before the update to the deletion list
in storage, a poorly timed cache refill that happens just before the
storage update will result in storing the old state for as long as the
cache's TTL.

This makes it clear when (and why) the filesystem was unmounted.

Example output:

$ gocryptfs -fg -nosyslog -fusedebug a b
Password:
Decrypting master key
Filesystem mounted and ready.
2019/01/23 21:52:59 rx 2: ACCESS i1 {r}
2019/01/23 21:52:59 tx 2:     OK
2019/01/23 21:52:59 rx 3: LOOKUP i1 [".Trash"] 7b
2019/01/23 21:52:59 tx 3:     OK, {i0 g0 tE=1s tA=0s {M00 SZ=0 L=0 0:0 B0*0 i0:0 A 0.000000 M 0.000000 C 0.000000}}
2019/01/23 21:52:59 rx 4: LOOKUP i1 [".Trash-1026"] 12b
2019/01/23 21:52:59 tx 4:     OK, {i0 g0 tE=1s tA=0s {M00 SZ=0 L=0 0:0 B0*0 i0:0 A 0.000000 M 0.000000 C 0.000000}}
2019/01/23 21:53:02 received ENODEV (unmount request), thread exiting
2019/01/23 21:53:02 received ENODEV (unmount request), thread exiting
2019/01/23 21:53:02 received ENODEV (unmount request), thread exiting

d1c826d1 ("fuse: increase signal/noise in log messages",
https://github.com/hanwen/go-fuse/pull/249) changed log to use
abbreviations in the name of improving signal/noise ratio. However it
might be not evident offhand what an abbreviation means.

Add a short reference in the readme with the summary on how to read the
log and a short example.

The summary is incomplete - for example I don't describe Fh and other
attributes that d1c826d1 did not change. I propose we review logging
more, e.g. consider doing `Fh X` -> `fX` and maybe similarly for other
fields, and while doing so, also populate/update the summary and example
in the readme. In other words it is good to document current state, but
it is not fixed in stone and can be evolved.

- use tA=...s instead of `A...` or `AttrValid=...` for time(Attr valid);
- use tE=...s instead of `EntryValid` for time(Entry valid);
- use iX instead of `NodeId: X` for inode X;
- use gX instead of `Generation=X` for generation X;
- use `[<off> +<size>)` instead of `off <off> sz <sz>`;

- use

        rx uniq: Op iX opargs
        tx uniq: status reply...

  instead of

        Dispatch uniq: Op NodeId: X opargs
        Serialize uniq: Op code: status reply...

  for received/replied messages;

- use `["file1", "file2"]` instead of `names: [file1, file2]` for filenames.

- use `xb` instead of `x bytes`

- for replied data, also log data content, but only up to first 8 bytes.
  This does not flood the log, but at the same time makes filesystem
  diagnostics easier.

nodeMap.Handle(&node) == 0 means the kernel does not currently have an
entry for this node in its dentry cache. And the kernel would return
ENOENT if we would try to send it notify store message with nodeID it
does not currently know.

So return proper ENOENT when we see that currently there is no handle
for the inode, instead of returning EINVAL, which means that call
arguments - e.g. off is invalid.

NOTE contrary to cache retrieve (where we could turn such error into empty OK
read; see previous patch) for cache store we cannot ignore the error.

Fixes bdca0e6a (Add support for store notify).
See also: https://github.com/hanwen/go-fuse/pull/246#discussion_r242050595