Could not edit Microsoft Office files from mountpoint

ikmak commented 1 year ago

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

ikmak commented 1 year ago

@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

willscott commented 1 year ago

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?

ikmak commented 1 year ago

@willscott Same...

ncw commented 3 months ago

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

willscott commented 3 months ago

@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.

ncw commented 3 months ago

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?

willscott commented 3 months ago

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

ncw commented 3 months ago

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...

willscott commented 3 months ago

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

willscott commented 3 months ago

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

ncw commented 3 months ago

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

ncw commented 3 months ago

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.

willscott commented 3 months ago

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.

willscott commented 3 months ago

@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

ncw commented 3 months ago

Alas this does not compile on Linux

github.com/willscott/go-nfs/file
# github.com/willscott/go-nfs/file
../../../../pkg/mod/github.com/willscott/go-nfs@v0.0.3-0.20240826094117-6dc01bc0f44d/file/file_unix.go:22:26: s.Atimespec undefined (type *"syscall".Stat_t has no field or method Atimespec)
../../../../pkg/mod/github.com/willscott/go-nfs@v0.0.3-0.20240826094117-6dc01bc0f44d/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.

willscott commented 3 months ago

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

ncw commented 3 months ago

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.

willscott commented 3 months ago

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.

ncw commented 3 months ago

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

willscott commented 3 months ago

Does the addition of exclusive create change office behavior?

ncw commented 3 months ago

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

ncw commented 3 months ago

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/go-nfs@v0.0.3-0.20240826115235-e7154b306671/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/go-nfs@v0.0.3-0.20240826115235-e7154b306671/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.

ncw commented 3 months ago

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= 2024/08/28 17:01:14 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147 2024/08/28 17:01:14 DEBUG : nfs: >FromHandle: path=[], err= 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= 2024/08/28 17:01:14 DEBUG : : >ReadDir: items=[824636002624], err= 2024/08/28 17:01:14 DEBUG : : Lstat: 2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err= 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= ``` 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= 2024/08/28 17:01:14 DEBUG : test.docx: Lstat: 2024/08/28 17:01:14 DEBUG : test.docx: >Lstat: fi=test.docx, err= 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= 2024/08/28 17:01:14 DEBUG : test.docx: Lstat: 2024/08/28 17:01:14 DEBUG : test.docx: >Lstat: fi=test.docx, err= 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= 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= ``` ``` 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= 2024/08/28 17:01:14 DEBUG : : Lstat: 2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:01:14 DEBUG : : Lstat: 2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:14 DEBUG : .ql_disablethumbnails: Lstat: 2024/08/28 17:01:14 DEBUG : .ql_disablethumbnails: >Lstat: fi=, 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= 2024/08/28 17:01:14 DEBUG : : Lstat: 2024/08/28 17:01:14 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:14 DEBUG : .ql_disablecache: Lstat: 2024/08/28 17:01:14 DEBUG : .ql_disablecache: >Lstat: fi=, 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= 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= ``` 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= 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= 2024/08/28 17:01:14 DEBUG : test.docx: >Open: fd=test.docx (rw), err= 2024/08/28 17:01:14 DEBUG : test.docx: >OpenFile: fd=test.docx (rw), err= 2024/08/28 17:01:14 DEBUG : test.docx: >Open: test.docx (rw), err= 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= 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= ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:01:19 DEBUG : : Lstat: 2024/08/28 17:01:19 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:01:24 DEBUG : : Lstat: 2024/08/28 17:01:24 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : Brochure.docx: Lstat: 2024/08/28 17:01:26 DEBUG : Brochure.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : DocTest.docx: Lstat: 2024/08/28 17:01:26 DEBUG : DocTest.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 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=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : Jul2024.docx: Lstat: 2024/08/28 17:01:26 DEBUG : Jul2024.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : Jul2024-a.docx: Lstat: 2024/08/28 17:01:26 DEBUG : Jul2024-a.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : Jul2024a.docx: Lstat: 2024/08/28 17:01:26 DEBUG : Jul2024a.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : Hgfghfh jgjhgj.docx: Lstat: 2024/08/28 17:01:26 DEBUG : Hgfghfh jgjhgj.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : hgjhg.docx: Lstat: 2024/08/28 17:01:26 DEBUG : hgjhg.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : asdasdasd.docx: Lstat: 2024/08/28 17:01:26 DEBUG : asdasdasd.docx: >Lstat: fi=, 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= 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= ``` ``` 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : 123.docx: Lstat: 2024/08/28 17:01:26 DEBUG : 123.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : test2.docx: Lstat: 2024/08/28 17:01:26 DEBUG : test2.docx: >Lstat: fi=, 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= 2024/08/28 17:01:26 DEBUG : : Lstat: 2024/08/28 17:01:26 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:01:26 DEBUG : test1.docx: Lstat: 2024/08/28 17:01:26 DEBUG : test1.docx: >Lstat: fi=, 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= 2024/08/28 17:01:29 DEBUG : : Lstat: 2024/08/28 17:01:29 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:01:34 DEBUG : : Lstat: 2024/08/28 17:01:34 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:01:39 DEBUG : : Lstat: 2024/08/28 17:01:39 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:01:44 DEBUG : : Lstat: 2024/08/28 17:01:44 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:01:49 DEBUG : : Lstat: 2024/08/28 17:01:49 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` ``` 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= 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= ``` 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= 2024/08/28 17:01:52 DEBUG : test.docx: Lstat: 2024/08/28 17:01:52 DEBUG : test.docx: >Lstat: fi=test.docx, err= 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:01:54 DEBUG : : Lstat: 2024/08/28 17:01:54 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:01:55 DEBUG : : Lstat: 2024/08/28 17:01:55 DEBUG : : >Lstat: fi=/, err= 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=, 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:01:59 DEBUG : : Lstat: 2024/08/28 17:01:59 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` 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= 2024/08/28 17:02:00 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147 2024/08/28 17:02:00 DEBUG : nfs: >FromHandle: path=[], err= 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= 2024/08/28 17:02:00 DEBUG : : >ReadDir: items=[824636002624], err= 2024/08/28 17:02:00 DEBUG : : Lstat: 2024/08/28 17:02:00 DEBUG : : >Lstat: fi=/, err= 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= ``` 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= 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= ``` ``` 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= 2024/08/28 17:02:04 DEBUG : : Lstat: 2024/08/28 17:02:04 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:09 DEBUG : : Lstat: 2024/08/28 17:02:09 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= 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= 2024/08/28 17:02:14 DEBUG : : Lstat: 2024/08/28 17:02:14 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:19 DEBUG : : Lstat: 2024/08/28 17:02:19 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:02:24 DEBUG : : Lstat: 2024/08/28 17:02:24 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:29 DEBUG : : Lstat: 2024/08/28 17:02:29 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:29 DEBUG : : Lstat: 2024/08/28 17:02:29 DEBUG : : >Lstat: fi=/, err= 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= 2024/08/28 17:02:29 DEBUG : test.docx: Lstat: 2024/08/28 17:02:29 DEBUG : test.docx: >Lstat: fi=test.docx, err= 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= 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= ``` 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= 2024/08/28 17:02:30 DEBUG : : Lstat: 2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:30 DEBUG : Untitled: Lstat: 2024/08/28 17:02:30 DEBUG : Untitled: >Lstat: fi=, 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= 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= ``` ``` 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= 2024/08/28 17:02:30 DEBUG : : Lstat: 2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:30 DEBUG : Untitled.docx: Lstat: 2024/08/28 17:02:30 DEBUG : Untitled.docx: >Lstat: fi=, 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= 2024/08/28 17:02:30 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147 2024/08/28 17:02:30 DEBUG : nfs: >FromHandle: path=[], err= 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= 2024/08/28 17:02:30 DEBUG : : >ReadDir: items=[824636002624], err= 2024/08/28 17:02:30 DEBUG : : Lstat: 2024/08/28 17:02:30 DEBUG : : >Lstat: fi=/, err= 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= ``` ``` 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= 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= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:02:34 DEBUG : : Lstat: 2024/08/28 17:02:34 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=, 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= 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=, err=file does not exist 2024/08/28 17:02:36 DEBUG : : Stat: 2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err= 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= 2024/08/28 17:02:36 DEBUG : test1.docx: >newRWFileHandle: err= 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= 2024/08/28 17:02:36 DEBUG : test1.docx: >OpenFile: fd=test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : test1.docx: >Create: test1.docx (rw), err= 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= ``` 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= 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= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=, 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= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= 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= 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= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= ``` 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= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=, 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= 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=, err=file does not exist 2024/08/28 17:02:36 DEBUG : : Stat: 2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Create: ._test1.docx (rw), err= 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= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` 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= 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= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._.: Lstat: 2024/08/28 17:02:36 DEBUG : ._.: >Lstat: fi=, 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= 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= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: ._test1.docx (rw), err= 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= 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= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= ``` 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= 2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147 2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err= 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= 2024/08/28 17:02:36 DEBUG : : >ReadDir: items=[824644485504 824636002624 824644485312], err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 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= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: Lstat: 2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Lstat: fi=, 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= 2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147 2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err= 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= 2024/08/28 17:02:36 DEBUG : : Stat: 2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err= 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 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= 2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=33B66ECA30BA44A99F03AC4385CBD356 2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 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= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=, 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= 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= ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` 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= 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= 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= 2024/08/28 17:02:36 DEBUG : .nfs.2005103d.05c2: >Remove: err= 2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=EF6F00FDB1BB4E7BBC697F9B6C40731D 2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test.docx: >Lstat: fi=, 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= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=, 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= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= 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= 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=, err=file does not exist 2024/08/28 17:02:36 DEBUG : : Stat: 2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >newRWFileHandle: err= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Create: ._test1.docx (rw), err= 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= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test1.docx: >Lstat: fi=test1.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: ._test1.docx (rw), err= 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= 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= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=._test1.docx, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: Lstat: 2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Lstat: fi=, 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= 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= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >OpenFile: fd=._test1.docx (rw), err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Open: ._test1.docx (rw), err= 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= 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= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : nfs: FromHandle: handle=A1C9D97847814F99ADB4B012E9F6A147 2024/08/28 17:02:36 DEBUG : nfs: >FromHandle: path=[], err= 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= 2024/08/28 17:02:36 DEBUG : : Stat: 2024/08/28 17:02:36 DEBUG : : >Stat: fi=/, err= 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 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= 2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=AB6D9C9E7EAA475AA20AFB7A6D8B1C14 2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 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= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 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= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test1.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test1.docx: >Lstat: fi=, 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= 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= 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= 2024/08/28 17:02:36 DEBUG : .nfs.2005103e.05c2: >Remove: err= 2024/08/28 17:02:36 DEBUG : nfs: InvalidateHandle: handle=DBB0F6C837674A83976658D99AA6E034 2024/08/28 17:02:36 DEBUG : nfs: >InvalidateHandle: err= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : ._test.docx: Lstat: 2024/08/28 17:02:36 DEBUG : ._test.docx: >Lstat: fi=, 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= 2024/08/28 17:02:36 DEBUG : test.docx: Lstat: 2024/08/28 17:02:36 DEBUG : test.docx: >Lstat: fi=test.docx, err= 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err= ``` ``` 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= 2024/08/28 17:02:36 DEBUG : : Lstat: 2024/08/28 17:02:36 DEBUG : : >Lstat: fi=/, err=

willscott commented 3 months ago

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

willscott commented 3 months ago

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 ?

ncw commented 3 months ago

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.

willscott commented 3 months ago

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

willscott commented 3 months ago

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.

willscott commented 3 months ago

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.

willscott / go-nfs

Could not edit Microsoft Office files from mountpoint #54