go-nfs Could not edit Microsoft Office files from mountpoint

Everything works fine except editing Microsoft Office files(e.g. Word, Excel, PowerPoint) from mountpoint. It can be edited if the file open directly from source folder, but when opening from mountpoint the Microsoft Office shows "readonly".

NFS Server: macOS, ./example/osnfs
NFS Client: macOS, mount

Dec 05 '22 09:12 ikmak

@willscott I've tried to mount with options locallocks, and it looks better. But there are still some problems. Word docx(doc) files could be saved with some wired temporary directories like abc.docx.sb-xxxxxx-xxxxx Excel xlsx(xls) files could be saved without any sb temporary directory PowerPoint pptx(ppt) files could be created but couldn't be saved.

NFS Server: macOS, sudo ./example/osnfs /path/to/files/ 45678
NFS Client: macOS, sudo mount_nfs -vvv -o port=45678,mountport=45678,proto=tcp,nosuid,sync,locallocks "localhost:/nfs" /path/to/mount

Dec 12 '22 05:12 ikmak

I wonder if https://github.com/willscott/go-nfs/pull/72 was the underlying issue behind this

can you try again with the current version?

Sep 18 '23 09:09 willscott

@willscott Same...

Sep 20 '23 07:09 ikmak

Does anyone have a clear idea what is happening here? This is affecting rclone users in https://github.com/rclone/rclone/issues/7973 in exactly the same way.

Putting nolock or locallocks doesn't fix the problem though - the symptoms are as described above https://github.com/willscott/go-nfs/issues/54#issuecomment-1345932088

Is this a problem because the nfs server doesn't implement locking? If so could we implement a skeleton locking system?

I notice that memfs has a stubbed out Lock and Unlock which don't appear to be called anywhere

https://github.com/willscott/go-nfs/blob/91bc38957cc95bcbbcc6f41c9bcf72dc8f6f47e0/helpers/memfs/memfs.go#L335-L343

Aug 22 '24 17:08 ncw

@ncw - the reason memfs does not implement lock / unlock is because the accompanying 'Network Lock Manager (NLM) protocol' is not implemented here. The protocol is documented in RFC 1813 - but it will be a bigger effort than the method you point to.

Aug 22 '24 17:08 willscott

Thanks @willscott

What do you think the best way forward with this issue is? Rclone can't support locking so how can we tell the clients not to try?

Aug 22 '24 20:08 ncw

If we can get logging of the NFS calls made while opening a word document, I'm not totally convinced that the underlying issue is lack of the locking protocol (especially since it has been observed in cases where the mount is done with local / no locks). If there's some other NFS call that is giving an error or otherwise appears to be acting in a way that might be suspicious I don't know if that's been fully ruled out at this point.
Otherwise, the next step may be to try to scaffold enough of NLMv4 to accept lock/test calls and see if that changes behavior. https://pubs.opengroup.org/onlinepubs/9629799/chap14.htm

Aug 23 '24 10:08 willscott

If we can get logging of the NFS calls made while opening a word document, I'm not totally convinced that the underlying issue is lack of the locking protocol (especially since it has been observed in cases where the mount is done with local / no locks). If there's some other NFS call that is giving an error or otherwise appears to be acting in a way that might be suspicious I don't know if that's been fully ruled out at this point.

What is the best way of doing this? The logging in the library doesn't seem to do a full rpc in/out trace or at least I haven't figured out how to make it do that if it can.

I'm not 100% convinced that this problem is to do with locking so tracing sound like a great idea

Otherwise, the next step may be to try to scaffold enough of NLMv4 to accept lock/test calls and see if that changes behavior. https://pubs.opengroup.org/onlinepubs/9629799/chap14.htm

It doesn't look too complicated...

Aug 24 '24 20:08 ncw

There's a log trace on each request: https://github.com/willscott/go-nfs/blob/master/conn.go#L62

Aug 25 '24 08:08 willscott

There's a major issue with NLM in this context - which is that from what i can tell mount'ing of NFS (the clients in Mac and Linux at least) don't allow specification of an explicit NLM port. As such, the server needs to be running in the standard privileged context where portmap is running and used to discover the port the lock manager is running on. I don't see a way to allow interaction with the locking sideband protocol with the same explicit mount-time behavior as with mountd and nfs itself

Aug 25 '24 12:08 willscott

There's a log trace on each request: https://github.com/willscott/go-nfs/blob/master/conn.go#L62

Here is a trace of those log statements

nfs-logs.txt

I extracted these from the rclone log which gives a bit more context

Terminal.Saved.Output (2).txt

I did not notice this line before

2024/07/30 17:58:02 DEBUG : [NFS DEBUG] failing create to indicate lack of support for 'exclusive' mode.

I wonder if that is the problem? Can we just ignore the exclusive mode?

That comes from here

https://github.com/willscott/go-nfs/blob/91bc38957cc95bcbbcc6f41c9bcf72dc8f6f47e0/nfs_oncreate.go#L36-L44

Aug 25 '24 13:08 ncw

I'm attempting an experiment using this patch. I've made an rclone binary with this patch and sent it to the user with the mac (not me!).

diff --git a/nfs_oncreate.go b/nfs_oncreate.go
index 63d7901..262eb8f 100644
--- a/nfs_oncreate.go
+++ b/nfs_oncreate.go
@@ -39,9 +39,8 @@ func onCreate(ctx context.Context, w *response, userHandle Handler) error {
                if err := xdr.Read(w.req.Body, &verf); err != nil {
                        return &NFSStatusError{NFSStatusInval, err}
                }
-               Log.Errorf("failing create to indicate lack of support for 'exclusive' mode.")
-               // TODO: support 'exclusive' mode.
-               return &NFSStatusError{NFSStatusNotSupp, os.ErrPermission}
+               // We ignore the createverf3 which is the key to the lock
+               Log.Errorf("ignoring 'exclusive' mode on create file.")
        } else {
                // invalid
                return &NFSStatusError{NFSStatusNotSupp, os.ErrInvalid}
@@ -88,9 +87,11 @@ func onCreate(ctx context.Context, w *response, userHandle Handler) error {
 
        fp := userHandle.ToHandle(fs, newFile)
        changer := userHandle.Change(fs)
-       if err := attrs.Apply(changer, fs, newFilePath); err != nil {
-               Log.Errorf("Error applying attributes: %v\n", err)
-               return &NFSStatusError{NFSStatusIO, err}
+       if attrs != nil {
+               if err := attrs.Apply(changer, fs, newFilePath); err != nil {
+                       Log.Errorf("Error applying attributes: %v\n", err)
+                       return &NFSStatusError{NFSStatusIO, err}
+               }
        }
 
        writer := bytes.NewBuffer([]byte{})

Which I think should work (cross fingers!)

There was one thing I didn't understand in that code though - the code appears to assume that the file already exists (ie has a handle and can have Stat called on it without an error) whereas the RFC doesn't say anything about the file existing or not. I've probably mis-understood the code or the RFC as I'm not very familiar with either but I just thought I'd mention it.

Aug 26 '24 08:08 ncw

I'm working on implementing the expected verifier for exclusive mode semantics. I'll try to have that up in the next day or two
The attempt at 'Stat' that you mention is used to not attempt creation if the file exists already as should be done in 'Guarded' mode. The call to Create is still done after the stat call unless the guarded mode failure is returned.

Aug 26 '24 08:08 willscott

@ncw perhaps also try with my branch at https://github.com/willscott/go-nfs/tree/feat/exclusive-create and see if it makes a difference

Aug 26 '24 09:08 willscott

Alas this does not compile on Linux

github.com/willscott/go-nfs/file
# github.com/willscott/go-nfs/file
../../../../pkg/mod/github.com/willscott/[email protected]/file/file_unix.go:22:26: s.Atimespec undefined (type *"syscall".Stat_t has no field or method Atimespec)
../../../../pkg/mod/github.com/willscott/[email protected]/file/file_unix.go:23:26: s.Ctimespec undefined (type *"syscall".Stat_t has no field or method Ctimespec)

Annoyingly the names of the Atimespec and Ctimespec change on a per OS basis

$ GOOS=linux go doc syscall.Stat_t | grep Timespec
	Atim      Timespec
	Mtim      Timespec
	Ctim      Timespec
$ GOOS=darwin go doc syscall.Stat_t | grep Timespec
	Atimespec     Timespec
	Mtimespec     Timespec
	Ctimespec     Timespec
	Birthtimespec Timespec

As for rclone, this locking scheme is unlikely to work as-is as backends don't support atime/ctime. Something based on mtime alone would work, but bear in mind that the precision might be truncated depending on the backend.

Probably my preference would be to have a way to tell the library just to treat exclusive creates the same as non-exclusive ones.

Aug 26 '24 11:08 ncw

I think the approach i have should work in a degraded way - if there isn't an exact match, a temporary file is made to save and recover the verifier. In cases where atime/ctime aren't supported, or things like dos with lower time precision, the intention is to degrade.

Thanks for flagging the build issue. I need some more os-specific casing

Aug 26 '24 11:08 willscott

Sounds good :-)

As an aside while we are talking about how annoyingsyscall.Stat_t, it is very annoying to work with because it is very OS dependent and even if the names of the fields are the same, they quite often have different types eg uint32 vs uint64 so using this as an extension struct as the output of FileInfo.Sys() isn't ideal other than making the reading from os.File based files easy.

I'd prefer you used a struct you defined specifically (probably your file.Fileinfo struct). You could make this change in a backwards compatible way by making file.GetInfo look for a file.Fileinfo struct as the output of Sys() too.

Aug 26 '24 11:08 ncw

I think that's what that method does, right? if the Sys() returns a FileInfo or *FileInfo it is directly returned, rather than being parsed from the unstable OS struct.

Aug 26 '24 11:08 willscott

I think that's what that method does, right? if the Sys() returns a FileInfo or *FileInfo it is directly returned, rather than being parsed from the unstable OS struct.

It does, you are quite right :blush:

It should probably say that here - I will send a PR to fix.

https://github.com/willscott/go-nfs/blob/91bc38957cc95bcbbcc6f41c9bcf72dc8f6f47e0/README.md?plain=1#L89-L91

Aug 26 '24 17:08 ncw

Does the addition of exclusive create change office behavior?

Aug 27 '24 13:08 willscott

Sorry, didn't see you updated your branch. Will test tomorrow

Aug 27 '24 17:08 ncw

Just a FYI - you can't go get your branch because apparently go tags can't have / in! It is no big deal to use the commit hash though.

The branch compiles much better now, but it didn't compile for these GOOS/GOARCH pairs

  linux/386
  linux/arm
  linux/mips
  linux/mipsle
  freebsd/386
  freebsd/amd64
  freebsd/arm
  netbsd/386
  netbsd/amd64
  netbsd/arm
  openbsd/386

With a selection of errors like

Error: ../../../../go/pkg/mod/github.com/willscott/[email protected]/file/file_unix.go:22:36: cannot use s.Atim.Nsec (variable of type int32) as int64 value in argument to time.Unix
Error: ../../../../go/pkg/mod/github.com/willscott/[email protected]/file/file_unix.go:22:26: s.Atim undefined (type *syscall.Stat_t has no field or method Atim)

You can check out the full selection in rclone's build logs 1 2

It built on darwin though so I've sent that off to my testers

I went through this pain in rclone so if you want to see what I came up with I needed 3 build files for bsd, linux and other unix.

Aug 28 '24 12:08 ncw

I've had a report back from the user doing the testing. Alas, it did not work.

Here is the nfs logs from go-nfs set to Trace level debug

fix-7973-nfs-server-ids-ff8ce1bef.nfs.log

Which were grepped out of the rclone logs here which have more context as to what the backend is doing

fix-7973-nfs-server-ids-ff8ce1bef.log

I annotated some of the rclone log with the nfs transactions below. I got bored of annotating the stat calls to the root and I stopped after the create.

The description of what the user did

I attempt to open this Word document. It is opened but with message that it is read-only and I should create duplicate in order to edit so I try to save it as "test1.docx". It fails.

There is just one file available.

I think if we we could figure out why word thinks it is read only then we could probably fix the problem.

Your new code is visible setting atime/mtime below, but the OS overwrites them immediately so I don't think this strategy is going to work. I think just ignoring the exclusive lock is probably the best strategy.

Click to see annotated transactions

List root

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800512 (nfs.ReadDirPlus)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : : ReadDir: 
2024/08/28 17:01:14 DEBUG : : OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:01:14 DEBUG : : >OpenFile: fd=/ (r), err=<nil>
2024/08/28 17:01:14 DEBUG : : >ReadDir: items=[824636002624], err=<nil>
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:14 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:01:14 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>

Stat test.docx

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800513 (nfs.Access)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=["test.docx"], err=<nil>
2024/08/28 17:01:14 DEBUG : test.docx: Lstat: 
2024/08/28 17:01:14 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:01:14 DEBUG : Capabilities: 
2024/08/28 17:01:14 DEBUG : >Capabilities: caps=31

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800514 (nfs.Access)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=["test.docx"], err=<nil>
2024/08/28 17:01:14 DEBUG : test.docx: Lstat: 
2024/08/28 17:01:14 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:01:14 DEBUG : Capabilities: 
2024/08/28 17:01:14 DEBUG : >Capabilities: caps=31

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800515 (nfs.FSStat)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : Capabilities: 
2024/08/28 17:01:14 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800516 (nfs.GetAttr)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800517 (nfs.FSStat)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : Capabilities: 
2024/08/28 17:01:14 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800518 (nfs.FSStat)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : Capabilities: 
2024/08/28 17:01:14 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800519 (nfs.FSStat)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : Capabilities: 
2024/08/28 17:01:14 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800520 (nfs.Lookup)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:14 DEBUG : .ql_disablethumbnails: Lstat: 
2024/08/28 17:01:14 DEBUG : .ql_disablethumbnails: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800521 (nfs.Lookup)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:14 DEBUG : .ql_disablecache: Lstat: 
2024/08/28 17:01:14 DEBUG : .ql_disablecache: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800522 (nfs.FSStat)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:14 DEBUG : Capabilities: 
2024/08/28 17:01:14 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:14 DEBUG : : Lstat: 
2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err=<nil>

Open test.docx and read - 13533 bytes read to EOF successfully

2024/08/28 17:01:14 DEBUG : nfs: request: RPC #3285800523 (nfs.Read)
2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=["test.docx"], err=<nil>
2024/08/28 17:01:14 DEBUG : test.docx: Open: 
2024/08/28 17:01:14 DEBUG : test.docx: OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:01:14 DEBUG : test.docx: Open: flags=O_RDONLY
2024/08/28 17:01:14 DEBUG : test.docx: newRWFileHandle: 
2024/08/28 17:01:14 DEBUG : test.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:01:14 DEBUG : test.docx: >Open: fd=test.docx (rw), err=<nil>
2024/08/28 17:01:14 DEBUG : test.docx: >OpenFile: fd=test.docx (rw), err=<nil>
2024/08/28 17:01:14 DEBUG : test.docx: >Open: test.docx (rw), err=<nil>
2024/08/28 17:01:14 DEBUG : test.docx(0xc000608e40): _readAt: size=32768, off=0
2024/08/28 17:01:14 DEBUG : test.docx(0xc000608e40): openPending: 
2024/08/28 17:01:14 DEBUG : test.docx: vfs cache: checking remote fingerprint "13533,2024-08-27 15:44:47.656015 +0000 UTC,f2a5ee52bb825eaa1b1dbc365f043a3b" against cached fingerprint ""
2024/08/28 17:01:14 DEBUG : test.docx: vfs cache: truncate to size=13533
2024/08/28 17:01:14 DEBUG : : Added virtual directory entry vAddFile: "test.docx"
2024/08/28 17:01:14 DEBUG : test.docx(0xc000608e40): >openPending: err=<nil>
2024/08/28 17:01:14 DEBUG : vfs cache: looking for range={Pos:0 Size:13533} in [] - present false
2024/08/28 17:01:14 DEBUG : test.docx: ChunkedReader.RangeSeek from -1 to 0 length -1
2024/08/28 17:01:14 DEBUG : test.docx: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2024/08/28 17:01:14 DEBUG : test.docx: ChunkedReader.openRange at 0 length 134217728
2024/08/28 17:01:15 DEBUG : test.docx(0xc000608e40): >_readAt: n=13533, err=EOF
2024/08/28 17:01:15 DEBUG : test.docx: Lstat: 
2024/08/28 17:01:15 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>

stat the root loads of times

2024/08/28 17:01:15 DEBUG : nfs: request: RPC #3285800524 (nfs.FSStat)
2024/08/28 17:01:15 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:15 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:15 DEBUG : Capabilities: 
2024/08/28 17:01:15 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:15 DEBUG : : Lstat: 
2024/08/28 17:01:15 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:15 DEBUG : nfs: request: RPC #3285800525 (nfs.FSStat)
2024/08/28 17:01:15 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:15 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:15 DEBUG : Capabilities: 
2024/08/28 17:01:15 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:15 DEBUG : : Lstat: 
2024/08/28 17:01:15 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:17 DEBUG : nfs: request: RPC #3285800526 (nfs.FSStat)
2024/08/28 17:01:17 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:17 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:17 DEBUG : Capabilities: 
2024/08/28 17:01:17 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:17 DEBUG : : Lstat: 
2024/08/28 17:01:17 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:18 DEBUG : nfs: request: RPC #3285800527 (nfs.FSStat)
2024/08/28 17:01:18 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:18 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:18 DEBUG : Capabilities: 
2024/08/28 17:01:18 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:18 DEBUG : : Lstat: 
2024/08/28 17:01:18 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:19 DEBUG : nfs: request: RPC #3285800528 (nfs.GetAttr)
2024/08/28 17:01:19 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:19 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:19 DEBUG : : Lstat: 
2024/08/28 17:01:19 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:22 DEBUG : nfs: request: RPC #3285800529 (nfs.FSStat)
2024/08/28 17:01:22 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:22 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:22 DEBUG : Capabilities: 
2024/08/28 17:01:22 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:22 DEBUG : : Lstat: 
2024/08/28 17:01:22 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:24 DEBUG : nfs: request: RPC #3285800530 (nfs.GetAttr)
2024/08/28 17:01:24 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:24 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:24 DEBUG : : Lstat: 
2024/08/28 17:01:24 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:24 DEBUG : nfs: request: RPC #3285800531 (nfs.FSStat)
2024/08/28 17:01:24 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:24 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:24 DEBUG : Capabilities: 
2024/08/28 17:01:24 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:24 DEBUG : : Lstat: 
2024/08/28 17:01:24 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:24 DEBUG : nfs: request: RPC #3285800532 (nfs.FSStat)
2024/08/28 17:01:24 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:24 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:24 DEBUG : Capabilities: 
2024/08/28 17:01:24 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:24 DEBUG : : Lstat: 
2024/08/28 17:01:24 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:24 DEBUG : nfs: request: RPC #3285800533 (nfs.FSStat)
2024/08/28 17:01:24 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:24 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:24 DEBUG : Capabilities: 
2024/08/28 17:01:24 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:24 DEBUG : : Lstat: 
2024/08/28 17:01:24 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:25 DEBUG : nfs: request: RPC #3285800534 (nfs.FSStat)
2024/08/28 17:01:25 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:25 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:25 DEBUG : Capabilities: 
2024/08/28 17:01:25 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:25 DEBUG : : Lstat: 
2024/08/28 17:01:25 DEBUG : : >Lstat: fi=/, err=<nil>

Now stat random files which appear to have nothing to do with what is going on

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800535 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : Brochure.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : Brochure.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800536 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : DocTest.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : DocTest.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800537 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : children of israel.docx.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : children of israel.docx.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800538 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : Jul2024.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : Jul2024.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800539 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : Jul2024-a.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : Jul2024-a.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800540 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : Jul2024a.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : Jul2024a.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800541 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : Hgfghfh jgjhgj.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : Hgfghfh jgjhgj.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800542 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : hgjhg.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : hgjhg.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800543 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : asdasdasd.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : asdasdasd.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800544 (nfs.FSStat)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : Capabilities: 
2024/08/28 17:01:26 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800545 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : 123.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : 123.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800546 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : test2.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : test2.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:26 DEBUG : nfs: request: RPC #3285800547 (nfs.Lookup)
2024/08/28 17:01:26 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:26 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:26 DEBUG : : Lstat: 
2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:26 DEBUG : test1.docx: Lstat: 
2024/08/28 17:01:26 DEBUG : test1.docx: >Lstat: fi=<nil>, err=file does not exist

Some more root stats for good measure

2024/08/28 17:01:29 DEBUG : nfs: request: RPC #3285800548 (nfs.GetAttr)
2024/08/28 17:01:29 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:29 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:29 DEBUG : : Lstat: 
2024/08/28 17:01:29 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:34 DEBUG : nfs: request: RPC #3285800549 (nfs.GetAttr)
2024/08/28 17:01:34 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:34 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:34 DEBUG : : Lstat: 
2024/08/28 17:01:34 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:39 DEBUG : nfs: request: RPC #3285800550 (nfs.GetAttr)
2024/08/28 17:01:39 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:39 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:39 DEBUG : : Lstat: 
2024/08/28 17:01:39 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:44 DEBUG : nfs: request: RPC #3285800551 (nfs.GetAttr)
2024/08/28 17:01:44 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:44 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:44 DEBUG : : Lstat: 
2024/08/28 17:01:44 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:49 DEBUG : nfs: request: RPC #3285800552 (nfs.GetAttr)
2024/08/28 17:01:49 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:49 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:49 DEBUG : : Lstat: 
2024/08/28 17:01:49 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:49 DEBUG : nfs: request: RPC #3285800553 (nfs.FSStat)
2024/08/28 17:01:49 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:49 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:49 DEBUG : Capabilities: 
2024/08/28 17:01:49 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:49 DEBUG : : Lstat: 
2024/08/28 17:01:49 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:49 DEBUG : nfs: request: RPC #3285800554 (nfs.FSStat)
2024/08/28 17:01:49 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:49 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:49 DEBUG : Capabilities: 
2024/08/28 17:01:49 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:49 DEBUG : : Lstat: 
2024/08/28 17:01:49 DEBUG : : >Lstat: fi=/, err=<nil>

stat test.docx again

2024/08/28 17:01:52 DEBUG : nfs: request: RPC #3285800555 (nfs.Access)
2024/08/28 17:01:52 DEBUG : nfs: FromHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:01:52 DEBUG : nfs: >FromHandle: path=["test.docx"], err=<nil>
2024/08/28 17:01:52 DEBUG : test.docx: Lstat: 
2024/08/28 17:01:52 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:01:52 DEBUG : Capabilities: 
2024/08/28 17:01:52 DEBUG : >Capabilities: caps=31

and then the root

2024/08/28 17:01:52 DEBUG : nfs: request: RPC #3285800556 (nfs.FSStat)
2024/08/28 17:01:52 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:52 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:52 DEBUG : Capabilities: 
2024/08/28 17:01:52 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:52 DEBUG : : Lstat: 
2024/08/28 17:01:52 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:52 DEBUG : nfs: request: RPC #3285800557 (nfs.FSStat)
2024/08/28 17:01:52 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:52 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:52 DEBUG : Capabilities: 
2024/08/28 17:01:52 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:52 DEBUG : : Lstat: 
2024/08/28 17:01:52 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:53 DEBUG : nfs: request: RPC #3285800558 (nfs.FSStat)
2024/08/28 17:01:53 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:53 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:53 DEBUG : Capabilities: 
2024/08/28 17:01:53 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:53 DEBUG : : Lstat: 
2024/08/28 17:01:53 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:54 DEBUG : nfs: request: RPC #3285800559 (nfs.GetAttr)
2024/08/28 17:01:54 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:54 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:54 DEBUG : : Lstat: 
2024/08/28 17:01:54 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:55 DEBUG : nfs: request: RPC #3285800560 (nfs.FSStat)
2024/08/28 17:01:55 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:55 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:55 DEBUG : Capabilities: 
2024/08/28 17:01:55 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:55 DEBUG : : Lstat: 
2024/08/28 17:01:55 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:55 DEBUG : nfs: request: RPC #3285800561 (nfs.FSStat)
2024/08/28 17:01:55 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:55 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:55 DEBUG : Capabilities: 
2024/08/28 17:01:55 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:55 DEBUG : : Lstat: 
2024/08/28 17:01:55 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:55 DEBUG : nfs: request: RPC #3285800562 (nfs.Lookup)
2024/08/28 17:01:55 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:55 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:55 DEBUG : : Lstat: 
2024/08/28 17:01:55 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:01:55 DEBUG : children%20of%20israel.docx.docx: Lstat: 
2024/08/28 17:01:55 DEBUG : children%20of%20israel.docx.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:01:55 DEBUG : nfs: request: RPC #3285800563 (nfs.FSStat)
2024/08/28 17:01:55 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:55 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:55 DEBUG : Capabilities: 
2024/08/28 17:01:55 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:55 DEBUG : : Lstat: 
2024/08/28 17:01:55 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:56 DEBUG : nfs: request: RPC #3285800564 (nfs.FSStat)
2024/08/28 17:01:56 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:56 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:56 DEBUG : Capabilities: 
2024/08/28 17:01:56 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:56 DEBUG : : Lstat: 
2024/08/28 17:01:56 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:57 DEBUG : nfs: request: RPC #3285800565 (nfs.FSStat)
2024/08/28 17:01:57 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:57 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:57 DEBUG : Capabilities: 
2024/08/28 17:01:57 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:57 DEBUG : : Lstat: 
2024/08/28 17:01:57 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:58 DEBUG : nfs: request: RPC #3285800566 (nfs.FSStat)
2024/08/28 17:01:58 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:58 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:58 DEBUG : Capabilities: 
2024/08/28 17:01:58 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:58 DEBUG : : Lstat: 
2024/08/28 17:01:58 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:58 DEBUG : nfs: request: RPC #3285800567 (nfs.FSStat)
2024/08/28 17:01:58 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:58 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:58 DEBUG : Capabilities: 
2024/08/28 17:01:58 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:58 DEBUG : : Lstat: 
2024/08/28 17:01:58 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:58 DEBUG : nfs: request: RPC #3285800568 (nfs.FSStat)
2024/08/28 17:01:58 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:58 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:58 DEBUG : Capabilities: 
2024/08/28 17:01:58 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:58 DEBUG : : Lstat: 
2024/08/28 17:01:58 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:58 DEBUG : nfs: request: RPC #3285800569 (nfs.FSStat)
2024/08/28 17:01:58 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:58 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:58 DEBUG : Capabilities: 
2024/08/28 17:01:58 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:58 DEBUG : : Lstat: 
2024/08/28 17:01:58 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:59 DEBUG : nfs: request: RPC #3285800570 (nfs.GetAttr)
2024/08/28 17:01:59 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:59 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:59 DEBUG : : Lstat: 
2024/08/28 17:01:59 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:01:59 DEBUG : nfs: request: RPC #3285800571 (nfs.FSStat)
2024/08/28 17:01:59 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:01:59 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:01:59 DEBUG : Capabilities: 
2024/08/28 17:01:59 DEBUG : >Capabilities: caps=31
2024/08/28 17:01:59 DEBUG : : Lstat: 
2024/08/28 17:01:59 DEBUG : : >Lstat: fi=/, err=<nil>

List the root - still just the one file test.docx in it

2024/08/28 17:02:00 DEBUG : nfs: request: RPC #3285800572 (nfs.ReadDirPlus)
2024/08/28 17:02:00 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:00 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:00 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:00 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:00 DEBUG : : ReadDir: 
2024/08/28 17:02:00 DEBUG : : OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:02:00 DEBUG : : >OpenFile: fd=/ (r), err=<nil>
2024/08/28 17:02:00 DEBUG : : >ReadDir: items=[824636002624], err=<nil>
2024/08/28 17:02:00 DEBUG : : Lstat: 
2024/08/28 17:02:00 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:00 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:00 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:00 DEBUG : : Lstat: 
2024/08/28 17:02:00 DEBUG : : >Lstat: fi=/, err=<nil>

stat the root some more

2024/08/28 17:02:00 DEBUG : nfs: request: RPC #3285800573 (nfs.FSStat)
2024/08/28 17:02:00 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:00 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:00 DEBUG : Capabilities: 
2024/08/28 17:02:00 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:00 DEBUG : : Lstat: 
2024/08/28 17:02:00 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:04 DEBUG : nfs: request: RPC #3285800574 (nfs.GetAttr)
2024/08/28 17:02:04 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:04 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:04 DEBUG : : Lstat: 
2024/08/28 17:02:04 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:09 DEBUG : nfs: request: RPC #3285800575 (nfs.GetAttr)
2024/08/28 17:02:09 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:09 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:09 DEBUG : : Lstat: 
2024/08/28 17:02:09 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:09 DEBUG : nfs: request: RPC #3285800576 (nfs.FSStat)
2024/08/28 17:02:09 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:09 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:09 DEBUG : Capabilities: 
2024/08/28 17:02:09 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:09 DEBUG : : Lstat: 
2024/08/28 17:02:09 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:10 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test.docx not removed, freed 0 bytes
2024/08/28 17:02:10 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 13.216Ki (was 13.216Ki)

2024/08/28 17:02:14 DEBUG : nfs: request: RPC #3285800577 (nfs.GetAttr)
2024/08/28 17:02:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:14 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:14 DEBUG : : Lstat: 
2024/08/28 17:02:14 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:19 DEBUG : nfs: request: RPC #3285800578 (nfs.GetAttr)
2024/08/28 17:02:19 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:19 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:19 DEBUG : : Lstat: 
2024/08/28 17:02:19 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:19 DEBUG : nfs: request: RPC #3285800579 (nfs.FSStat)
2024/08/28 17:02:19 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:19 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:19 DEBUG : Capabilities: 
2024/08/28 17:02:19 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:19 DEBUG : : Lstat: 
2024/08/28 17:02:19 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:24 DEBUG : nfs: request: RPC #3285800580 (nfs.GetAttr)
2024/08/28 17:02:24 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:24 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:24 DEBUG : : Lstat: 
2024/08/28 17:02:24 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:29 DEBUG : nfs: request: RPC #3285800581 (nfs.GetAttr)
2024/08/28 17:02:29 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:29 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:29 DEBUG : : Lstat: 
2024/08/28 17:02:29 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:29 DEBUG : nfs: request: RPC #3285800582 (nfs.Access)
2024/08/28 17:02:29 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:29 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:29 DEBUG : : Lstat: 
2024/08/28 17:02:29 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:29 DEBUG : Capabilities: 
2024/08/28 17:02:29 DEBUG : >Capabilities: caps=31

Stat test.docx

2024/08/28 17:02:29 DEBUG : nfs: request: RPC #3285800583 (nfs.Access)
2024/08/28 17:02:29 DEBUG : nfs: FromHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:29 DEBUG : nfs: >FromHandle: path=["test.docx"], err=<nil>
2024/08/28 17:02:29 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:29 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:29 DEBUG : Capabilities: 
2024/08/28 17:02:29 DEBUG : >Capabilities: caps=31

And now the root some more

2024/08/28 17:02:29 DEBUG : nfs: request: RPC #3285800584 (nfs.FSStat)
2024/08/28 17:02:29 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:29 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:29 DEBUG : Capabilities: 
2024/08/28 17:02:29 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:29 DEBUG : : Lstat: 
2024/08/28 17:02:29 DEBUG : : >Lstat: fi=/, err=<nil>

Stat Untitled

2024/08/28 17:02:30 DEBUG : nfs: request: RPC #3285800585 (nfs.Lookup)
2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:30 DEBUG : : Lstat: 
2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:30 DEBUG : Untitled: Lstat: 
2024/08/28 17:02:30 DEBUG : Untitled: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:30 DEBUG : nfs: request: RPC #3285800586 (nfs.FSStat)
2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:30 DEBUG : Capabilities: 
2024/08/28 17:02:30 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:30 DEBUG : : Lstat: 
2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:30 DEBUG : nfs: request: RPC #3285800587 (nfs.Lookup)
2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:30 DEBUG : : Lstat: 
2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:30 DEBUG : Untitled.docx: Lstat: 
2024/08/28 17:02:30 DEBUG : Untitled.docx: >Lstat: fi=<nil>, err=file does not exist

List the directory again, still only test.docx in there

2024/08/28 17:02:30 DEBUG : nfs: request: RPC #3285800588 (nfs.ReadDirPlus)
2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:30 DEBUG : : ReadDir: 
2024/08/28 17:02:30 DEBUG : : OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:02:30 DEBUG : : >OpenFile: fd=/ (r), err=<nil>
2024/08/28 17:02:30 DEBUG : : >ReadDir: items=[824636002624], err=<nil>
2024/08/28 17:02:30 DEBUG : : Lstat: 
2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:30 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:30 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:30 DEBUG : : Lstat: 
2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:30 DEBUG : nfs: request: RPC #3285800589 (nfs.FSStat)
2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:30 DEBUG : Capabilities: 
2024/08/28 17:02:30 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:30 DEBUG : : Lstat: 
2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:30 DEBUG : nfs: request: RPC #3285800590 (nfs.FSStat)
2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:30 DEBUG : Capabilities: 
2024/08/28 17:02:30 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:30 DEBUG : : Lstat: 
2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:34 DEBUG : nfs: request: RPC #3285800591 (nfs.GetAttr)
2024/08/28 17:02:34 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:34 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:34 DEBUG : : Lstat: 
2024/08/28 17:02:34 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800592 (nfs.Access)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31

By this point Word has concluded (somehow) that test.docx is read only.

Check the file test1.docx does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800593 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=<nil>, err=file does not exist

Create the file test1.docx - this is the part that failed before I think

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800595 (nfs.Create)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : test1.docx: Stat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Stat: fi=<nil>, err=file does not exist
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Create: 
2024/08/28 17:02:36 DEBUG : test1.docx: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2024/08/28 17:02:36 DEBUG : test1.docx: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2024/08/28 17:02:36 DEBUG : test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : test1.docx(0xc000a4e600): openPending: 
2024/08/28 17:02:36 DEBUG : test1.docx: vfs cache: truncate to size=0 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "test1.docx"
2024/08/28 17:02:36 DEBUG : test1.docx(0xc000a4e600): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "test1.docx"
2024/08/28 17:02:36 DEBUG : test1.docx: >Open: fd=test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: >OpenFile: fd=test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: >Create: test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx(0xc000a4e600): close: 
2024/08/28 17:02:36 DEBUG : test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.736277 +0200 CEST m=+86.160299270
2024/08/28 17:02:36 INFO  : test1.docx: vfs cache: queuing for upload in 5s
2024/08/28 17:02:36 DEBUG : test1.docx(0xc000a4e600): >close: err=<nil>

I think this is your new code attempting to set the atime and mtime - note odd 2042 date!

2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Chtimes: atime=2042-07-14 03:04:03.423622144 +0200 CEST, mtime=2074-02-14 03:23:14 +0100 CET
2024/08/28 17:02:36 DEBUG : test1.docx: vfs cache: setting modification time to 2074-02-14 03:23:14 +0100 CET
2024/08/28 17:02:36 DEBUG : test1.docx: >Chtimes: err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

Does the lock file exist?

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800596 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=<nil>, err=file does not exist

I think this is word or macOS setting the modification times (not sure)

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800597 (nfs.SetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Chtimes: atime=2024-08-28 17:02:36.738379 +0200 CEST m=+86.162401937, mtime=2024-08-28 17:02:36.73838 +0200 CEST m=+86.162402353
2024/08/28 17:02:36 DEBUG : test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.73838 +0200 CEST m=+86.162402353
2024/08/28 17:02:36 DEBUG : test1.docx: >Chtimes: err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>

more stats

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800600 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>

more stats

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800601 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=<nil>, err=file does not exist

Create the lock file - apparently successful

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800602 (nfs.Create)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : ._test1.docx: Stat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Stat: fi=<nil>, err=file does not exist
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Create: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e880): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=0 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e880): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Create: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e880): close: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.741509 +0200 CEST m=+86.165531369
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: queuing for upload in 5s
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e880): >close: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=33B66ECA30BA44A99F03AC4385CBD356
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

something loves stat calls!

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800603 (nfs.FSStat)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

stat a lock file ._. ?

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800604 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._.: Lstat: 
2024/08/28 17:02:36 DEBUG : ._.: >Lstat: fi=<nil>, err=file does not exist

Write to the ._test1.docx file - apparently successful

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800605 (nfs.Write)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=33B66ECA30BA44A99F03AC4385CBD356
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : ._test1.docx: Stat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Stat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flag=0x2, perm=-rw-r--r--
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDWR, perm=-rw-r--r--
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDWR
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e9c0): _writeAt: size=4096, off=0
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e9c0): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=0 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e9c0): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: cancelling writeback (uploading false) 0xc000147420 item 2
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e9c0): >_writeAt: n=4096, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e9c0): close: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.760681 +0200 CEST m=+86.184703562
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: queuing for upload in 5s
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4e9c0): >close: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

List the root (root directory is "" in rclone world)

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800606 (nfs.ReadDirPlus)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : ReadDir: 
2024/08/28 17:02:36 DEBUG : : OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:02:36 DEBUG : : >OpenFile: fd=/ (r), err=<nil>
2024/08/28 17:02:36 DEBUG : : >ReadDir: items=[824644485504 824636002624 824644485312], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=33B66ECA30BA44A99F03AC4385CBD356
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

stat ._test1.docx

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800608 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=33B66ECA30BA44A99F03AC4385CBD356
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

stat the file .nfs.2005103d.05c2 - where does this come from?

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800609 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Lstat: fi=<nil>, err=file does not exist

Rename ._test1.docx to .nfs.2005103d.05c2 successfully

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800610 (nfs.Rename)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=33B66ECA30BA44A99F03AC4385CBD356
2024/08/28 17:02:36 DEBUG : ._test1.docx: Rename: newpath=".nfs.2005103d.05c2"
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: renamed in cache to ".nfs.2005103d.05c2"
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Updating file with <nil> 0xc000a44180
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vDel: "._test1.docx"
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: ".nfs.2005103d.05c2"
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Rename: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=33B66ECA30BA44A99F03AC4385CBD356
2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

stat .nfs.2005103d.05c2

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800611 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Lstat: fi=.nfs.2005103d.05c2, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=[".nfs.2005103d.05c2"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=EF6F00FDB1BB4E7BBC697F9B6C40731D
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Lstat: fi=.nfs.2005103d.05c2, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

check ._test1.docx does not exist any more

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800613 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=<nil>, err=file does not exist

stat .nfs.2005103d.05c2

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800614 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=EF6F00FDB1BB4E7BBC697F9B6C40731D
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[".nfs.2005103d.05c2"], err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Lstat: fi=.nfs.2005103d.05c2, err=<nil>

stat test.docx - it exists

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800615 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

Remove .nfs.2005103d.05c2

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800616 (nfs.Remove)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=[".nfs.2005103d.05c2"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=EF6F00FDB1BB4E7BBC697F9B6C40731D
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Remove: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Remove: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: vfs cache: cancelling writeback (uploading false) 0xc0001478f0 item 2
2024/08/28 17:02:36 INFO  : .nfs.2005103d.05c2: vfs cache: removed cache file as file deleted
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: vfs cache: removed metadata from cache as file deleted
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vDel: ".nfs.2005103d.05c2"
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Remove: err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Remove: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=EF6F00FDB1BB4E7BBC697F9B6C40731D
2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800618 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800619 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800620 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800621 (nfs.Access)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800622 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800623 (nfs.Access)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800624 (nfs.Create)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : ._test1.docx: Stat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Stat: fi=<nil>, err=file does not exist
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Create: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f080): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=0 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f080): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Create: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f080): close: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.769976 +0200 CEST m=+86.193999168
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: queuing for upload in 5s
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f080): >close: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800625 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800626 (nfs.Write)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : ._test1.docx: Stat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Stat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flag=0x2, perm=-rw-r--r--
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDWR, perm=-rw-r--r--
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDWR
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f180): _writeAt: size=4096, off=0
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f180): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=0 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f180): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: cancelling writeback (uploading false) 0xc0004d6930 item 3
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f180): >_writeAt: n=4096, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f180): close: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.773165 +0200 CEST m=+86.197187821
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: queuing for upload in 5s
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f180): >close: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800629 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800630 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800633 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800634 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800635 (nfs.Read)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDONLY
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f300): _readAt: size=32768, off=0
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f300): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=4096 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f300): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:4096}] - present true
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc000a4f300): >_readAt: n=4096, err=EOF
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800636 (nfs.Rename)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : ._test1.docx: Rename: newpath=".nfs.2005103e.05c2"
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: renamed in cache to ".nfs.2005103e.05c2"
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Updating file with <nil> 0xc000a44240
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vDel: "._test1.docx"
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: ".nfs.2005103e.05c2"
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Rename: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14
2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800637 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Lstat: fi=.nfs.2005103e.05c2, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=[".nfs.2005103e.05c2"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=DBB0F6C837674A83976658D99AA6E034
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Lstat: fi=.nfs.2005103e.05c2, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800639 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800640 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=DBB0F6C837674A83976658D99AA6E034
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[".nfs.2005103e.05c2"], err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Lstat: fi=.nfs.2005103e.05c2, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800641 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800642 (nfs.Remove)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=[".nfs.2005103e.05c2"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=DBB0F6C837674A83976658D99AA6E034
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Remove: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Remove: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: vfs cache: cancelling writeback (uploading false) 0xc0004d6e00 item 3
2024/08/28 17:02:36 INFO  : .nfs.2005103e.05c2: vfs cache: removed cache file as file deleted
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: vfs cache: removed metadata from cache as file deleted
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vDel: ".nfs.2005103e.05c2"
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Remove: err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Remove: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=DBB0F6C837674A83976658D99AA6E034
2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800644 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800645 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800646 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800647 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800648 (nfs.FSStat)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800649 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800650 (nfs.Create)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : ._test1.docx: Stat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Stat: fi=<nil>, err=file does not exist
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Create: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9040): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=0 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9040): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Create: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9040): close: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.788716 +0200 CEST m=+86.212738997
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: queuing for upload in 5s
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9040): >close: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=F8718F812B964E9EBFAED9731D6E0778
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800651 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800652 (nfs.Write)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=F8718F812B964E9EBFAED9731D6E0778
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : ._test1.docx: Stat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Stat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flag=0x2, perm=-rw-r--r--
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDWR, perm=-rw-r--r--
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDWR
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9180): _writeAt: size=4096, off=0
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9180): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=0 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9180): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: cancelling writeback (uploading false) 0xc0004d9730 item 4
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9180): >_writeAt: n=4096, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9180): close: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: setting modification time to 2024-08-28 17:02:36.793359 +0200 CEST m=+86.217382177
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: queuing for upload in 5s
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f9180): >close: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800655 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=F8718F812B964E9EBFAED9731D6E0778
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800656 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=F8718F812B964E9EBFAED9731D6E0778
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800657 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800658 (nfs.Read)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=F8718F812B964E9EBFAED9731D6E0778
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=["._test1.docx"], err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:02:36 DEBUG : ._test1.docx: Open: flags=O_RDONLY
2024/08/28 17:02:36 DEBUG : ._test1.docx: newRWFileHandle: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: ._test1.docx (rw), err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f92c0): _readAt: size=32768, off=0
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f92c0): openPending: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: vfs cache: truncate to size=4096 (not needed as size correct)
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: "._test1.docx"
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f92c0): >openPending: err=<nil>
2024/08/28 17:02:36 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [{Pos:0 Size:4096}] - present true
2024/08/28 17:02:36 DEBUG : ._test1.docx(0xc0000f92c0): >_readAt: n=4096, err=EOF
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800659 (nfs.Rename)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=["._test1.docx"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=F8718F812B964E9EBFAED9731D6E0778
2024/08/28 17:02:36 DEBUG : ._test1.docx: Rename: newpath=".nfs.2005103f.05c2"
2024/08/28 17:02:36 INFO  : ._test1.docx: vfs cache: renamed in cache to ".nfs.2005103f.05c2"
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: Updating file with <nil> 0xc00022d080
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vDel: "._test1.docx"
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vAddFile: ".nfs.2005103f.05c2"
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Rename: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=F8718F812B964E9EBFAED9731D6E0778
2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800660 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: >Lstat: fi=.nfs.2005103f.05c2, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=[".nfs.2005103f.05c2"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=9D623F51D73242A6AF3614636B260A5F
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: >Lstat: fi=.nfs.2005103f.05c2, err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800662 (nfs.GetAttr)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=9D623F51D73242A6AF3614636B260A5F
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[".nfs.2005103f.05c2"], err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: Lstat: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: >Lstat: fi=.nfs.2005103f.05c2, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800663 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 
2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800664 (nfs.Remove)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : Capabilities: 
2024/08/28 17:02:36 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:36 DEBUG : : Stat: 
2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: ToHandle: path=[".nfs.2005103f.05c2"]
2024/08/28 17:02:36 DEBUG : nfs: >ToHandle: handle=9D623F51D73242A6AF3614636B260A5F
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: Remove: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: Remove: 
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: vfs cache: cancelling writeback (uploading false) 0xc0004d99d0 item 4
2024/08/28 17:02:36 INFO  : .nfs.2005103f.05c2: vfs cache: removed cache file as file deleted
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: vfs cache: removed metadata from cache as file deleted
2024/08/28 17:02:36 DEBUG : : Added virtual directory entry vDel: ".nfs.2005103f.05c2"
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: >Remove: err=<nil>
2024/08/28 17:02:36 DEBUG : .nfs.2005103f.05c2: >Remove: err=<nil>
2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=9D623F51D73242A6AF3614636B260A5F
2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:36 DEBUG : nfs: request: RPC #3285800666 (nfs.Lookup)
2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:36 DEBUG : : Lstat: 
2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:36 DEBUG : test1: Lstat: 
2024/08/28 17:02:36 DEBUG : test1: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800667 (nfs.FSStat)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : Capabilities: 
2024/08/28 17:02:37 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800668 (nfs.Lookup)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:37 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:37 DEBUG : test.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test.docx: >Lstat: fi=test.docx, err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800669 (nfs.Access)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=["test1.docx"], err=<nil>
2024/08/28 17:02:37 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:37 DEBUG : Capabilities: 
2024/08/28 17:02:37 DEBUG : >Capabilities: caps=31

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800670 (nfs.Lookup)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : ._.: Lstat: 
2024/08/28 17:02:37 DEBUG : ._.: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800671 (nfs.ReadDirPlus)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : : ReadDir: 
2024/08/28 17:02:37 DEBUG : : OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:02:37 DEBUG : : >OpenFile: fd=/ (r), err=<nil>
2024/08/28 17:02:37 DEBUG : : >ReadDir: items=[824636002624 824644485312], err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:37 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:37 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:37 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800672 (nfs.FSStat)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : Capabilities: 
2024/08/28 17:02:37 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800673 (nfs.FSStat)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : Capabilities: 
2024/08/28 17:02:37 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800674 (nfs.Lookup)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:37 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:37 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800676 (nfs.Lookup)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:37 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:37 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test1.docx: >Lstat: fi=test1.docx, err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800677 (nfs.Remove)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : Capabilities: 
2024/08/28 17:02:37 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:37 DEBUG : : Stat: 
2024/08/28 17:02:37 DEBUG : : >Stat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: ToHandle: path=["test1.docx"]
2024/08/28 17:02:37 DEBUG : nfs: >ToHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:37 DEBUG : test1.docx: Remove: 
2024/08/28 17:02:37 DEBUG : test1.docx: Remove: 
2024/08/28 17:02:37 DEBUG : test1.docx: vfs cache: cancelling writeback (uploading false) 0xc000146d90 item 1
2024/08/28 17:02:37 INFO  : test1.docx: vfs cache: removed cache file as file deleted
2024/08/28 17:02:37 DEBUG : test1.docx: vfs cache: removed metadata from cache as file deleted
2024/08/28 17:02:37 DEBUG : : Added virtual directory entry vDel: "test1.docx"
2024/08/28 17:02:37 DEBUG : test1.docx: >Remove: err=<nil>
2024/08/28 17:02:37 DEBUG : test1.docx: >Remove: err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: InvalidateHandle: handle=71B7D7B523CF41DF99305EED0CCAA4C1
2024/08/28 17:02:37 DEBUG : nfs: >InvalidateHandle: err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800679 (nfs.Lookup)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : test1.docx: Lstat: 
2024/08/28 17:02:37 DEBUG : test1.docx: >Lstat: fi=<nil>, err=file does not exist

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800680 (nfs.ReadDirPlus)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : : ReadDir: 
2024/08/28 17:02:37 DEBUG : : OpenFile: flags=O_RDONLY, perm=----------
2024/08/28 17:02:37 DEBUG : : >OpenFile: fd=/ (r), err=<nil>
2024/08/28 17:02:37 DEBUG : : >ReadDir: items=[824636002624], err=<nil>
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:37 DEBUG : nfs: ToHandle: path=["test.docx"]
2024/08/28 17:02:37 DEBUG : nfs: >ToHandle: handle=AF0687EE68ED4BE287759CB95D8C62EB
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:37 DEBUG : nfs: request: RPC #3285800681 (nfs.FSStat)
2024/08/28 17:02:37 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:37 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:37 DEBUG : Capabilities: 
2024/08/28 17:02:37 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:37 DEBUG : : Lstat: 
2024/08/28 17:02:37 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:39 DEBUG : nfs: request: RPC #3285800682 (nfs.GetAttr)
2024/08/28 17:02:39 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:39 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:39 DEBUG : : Lstat: 
2024/08/28 17:02:39 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:39 DEBUG : nfs: request: RPC #3285800683 (nfs.FSStat)
2024/08/28 17:02:39 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:39 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:39 DEBUG : Capabilities: 
2024/08/28 17:02:39 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:39 DEBUG : : Lstat: 
2024/08/28 17:02:39 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:44 DEBUG : nfs: request: RPC #3285800684 (nfs.GetAttr)
2024/08/28 17:02:44 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:44 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:44 DEBUG : : Lstat: 
2024/08/28 17:02:44 DEBUG : : >Lstat: fi=/, err=<nil>

2024/08/28 17:02:47 DEBUG : nfs: request: RPC #3285800685 (nfs.FSStat)
2024/08/28 17:02:47 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147
2024/08/28 17:02:47 DEBUG : nfs: >FromHandle: path=[], err=<nil>
2024/08/28 17:02:47 DEBUG : Capabilities: 
2024/08/28 17:02:47 DEBUG : >Capabilities: caps=31
2024/08/28 17:02:47 DEBUG : : Lstat: 
2024/08/28 17:02:47 DEBUG : : >Lstat: fi=/, err=<nil>
2024/08/28 17:02:47 INFO  : unmount detected
2024/08/28 17:02:47 ERROR : /Users/kptsky/Temp/mount: Unmounted rclone mount
2024/08/28 17:02:47 DEBUG : rclone: Version "v1.68.0-DEV" finishing with parameters ["./rclone" "nfsmount" "iDrive:test-uk" "/Users/kptsky/Temp/mount" "--vfs-cache-mode=full" "-vv" "--log-file" "fix-7973-nfs-server-ids-ff8ce1bef.log"]

Aug 28 '24 17:08 ncw

nevermind - i misread a read of a directory as indicating read-only permissions on the underlying FS

Aug 28 '24 21:08 willscott

Could this be something about 'word defaults to open files on remote servers in a protected view' https://answers.microsoft.com/en-us/msoffice/forum/all/word-for-mac-opens-docs-on-a-server-read-only-how/410df015-4b27-414e-9e0f-2a4ac233f580 ?

Aug 29 '24 07:08 willscott

We double checked the permissions of things and they all look OK.

I think the clue here is that -o locallocks causes things to work better - word files can be opened read and saved but strange directories get created

drwxr-xr-x@ 1 user  staff      0 Aug 28 20:06 test.docx.sb-a308ef70-2NoZmO
drwxr-xr-x@ 1 user  staff      0 Aug 28 20:06 test.docx.sb-a308ef70-3ypGPP
drwxr-xr-x@ 1 user  staff      0 Aug 28 20:06 test.docx.sb-a308ef70-buTkcS
drwxr-xr-x@ 1 user  staff      0 Aug 28 20:06 test.docx.sb-a308ef70-kVONuI

I'm pretty sure these directories are created by the NFS client to implement locallocks. the a308ef70 is a host identifier of some kind and the 2NoZmO is a random 4 byte identifier maybe.

So it is almost certainly the lack of some kind of locking which is causing the problem I think.

Aug 29 '24 08:08 ncw

There's a major issue with NLM in this context - which is that from what i can tell mount'ing of NFS (the clients in Mac and Linux at least) don't allow specification of an explicit NLM port. As such, the server needs to be running in the standard privileged context where portmap is running and used to discover the port the lock manager is running on. I don't see a way to allow interaction with the locking sideband protocol with the same explicit mount-time behavior as with mountd and nfs itself

seems like the main issue in being able to do something other than locallocks

Aug 29 '24 08:08 willscott

looking at the kernel handling of locallocks - (https://github.com/nneonneo/osx-10.9-opensource/blob/master/xnu-2422.1.72/bsd/vfs/kpi_vfs.c#L4823 may be as reasonable a place to start diving in as anywhere) it looks like the advisory locks are dealt with in the kernel, not in an NFS-specific-driver when that that option is passed (see here) and i don't see any path where the temporary files would be getting created out of those memory structures, so i'm suspecting there's something more than a standard flock happening here.

Aug 29 '24 08:08 willscott

I wonder if another potential culprit could be that nfsv3 doesn't support extended file attributes. If the software is trying to make use of extended attributes, it will find that the filesystem doesn't support them.

Solutions to both of these issues (userland locking protocol support, and extended attributes) seem to point to nfs v4 protocol rather than this library which offers v3.

Aug 29 '24 12:08 willscott

go-nfs go-nfs copied to clipboard

Could not edit Microsoft Office files from mountpoint

go-nfs
go-nfs copied to clipboard