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

This patch continues bdca0e6a (Add support for store notify) and adds
corresponding support for counterpart to cache-store - to retrieve an inode
data from kernel cache.

As it was already noted in bdca0e6a, FUSE protocol provides primitives for
pagecache control: to invalidate a data region for inode (notify_inval_inode),
to store data into inode kernel's cache (notify_store), and to retrieve data
from inode kernel's cache (notify_retrieve). For the latter 2 FUSE protocol
messages and brief documentation about semantic can be seen here:

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/include/uapi/linux/fuse.h?id=v4.19-rc6-177-gcec4de302c5f#n68
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/include/uapi/linux/fuse.h?id=v4.19-rc6-177-gcec4de302c5f#n756

https://git.kernel.org/linus/a1d75f2582
https://git.kernel.org/linus/2d45ba381a

In short, to retrieve data from kernel cache, filesystem server sends

	S > C	NOTIFY_RETRIEVE_CACHE{notifyUnique, inode, offset, size}

and if that message was sent correctly, the kernel sends back another
write-style message with unique=notifyUnique

	S < C	NOTIFY_REPLY{inode, offset, size, data}

Since so far there were no cases when a server was querying the kernel,
and the reply comes as separate kernel "request", we have to add
infrastructure for tracking such in-flight queries. This is done by
adding Server.retrieveTab and friends.

Otherwise the implementation is straightforward.

A particular note is that from a user-level API point of view we are not
following e.g. libfuse to register a callback to be invoked upon reply, but
instead provide {Inode,File}RetrieveCache that synchronously send notify query
and wait for kernel's reply.

This fits more naturally to Go and is easier to use.

I've made the notes for myself, but then though it could be maybe useful
as the package documentation.

- it is not NOTIFY_INVAL_DELETE, but just NOTIFY_DELETE as the kernel is
  notified of entry being deleted and there is no invalidation here.
  uapi/linux/fuse.h does not use "_INVAL_" for NOTIFY_DELETE neither.

- similarly for "notify store/retrieve" _INVAL_ is not appropriate and
  neither is used in uapi/linux/fuse.h . However since we took more
  explicit approach for "notify store/retrieve" naming (see bdca0e6a
  "Add support for store notify") let's also add _CACHE suffix for
  "notify store/retrieve" operation names for consistency and for being
  less ambiguous.

- for inode/entry invalidation operations, let's use _INVAL_ in internal
  _OP_NOTIFY_*, similarly to how it is used in corresponding NOTIFY_*
  constant. For example:

	_OP_NOTIFY_ENTRY -> _OP_NOTIFY_INVAL_ENTRY	(corresponds to NOTIFY_INVAL_ENTRY)

The debug printout in the -race tests interferes with timing, so it
makes race conditions less likely to appear.