After a directory renmane using mv, files are not visible any longer

Jue_Sch · March 12, 2021, 2:28pm

RClone version v1.54.1 (can also see this with latest beta)

Mount command: rclone mount :s3:rclonejs /rclone222 -vv --s3-acl=private --s3-env-auth=false --s3-access-key-id=.. --s3-secret-access-key=.. --s3-endpoint=s3.us-south.cloud-object-storage.appdomain.cloud --s3-location-constraint=us-south-standard --debug-fuse -v --vfs-cache-mode writes

Created a directory structure :

/rclone222/FileTest/diraa/dira/test.txt and /rclone222/FileTest/diraa/dirb/test.txt

find /rclone222/FileTest -name "*.txt" shows me the 2 files

Now use mv to rename diraa to dira

This time the files are not found any longer. Directly opening the files using cat is also not working.

Then I remove the mount and mount again the same way.

Now I can run find again and this time the files are visible again

Note: In Object Storage the file are always at the right place.

Here logs from the mv action that renames the dir

I can see

2021/03/12 13:39:54 INFO : FileTest/diraa/dirb/test.txt: Deleted
2021/03/12 13:39:54 INFO : FileTest/diraa/dira/test.txt: Deleted

before

2021/03/12 13:39:54 DEBUG : FileTest/diraa: Updating dir with FileTest/dira 0xc0001fda40

So not sure if that is the reasons that then the files are missing

2021/03/12 13:39:53 DEBUG : FileTest/: Lookup: name="dira"
2021/03/12 13:39:53 DEBUG : FileTest/: >Lookup: node=, err=no such file or directory
2021/03/12 13:39:53 DEBUG : fuse: -> [ID=0x58] Lookup error=ENOENT
2021/03/12 13:39:53 DEBUG : fuse: <- Rename [ID=0x59 Node=0x2 Uid=0 Gid=0 Pid=248] from "diraa" to dirnode 0x2 "dira"
2021/03/12 13:39:53 DEBUG : FileTest/: Rename: oldName="diraa", newName="dira", newDir=FileTest/
2021/03/12 13:39:54 DEBUG : FileTest/diraa/dirb/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/12 13:39:54 INFO : FileTest/diraa/dirb/test.txt: Copied (server-side copy) to: FileTest/dira/dirb/test.txt
2021/03/12 13:39:54 DEBUG : FileTest/diraa/dira/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/12 13:39:54 INFO : FileTest/diraa/dira/test.txt: Copied (server-side copy) to: FileTest/dira/dira/test.txt
2021/03/12 13:39:54 INFO : FileTest/diraa/dirb/test.txt: Deleted
2021/03/12 13:39:54 INFO : FileTest/diraa/dira/test.txt: Deleted
2021/03/12 13:39:54 DEBUG : FileTest/diraa: Updating dir with FileTest/dira 0xc0001fda40
2021/03/12 13:39:54 DEBUG : FileTest/diraa: forgetting directory cache
2021/03/12 13:39:54 DEBUG : FileTest/diraa/dira: forgetting directory cache
2021/03/12 13:39:54 DEBUG : FileTest/diraa/dirb: forgetting directory cache
2021/03/12 13:39:54 DEBUG : FileTest: Added virtual directory entry vDel: "diraa"
2021/03/12 13:39:54 DEBUG : FileTest: Added virtual directory entry vAddDir: "dira"
2021/03/12 13:39:54 DEBUG : FileTest/: >Rename: err=
2021/03/12 13:39:54 DEBUG : fuse: -> [ID=0x59] Rename

Jue_Sch · March 12, 2021, 2:44pm

Also tried with cache mode full. Same result

2021/03/12 14:36:55 DEBUG : fuse: -> [ID=0x27] Rename
2021/03/12 14:36:58 DEBUG : fuse: <- Getattr [ID=0x28 Node=0x7 Uid=0 Gid=0 Pid=197] 0x0 fl=0
2021/03/12 14:36:58 DEBUG : FileTest3/diraa/: Attr: 
2021/03/12 14:36:58 DEBUG : FileTest3/diraa/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2021/03/12 14:36:58 DEBUG : fuse: -> [ID=0x28] Getattr valid=1s ino=18022753798890842924 size=0 mode=drwxr-xr-x
2021/03/12 14:36:58 DEBUG : fuse: <- Getattr [ID=0x29 Node=0x5 Uid=0 Gid=0 Pid=197] 0x0 fl=0
2021/03/12 14:36:58 DEBUG : FileTest3/dirb/: Attr: 
2021/03/12 14:36:58 DEBUG : FileTest3/dirb/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2021/03/12 14:36:58 DEBUG : fuse: -> [ID=0x29] Getattr valid=1s ino=9452878609347810604 size=0 mode=drwxr-xr-x
2021/03/12 14:36:58 DEBUG : fuse: <- Lookup [ID=0x2a Node=0x7 Uid=0 Gid=0 Pid=197] "dirb"
2021/03/12 14:36:58 DEBUG : FileTest3/diraa/: Lookup: name="dirb"
2021/03/12 14:36:58 DEBUG : FileTest3/diraa/: >Lookup: node=<nil>, err=no such file or directory
2021/03/12 14:36:58 DEBUG : fuse: -> [ID=0x2a] Lookup error=ENOENT
2021/03/12 14:36:58 DEBUG : fuse: <- Lookup [ID=0x2b Node=0x7 Uid=0 Gid=0 Pid=197] "dirb"
2021/03/12 14:36:58 DEBUG : FileTest3/diraa/: Lookup: name="dirb"
2021/03/12 14:36:58 DEBUG : FileTest3/diraa/: >Lookup: node=<nil>, err=no such file or directory
2021/03/12 14:36:58 DEBUG : fuse: -> [ID=0x2b] Lookup error=ENOENT
2021/03/12 14:36:58 DEBUG : fuse: <- Rename [ID=0x2c Node=0x2 Uid=0 Gid=0 Pid=197] from "dirb" to dirnode 0x7 "dirb"
2021/03/12 14:36:58 DEBUG : FileTest3/: Rename: oldName="dirb", newName="dirb", newDir=FileTest3/diraa/
2021/03/12 14:36:58 DEBUG : FileTest3/dirb/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/12 14:36:58 INFO  : FileTest3/dirb/test.txt: Copied (server-side copy) to: FileTest3/diraa/dirb/test.txt
2021/03/12 14:36:59 INFO  : FileTest3/dirb/test.txt: Deleted
2021/03/12 14:36:59 DEBUG : FileTest3/dirb: Updating dir with FileTest3/diraa/dirb 0xc000b8f5c0
2021/03/12 14:36:59 DEBUG : FileTest3/dirb: forgetting directory cache
2021/03/12 14:36:59 DEBUG : FileTest3/dirb: Removed virtual directory entry vAddFile: "test.txt"
2021/03/12 14:36:59 DEBUG : FileTest3: Added virtual directory entry vDel: "dirb"
2021/03/12 14:36:59 DEBUG : FileTest3/diraa: Added virtual directory entry vAddDir: "dirb"
2021/03/12 14:36:59 DEBUG : FileTest3/: >Rename: err=<nil>
2021/03/12 14:36:59 DEBUG : fuse: -> [ID=0x2c] Rename
2021/03/12 14:37:01 DEBUG : fuse: <- Getattr [ID=0x2d Node=0x2 Uid=0 Gid=0 Pid=199] 0x0 fl=0
2021/03/12 14:37:01 DEBUG : FileTest3/: Attr: 
2021/03/12 14:37:01 DEBUG : FileTest3/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x2d] Getattr valid=1s ino=4199606730257647187 size=0 mode=drwxr-xr-x
2021/03/12 14:37:01 DEBUG : fuse: <- Open [ID=0x2e Node=0x2 Uid=0 Gid=0 Pid=199] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x2e] Open 0x1 fl=0
2021/03/12 14:37:01 DEBUG : fuse: <- Read [ID=0x2f Node=0x2 Uid=0 Gid=0 Pid=199] 0x1 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : FileTest3/: ReadDirAll: 
2021/03/12 14:37:01 DEBUG : FileTest3/: >ReadDirAll: item=3, err=<nil>
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x2f] Read 96
2021/03/12 14:37:01 DEBUG : fuse: <- Read [ID=0x30 Node=0x2 Uid=0 Gid=0 Pid=199] 0x1 4096 @0x60 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x30] Read 0
2021/03/12 14:37:01 DEBUG : fuse: <- Getattr [ID=0x31 Node=0x7 Uid=0 Gid=0 Pid=199] 0x0 fl=0
2021/03/12 14:37:01 DEBUG : FileTest3/diraa/: Attr: 
2021/03/12 14:37:01 DEBUG : FileTest3/diraa/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x31] Getattr valid=1s ino=18022753798890842924 size=0 mode=drwxr-xr-x
2021/03/12 14:37:01 DEBUG : fuse: <- Open [ID=0x32 Node=0x7 Uid=0 Gid=0 Pid=199] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x32] Open 0x2 fl=0
2021/03/12 14:37:01 DEBUG : fuse: <- Read [ID=0x33 Node=0x7 Uid=0 Gid=0 Pid=199] 0x2 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : FileTest3/diraa/: ReadDirAll: 
2021/03/12 14:37:01 DEBUG : FileTest3/diraa/: >ReadDirAll: item=4, err=<nil>
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x33] Read 128
2021/03/12 14:37:01 DEBUG : fuse: <- Read [ID=0x34 Node=0x7 Uid=0 Gid=0 Pid=199] 0x2 4096 @0x80 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x34] Read 0
2021/03/12 14:37:01 DEBUG : fuse: <- Getattr [ID=0x35 Node=0x3 Uid=0 Gid=0 Pid=199] 0x0 fl=0
2021/03/12 14:37:01 DEBUG : FileTest3/diraa/dira/: Attr: 
2021/03/12 14:37:01 DEBUG : FileTest3/diraa/dira/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x35] Getattr valid=1s ino=9452881907882695237 size=0 mode=drwxr-xr-x
2021/03/12 14:37:01 DEBUG : fuse: <- Open [ID=0x36 Node=0x3 Uid=0 Gid=0 Pid=199] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : fuse: -> [ID=0x36] Open 0x3 fl=0
2021/03/12 14:37:01 DEBUG : fuse: <- Read [ID=0x37 Node=0x3 Uid=0 Gid=0 Pid=199] 0x3 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:01 DEBUG : FileTest3/diraa/dira/: ReadDirAll: 
2021/03/12 14:37:02 DEBUG : FileTest3/diraa/dira/: >ReadDirAll: item=3, err=<nil>
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x37] Read 96
2021/03/12 14:37:02 DEBUG : fuse: <- Read [ID=0x38 Node=0x3 Uid=0 Gid=0 Pid=199] 0x3 4096 @0x60 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x38] Read 0
2021/03/12 14:37:02 DEBUG : fuse: <- Release [ID=0x39 Node=0x3 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x39] Release
2021/03/12 14:37:02 DEBUG : fuse: <- Getattr [ID=0x3a Node=0x5 Uid=0 Gid=0 Pid=199] 0x0 fl=0
2021/03/12 14:37:02 DEBUG : FileTest3/diraa/dirb/: Attr: 
2021/03/12 14:37:02 DEBUG : FileTest3/diraa/dirb/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x3a] Getattr valid=1s ino=9452878609347810604 size=0 mode=drwxr-xr-x
2021/03/12 14:37:02 DEBUG : fuse: <- Open [ID=0x3b Node=0x5 Uid=0 Gid=0 Pid=199] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x3b] Open 0x3 fl=0
2021/03/12 14:37:02 DEBUG : fuse: <- Read [ID=0x3c Node=0x5 Uid=0 Gid=0 Pid=199] 0x3 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:02 DEBUG : FileTest3/diraa/dirb/: ReadDirAll: 

2021/03/12 14:37:02 DEBUG : FileTest3/diraa/dirb/: >ReadDirAll: item=3, err=<nil>
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x3c] Read 96
2021/03/12 14:37:02 DEBUG : fuse: <- Read [ID=0x3d Node=0x5 Uid=0 Gid=0 Pid=199] 0x3 4096 @0x60 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x3d] Read 0
2021/03/12 14:37:02 DEBUG : fuse: <- Release [ID=0x3e Node=0x5 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x3e] Release
2021/03/12 14:37:02 DEBUG : fuse: <- Release [ID=0x3f Node=0x7 Uid=0 Gid=0 Pid=0] 0x2 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x3f] Release
2021/03/12 14:37:02 DEBUG : fuse: <- Release [ID=0x40 Node=0x2 Uid=0 Gid=0 Pid=0] 0x1 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/12 14:37:02 DEBUG : fuse: -> [ID=0x40] Release
2021/03/12 14:37:05 DEBUG : fuse: <- Lookup [ID=0x41 Node=0x2 Uid=0 Gid=0 Pid=201] "dira"
2021/03/12 14:37:05 DEBUG : FileTest3/: Lookup: name="dira"
2021/03/12 14:37:05 DEBUG : FileTest3/: >Lookup: node=<nil>, err=no such file or directory
2021/03/12 14:37:05 DEBUG : fuse: -> [ID=0x41] Lookup error=ENOENT
2021/03/12 14:37:05 DEBUG : fuse: <- Getattr [ID=0x42 Node=0x7 Uid=0 Gid=0 Pid=201] 0x0 fl=0
2021/03/12 14:37:05 DEBUG : FileTest3/diraa/: Attr: 
2021/03/12 14:37:05 DEBUG : FileTest3/diraa/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2021/03/12 14:37:05 DEBUG : fuse: -> [ID=0x42] Getattr valid=1s ino=18022753798890842924 size=0 mode=drwxr-xr-x
2021/03/12 14:37:05 DEBUG : fuse: <- Lookup [ID=0x43 Node=0x2 Uid=0 Gid=0 Pid=201] "dira"
2021/03/12 14:37:05 DEBUG : FileTest3/: Lookup: name="dira"
2021/03/12 14:37:05 DEBUG : FileTest3/: >Lookup: node=<nil>, err=no such file or directory
2021/03/12 14:37:05 DEBUG : fuse: -> [ID=0x43] Lookup error=ENOENT
2021/03/12 14:37:05 DEBUG : fuse: <- Lookup [ID=0x44 Node=0x2 Uid=0 Gid=0 Pid=201] "dira"
2021/03/12 14:37:05 DEBUG : FileTest3/: Lookup: name="dira"
2021/03/12 14:37:05 DEBUG : FileTest3/: >Lookup: node=<nil>, err=no such file or directory
2021/03/12 14:37:05 DEBUG : fuse: -> [ID=0x44] Lookup error=ENOENT
2021/03/12 14:37:05 DEBUG : fuse: <- Rename [ID=0x45 Node=0x2 Uid=0 Gid=0 Pid=201] from "diraa" to dirnode 0x2 "dira"
2021/03/12 14:37:05 DEBUG : FileTest3/: Rename: oldName="diraa", newName="dira", newDir=FileTest3/
2021/03/12 14:37:05 DEBUG : FileTest3/diraa/dirb/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/12 14:37:05 INFO  : FileTest3/diraa/dirb/test.txt: Copied (server-side copy) to: FileTest3/dira/dirb/test.txt
2021/03/12 14:37:05 INFO  : FileTest3/diraa/dirb/test.txt: Deleted
2021/03/12 14:37:06 DEBUG : FileTest3/diraa/dira/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/12 14:37:06 INFO  : FileTest3/diraa/dira/test.txt: Copied (server-side copy) to: FileTest3/dira/dira/test.txt
2021/03/12 14:37:06 INFO  : FileTest3/diraa/dira/test.txt: Deleted
2021/03/12 14:37:06 DEBUG : FileTest3/diraa: Updating dir with FileTest3/dira 0xc000b8f980
2021/03/12 14:37:06 DEBUG : FileTest3/diraa: forgetting directory cache
2021/03/12 14:37:06 DEBUG : FileTest3/diraa/dirb: forgetting directory cache
2021/03/12 14:37:06 DEBUG : FileTest3/diraa/dira: forgetting directory cache
2021/03/12 14:37:06 DEBUG : FileTest3: Added virtual directory entry vDel: "diraa"
2021/03/12 14:37:06 DEBUG : FileTest3: Added virtual directory entry vAddDir: "dira"
2021/03/12 14:37:06 DEBUG : FileTest3/: >Rename: err=<nil>
2021/03/12 14:37:06 DEBUG : fuse: -> [ID=0x45] Rename

ncw · March 12, 2021, 6:19pm

I'm having trouble replicating this.

Can you show exactly how you created the files and the exact mv command you ran - thank you

Jue_Sch · March 15, 2021, 1:15pm

Hi,

I did some further testing and here the results:

This works every time as expected

mkdir $filepath
mkdir $filepath/diraa
mkdir $filepath/diraa/dira
mkdir $filepath/diraa/dirb
echo "test" >> $filepath/diraa/dira/test.txt
echo "test" >> $filepath/diraa/dirb/test.txt

echo "Find Before:"
find $filepath -name "*.txt"

mv $filepath/diraa $filepath/dira

echo "Find After:"
find $filepath -name "*.txt"

and returns

Find Before:
/rclone222/FileTest14_06/diraa/dira/test.txt
/rclone222/FileTest14_06/diraa/dirb/test.txt
Find After:
/rclone222/FileTest14_06/dira/dira/test.txt
/rclone222/FileTest14_06/dira/dirb/test.txt

However, this causes issues all the times but sometimes with different outcomes

mkdir $filepath2
mkdir $filepath2/dira
echo "test" >> $filepath2/dira/test.txt
cp -R $filepath2/dira $filepath2/dirb
mkdir $filepath2/diraa
mv $filepath2/dira $filepath2/diraa
mv $filepath2/dirb $filepath2/diraa

echo "Find Before:"
find $filepath2 -name "*.txt"

mv $filepath2/diraa $filepath2/dira

echo "Find After:"
find $filepath2 -name "*.txt"

this gives

Find Before:
/rclone222/FileTest14_06_2/diraa/dira/test.txt
/rclone222/FileTest14_06_2/diraa/dirb/test.txt
Find After:
/rclone222/FileTest14_06_2/dira/test.txt

However, I am pretty sure that before it also was empty, so I assume this might be related to the speed of the backend object storage and depending on how fast things are, it might have different impacts

Note, in Object Storage the structure is

FileTest14_06_2/dira/test.txt
FileTest14_06_2/dirb/test.txt

which is also not right, but shows that the results of find does also not line up with Object Storage state.
On the local filesystem this gives

Find Before:
/FileTest_local/diraa/dirb/test.txt
/FileTest_local/diraa/dira/test.txt

Find After:
/FileTest_local/dira/dirb/test.txt
/FileTest_local/dira/dira/test.txt

which is expected

Additional Note: If I run the problematic code multiple times , I start to see

Find Before:
/rclone222/FileTest14_06_2/diraa/dira/test.txt
find: File system loop detected; ‘/rclone222/FileTest14_06_2/diraa/dira/dira’ is part of the same file system loop as ‘/rclone222/FileTest14_06_2/diraa/dira’.
/rclone222/FileTest14_06_2/diraa/dira/dirb/test.txt
/rclone222/FileTest14_06_2/diraa/dirb/dira/test.txt
/rclone222/FileTest14_06_2/diraa/dirb/test.txt
Find After:
/rclone222/FileTest14_06_2/dira/test.txt
find: File system loop detected; ‘/rclone222/FileTest14_06_2/dira/dira/dira’ is part of the same file system loop as ‘/rclone222/FileTest14_06_2/dira/dira’.
/rclone222/FileTest14_06_2/dira/dirb/dira/test.txt

ncw · March 15, 2021, 5:45pm

Very useful - thank you.

I'll have a go with it and report back whether I can repro.

ncw · March 16, 2021, 11:16am

I managed to reproduce this like this

$ mkdir -p /mnt/tmp/FileTest/diraa/dira/
$ echo hello > /mnt/tmp/FileTest/diraa/dira/test.txt
$ mkdir -p /mnt/tmp/FileTest/diraa/dirb #/test.txt
$ echo hello2 > /mnt/tmp/FileTest/diraa/dirb/test.txt
$ find /mnt/tmp/FileTest -name "*.txt"
/mnt/tmp/FileTest/diraa/dira/test.txt
/mnt/tmp/FileTest/diraa/dirb/test.txt
$ mv /mnt/tmp/FileTest/diraa /mnt/tmp/FileTest/dira
$ find /mnt/tmp/FileTest -name "*.txt"
$ rclone lsl s3:rclone/FileTest
        6 2021-03-16 09:32:50.656651287 dira/dira/test.txt
        7 2021-03-16 09:33:38.557192131 dira/dirb/test.txt

The log from the rename is

mv first finds the things it is operating on and checks the destination doesn't exist

2021/03/16 09:34:57 DEBUG : fuse: <- Lookup [ID=0x6e Node=0x1 Uid=1000 Gid=1000 Pid=3514212] "FileTest"
2021/03/16 09:34:57 DEBUG : /: Lookup: name="FileTest"
2021/03/16 09:34:57 DEBUG : /: >Lookup: node=FileTest/, err=<nil>
2021/03/16 09:34:57 DEBUG : FileTest/: Attr: 
2021/03/16 09:34:57 DEBUG : FileTest/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/03/16 09:34:57 DEBUG : fuse: -> [ID=0x6e] Lookup 0x2 gen=0 valid=1s attr={valid=1s ino=12907864677946988754 size=0 mode=drwxrwxr-x}
2021/03/16 09:34:57 DEBUG : fuse: <- Lookup [ID=0x70 Node=0x2 Uid=1000 Gid=1000 Pid=3514212] "diraa"
2021/03/16 09:34:57 DEBUG : FileTest/: Lookup: name="diraa"
2021/03/16 09:34:57 DEBUG : FileTest/: >Lookup: node=FileTest/diraa/, err=<nil>
2021/03/16 09:34:57 DEBUG : FileTest/diraa/: Attr: 
2021/03/16 09:34:57 DEBUG : FileTest/diraa/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/03/16 09:34:57 DEBUG : fuse: -> [ID=0x70] Lookup 0x3 gen=0 valid=1s attr={valid=1s ino=12767495182912600437 size=0 mode=drwxrwxr-x}
2021/03/16 09:34:57 DEBUG : fuse: <- Lookup [ID=0x72 Node=0x2 Uid=1000 Gid=1000 Pid=3514212] "dira"
2021/03/16 09:34:57 DEBUG : FileTest/: Lookup: name="dira"
2021/03/16 09:34:57 DEBUG : FileTest/: >Lookup: node=<nil>, err=no such file or directory
2021/03/16 09:34:57 DEBUG : fuse: -> [ID=0x72] Lookup error=ENOENT
2021/03/16 09:34:57 DEBUG : fuse: <- Lookup [ID=0x74 Node=0x2 Uid=1000 Gid=1000 Pid=3514212] "dira"
2021/03/16 09:34:57 DEBUG : FileTest/: Lookup: name="dira"
2021/03/16 09:34:57 DEBUG : FileTest/: >Lookup: node=<nil>, err=no such file or directory
2021/03/16 09:34:57 DEBUG : fuse: -> [ID=0x74] Lookup error=ENOENT
2021/03/16 09:34:57 DEBUG : fuse: <- Lookup [ID=0x76 Node=0x2 Uid=1000 Gid=1000 Pid=3514212] "dira"
2021/03/16 09:34:57 DEBUG : FileTest/: Lookup: name="dira"
2021/03/16 09:34:57 DEBUG : FileTest/: >Lookup: node=<nil>, err=no such file or directory
2021/03/16 09:34:57 DEBUG : fuse: -> [ID=0x76] Lookup error=ENOENT

Then mv does the rename which involves server side copying the objects

2021/03/16 09:34:57 DEBUG : fuse: <- Rename [ID=0x78 Node=0x2 Uid=1000 Gid=1000 Pid=3514212] from "diraa" to dirnode 0x2 "dira"
2021/03/16 09:34:57 DEBUG : FileTest/: Rename: oldName="diraa", newName="dira", newDir=FileTest/
2021/03/16 09:34:57 DEBUG : FileTest/diraa/dira/test.txt: MD5 = b1946ac92492d2347c6235b4d2611184 OK
2021/03/16 09:34:57 INFO  : FileTest/diraa/dira/test.txt: Copied (server-side copy) to: FileTest/dira/dira/test.txt
2021/03/16 09:34:57 DEBUG : FileTest/diraa/dirb/test.txt: MD5 = a10edbbb8f28f8e98ee6b649ea2556f4 OK
2021/03/16 09:34:57 INFO  : FileTest/diraa/dirb/test.txt: Copied (server-side copy) to: FileTest/dira/dirb/test.txt
2021/03/16 09:34:57 INFO  : FileTest/diraa/dira/test.txt: Deleted
2021/03/16 09:34:57 INFO  : FileTest/diraa/dirb/test.txt: Deleted
2021/03/16 09:34:57 DEBUG : FileTest/diraa: Updating dir with FileTest/dira 0xc000b18180
2021/03/16 09:34:57 DEBUG : FileTest/diraa: forgetting directory cache
2021/03/16 09:34:57 DEBUG : FileTest/diraa/dirb: forgetting directory cache
2021/03/16 09:34:57 DEBUG : FileTest/diraa/dirb: Removed virtual directory entry vAddFile: "test.txt"
2021/03/16 09:34:57 DEBUG : FileTest/diraa/dira: forgetting directory cache
2021/03/16 09:34:57 DEBUG : FileTest/diraa/dira: Removed virtual directory entry vAddFile: "test.txt"
2021/03/16 09:34:57 DEBUG : FileTest: Added virtual directory entry vDel: "diraa"
2021/03/16 09:34:57 DEBUG : FileTest: Added virtual directory entry vAddDir: "dira"
2021/03/16 09:34:57 DEBUG : FileTest/: >Rename: err=<nil>
2021/03/16 09:34:57 DEBUG : fuse: -> [ID=0x78] Rename

That all looked good

2021/03/16 09:35:02 DEBUG : fuse: <- Lookup [ID=0x7a Node=0x1 Uid=1000 Gid=1000 Pid=3514213] "FileTest"
2021/03/16 09:35:02 DEBUG : /: Lookup: name="FileTest"
2021/03/16 09:35:02 DEBUG : /: >Lookup: node=FileTest/, err=<nil>
2021/03/16 09:35:02 DEBUG : FileTest/: Attr: 
2021/03/16 09:35:02 DEBUG : FileTest/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x7a] Lookup 0x2 gen=0 valid=1s attr={valid=1s ino=12907864677946988754 size=0 mode=drwxrwxr-x}
2021/03/16 09:35:02 DEBUG : fuse: <- Open [ID=0x7c Node=0x2 Uid=1000 Gid=1000 Pid=3514213] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x7c] Open 0x2 fl=0
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x7e Node=0x2 Uid=1000 Gid=1000 Pid=3514213] 0x2 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : FileTest/: ReadDirAll: 
2021/03/16 09:35:02 DEBUG : FileTest/: >ReadDirAll: item=3, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x7e] Read 96
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x80 Node=0x2 Uid=1000 Gid=1000 Pid=3514213] 0x2 4096 @0x60 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x80] Read 0
2021/03/16 09:35:02 DEBUG : fuse: <- Lookup [ID=0x82 Node=0x2 Uid=1000 Gid=1000 Pid=3514213] "dira"
2021/03/16 09:35:02 DEBUG : FileTest/: Lookup: name="dira"
2021/03/16 09:35:02 DEBUG : FileTest/: >Lookup: node=FileTest/dira/, err=<nil>
2021/03/16 09:35:02 DEBUG : FileTest/dira/: Attr: 
2021/03/16 09:35:02 DEBUG : FileTest/dira/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x82] Lookup 0x3 gen=0 valid=1s attr={valid=1s ino=7751488938101355606 size=0 mode=drwxrwxr-x}
2021/03/16 09:35:02 DEBUG : fuse: <- Open [ID=0x84 Node=0x3 Uid=1000 Gid=1000 Pid=3514213] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x84] Open 0x1 fl=0
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x86 Node=0x3 Uid=1000 Gid=1000 Pid=3514213] 0x1 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : FileTest/dira/: ReadDirAll: 
2021/03/16 09:35:02 DEBUG : FileTest/dira: Removed virtual directory entry vAddDir: "dira"
2021/03/16 09:35:02 DEBUG : FileTest/dira: Removed virtual directory entry vAddDir: "dirb"
2021/03/16 09:35:02 DEBUG : FileTest/dira/: >ReadDirAll: item=4, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x86] Read 128
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x88 Node=0x3 Uid=1000 Gid=1000 Pid=3514213] 0x1 4096 @0x80 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x88] Read 0

Here is where the problem is. The client looks up FileTest/dira/ but gets a node back which has a path FileTest/diraa/dira in which is the old path.

2021/03/16 09:35:02 DEBUG : fuse: <- Lookup [ID=0x8a Node=0x3 Uid=1000 Gid=1000 Pid=3514213] "dira"
2021/03/16 09:35:02 DEBUG : FileTest/dira/: Lookup: name="dira"
2021/03/16 09:35:02 DEBUG : FileTest/dira/: >Lookup: node=FileTest/diraa/dira/, err=<nil>
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dira/: Attr: 
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dira/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x8a] Lookup 0x4 gen=0 valid=1s attr={valid=1s ino=13655602113203163872 size=0 mode=drwxrwxr-x}
2021/03/16 09:35:02 DEBUG : fuse: <- Open [ID=0x8c Node=0x4 Uid=1000 Gid=1000 Pid=3514213] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x8c] Open 0x3 fl=0
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x8e Node=0x4 Uid=1000 Gid=1000 Pid=3514213] 0x3 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dira/: ReadDirAll: 
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dira/: >ReadDirAll: item=2, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x8e] Read 64
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x90 Node=0x4 Uid=1000 Gid=1000 Pid=3514213] 0x3 4096 @0x40 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x90] Read 0
2021/03/16 09:35:02 DEBUG : fuse: <- Release [ID=0x92 Node=0x4 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x92] Release
2021/03/16 09:35:02 DEBUG : fuse: <- Lookup [ID=0x94 Node=0x3 Uid=1000 Gid=1000 Pid=3514213] "dirb"
2021/03/16 09:35:02 DEBUG : FileTest/dira/: Lookup: name="dirb"
2021/03/16 09:35:02 DEBUG : FileTest/dira/: >Lookup: node=FileTest/diraa/dirb/, err=<nil>
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dirb/: Attr: 
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dirb/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x94] Lookup 0x6 gen=0 valid=1s attr={valid=1s ino=13655605411738048505 size=0 mode=drwxrwxr-x}
2021/03/16 09:35:02 DEBUG : fuse: <- Open [ID=0x96 Node=0x6 Uid=1000 Gid=1000 Pid=3514213] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x96] Open 0x3 fl=0
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x98 Node=0x6 Uid=1000 Gid=1000 Pid=3514213] 0x3 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dirb/: ReadDirAll: 
2021/03/16 09:35:02 DEBUG : FileTest/diraa/dirb/: >ReadDirAll: item=2, err=<nil>
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x98] Read 64
2021/03/16 09:35:02 DEBUG : fuse: <- Read [ID=0x9a Node=0x6 Uid=1000 Gid=1000 Pid=3514213] 0x3 4096 @0x40 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x9a] Read 0
2021/03/16 09:35:02 DEBUG : fuse: <- Release [ID=0x9c Node=0x6 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x9c] Release
2021/03/16 09:35:02 DEBUG : fuse: <- Release [ID=0x9e Node=0x3 Uid=0 Gid=0 Pid=0] 0x1 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0x9e] Release
2021/03/16 09:35:02 DEBUG : fuse: <- Release [ID=0xa0 Node=0x2 Uid=0 Gid=0 Pid=0] 0x2 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 09:35:02 DEBUG : fuse: -> [ID=0xa0] Release

I'm pretty sure this is the same issue as

It doesn't reproduce with rclone cmount instead of rclone mount

Also if you do sync; echo 2 > /proc/sys/vm/drop_caches just before the mv it works properly.

Jue_Sch · March 16, 2021, 1:09pm

Hello. Thanks for your fast answer. When you say " It doesn't reproduce with rclone cmount"
does that suggest that I should use cmount or just a hint for those in the community that know the difference?

In case the suggestion is to use cmount, can I assume it uses the same config props or is it something on its own?

Just asking as I did not find any reference of cmount in the docu and search hits point to this forum entries and to one entry in which it sounds like it is based on some special go fuse library.

ncw · March 16, 2021, 1:31pm

You could use rclone cmount but it isn't standard compile for linux (on Windows and macOS rclone mount is rclone cmount).

I think I've managed to fix this however

Can you have a go with

v1.55.0-beta.5303.b48137c9b.fix-4977-mount-caching on branch fix-4977-mount-caching (uploaded in 15-30 mins)

Jue_Sch · March 16, 2021, 2:25pm

I tried the new build but it does not seem to solve my issue.

Run this code

mkdir $filepath2
mkdir $filepath2/dira
echo "test" >> $filepath2/dira/test.txt
cp -R $filepath2/dira $filepath2/dirb
mkdir $filepath2/diraa
mv $filepath2/dira $filepath2/diraa
mv $filepath2/dirb $filepath2/diraa

echo "Find Before:"
find $filepath2 -name "*.txt"

date
mv $filepath2/diraa $filepath2/dira

echo "Find After:"
find $filepath2 -name "*.txt"

Showed me

Find Before:
/rclone222/March16_3/diraa/dira/test.txt
/rclone222/March16_3/diraa/dirb/test.txt
Tue Mar 16 14:14:45 UTC 2021
Find After:
/rclone222/March16_3/dira/test.txt

Copied everything starting at 14:14:45 in the log

2021/03/16 14:14:45 DEBUG : March16_3/dira/test.txt: vfs cache: starting upload
2021/03/16 14:14:45 DEBUG : March16_3/dirb/test.txt: vfs cache: starting upload
2021/03/16 14:14:45 DEBUG : fuse: <- Lookup [ID=0x1bc Node=0x9 Uid=0 Gid=0 Pid=352] "dira"
2021/03/16 14:14:45 DEBUG : March16_3/: Lookup: name="dira"
2021/03/16 14:14:45 DEBUG : March16_3/: >Lookup: node=, err=no such file or directory
2021/03/16 14:14:45 DEBUG : fuse: -> [ID=0x1bc] Lookup error=ENOENT
2021/03/16 14:14:45 DEBUG : fuse: <- Getattr [ID=0x1bd Node=0x11 Uid=0 Gid=0 Pid=352] 0x0 fl=0
2021/03/16 14:14:45 DEBUG : March16_3/diraa/: Attr:
2021/03/16 14:14:45 DEBUG : March16_3/diraa/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:14:45 DEBUG : fuse: -> [ID=0x1bd] Getattr valid=1s ino=5480878212243221313 size=0 mode=drwxr-xr-x
2021/03/16 14:14:45 DEBUG : fuse: <- Lookup [ID=0x1be Node=0x9 Uid=0 Gid=0 Pid=352] "dira"
2021/03/16 14:14:45 DEBUG : March16_3/: Lookup: name="dira"
2021/03/16 14:14:45 DEBUG : March16_3/: >Lookup: node=, err=no such file or directory
2021/03/16 14:14:45 DEBUG : fuse: -> [ID=0x1be] Lookup error=ENOENT
2021/03/16 14:14:45 DEBUG : fuse: <- Lookup [ID=0x1bf Node=0x9 Uid=0 Gid=0 Pid=352] "dira"
2021/03/16 14:14:45 DEBUG : March16_3/: Lookup: name="dira"
2021/03/16 14:14:45 DEBUG : March16_3/: >Lookup: node=, err=no such file or directory
2021/03/16 14:14:45 DEBUG : fuse: -> [ID=0x1bf] Lookup error=ENOENT
2021/03/16 14:14:45 DEBUG : fuse: <- Rename [ID=0x1c0 Node=0x9 Uid=0 Gid=0 Pid=352] from "diraa" to dirnode 0x9 "dira"
2021/03/16 14:14:45 DEBUG : March16_3/: Rename: oldName="diraa", newName="dira", newDir=March16_3/
2021/03/16 14:14:45 DEBUG : March16_3/diraa: Updating dir with March16_3/dira 0xc000646b40
2021/03/16 14:14:45 DEBUG : March16_3/diraa: forgetting directory cache
2021/03/16 14:14:45 DEBUG : March16_3/diraa/dira: forgetting directory cache
2021/03/16 14:14:45 DEBUG : March16_3/diraa/dirb: forgetting directory cache
2021/03/16 14:14:45 DEBUG : March16_3: Added virtual directory entry vDel: "diraa"
2021/03/16 14:14:45 DEBUG : March16_3: Added virtual directory entry vAddDir: "dira"
2021/03/16 14:14:45 DEBUG : March16_3/: >Rename: err=
2021/03/16 14:14:45 DEBUG : fuse: -> [ID=0x1c0] Rename
2021/03/16 14:14:45 DEBUG : fuse: => InvalidateEntry 0x9 "diraa" Err:node not cached
2021/03/16 14:14:45 DEBUG : fuse: => InvalidateEntry 0x9 "dira"
2021/03/16 14:14:45 DEBUG : fuse: <- BatchForget [ID=0x1c1 Node=0x0 Uid=0 Gid=0 Pid=0] 16x1 15x1 17x1
2021/03/16 14:14:45 DEBUG : fuse: -> [ID=0x1c1] BatchForget
2021/03/16 14:14:45 DEBUG : March16_3/dirb/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/16 14:14:45 INFO : March16_3/dirb/test.txt: Copied (new)
2021/03/16 14:14:45 DEBUG : March16_3/dirb/test.txt: vfs cache: fingerprint now "5,2021-03-16 14:14:40.624749034 +0000 UTC,d8e8fca2dc0f896fd7cb4cb0031ba249"
2021/03/16 14:14:45 DEBUG : March16_3/dirb/test.txt: vfs cache: writeback object to VFS layer
2021/03/16 14:14:45 DEBUG : March16_3/diraa/dirb: Added virtual directory entry vAddFile: "test.txt"
2021/03/16 14:14:45 INFO : March16_3/dirb/test.txt: vfs cache: upload succeeded try #1
2021/03/16 14:14:46 DEBUG : March16_3/dira/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/16 14:14:46 INFO : March16_3/dira/test.txt: Copied (new)
2021/03/16 14:14:46 DEBUG : March16_3/dira/test.txt: vfs cache: fingerprint now "5,2021-03-16 14:14:39.762885256 +0000 UTC,d8e8fca2dc0f896fd7cb4cb0031ba249"
2021/03/16 14:14:46 DEBUG : March16_3/dira/test.txt: vfs cache: writeback object to VFS layer
2021/03/16 14:14:46 DEBUG : March16_3/diraa/dira: Added virtual directory entry vAddFile: "test.txt"
2021/03/16 14:14:46 INFO : March16_3/dira/test.txt: vfs cache: upload succeeded try #1
2021/03/16 14:14:47 DEBUG : fuse: <- Getattr [ID=0x1c2 Node=0x9 Uid=0 Gid=0 Pid=356] 0x0 fl=0
2021/03/16 14:14:47 DEBUG : March16_3/: Attr:
2021/03/16 14:14:47 DEBUG : March16_3/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c2] Getattr valid=1s ino=11301525552890248942 size=0 mode=drwxr-xr-x
2021/03/16 14:14:47 DEBUG : fuse: <- Open [ID=0x1c3 Node=0x9 Uid=0 Gid=0 Pid=356] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c3] Open 0x1 fl=0
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1c4 Node=0x9 Uid=0 Gid=0 Pid=356] 0x1 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : March16_3/: ReadDirAll:
2021/03/16 14:14:47 DEBUG : March16_3/: >ReadDirAll: item=3, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c4] Read 96
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1c5 Node=0x9 Uid=0 Gid=0 Pid=356] 0x1 4096 @0x60 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c5] Read 0
2021/03/16 14:14:47 DEBUG : fuse: <- Lookup [ID=0x1c6 Node=0x9 Uid=0 Gid=0 Pid=356] "dira"
2021/03/16 14:14:47 DEBUG : March16_3/: Lookup: name="dira"
2021/03/16 14:14:47 DEBUG : March16_3/: >Lookup: node=March16_3/dira/, err=
2021/03/16 14:14:47 DEBUG : March16_3/dira/: Attr:
2021/03/16 14:14:47 DEBUG : March16_3/dira/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c6] Lookup 0x11 gen=15 valid=1s attr={valid=1s ino=8624498603692088666 size=0 mode=drwxr-xr-x}
2021/03/16 14:14:47 DEBUG : fuse: <- Open [ID=0x1c7 Node=0x11 Uid=0 Gid=0 Pid=356] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c7] Open 0x3 fl=0
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1c8 Node=0x11 Uid=0 Gid=0 Pid=356] 0x3 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : March16_3/dira/: ReadDirAll:
2021/03/16 14:14:47 DEBUG : March16_3/dira/: >ReadDirAll: item=5, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c8] Read 160
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1c9 Node=0x11 Uid=0 Gid=0 Pid=356] 0x3 4096 @0xa0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1c9] Read 0
2021/03/16 14:14:47 DEBUG : fuse: <- Lookup [ID=0x1ca Node=0x11 Uid=0 Gid=0 Pid=356] "dira"
2021/03/16 14:14:47 DEBUG : March16_3/dira/: Lookup: name="dira"
2021/03/16 14:14:47 DEBUG : March16_3/dira/: >Lookup: node=March16_3/diraa/dira/, err=
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dira/: Attr:
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dira/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1ca] Lookup 0xf gen=16 valid=1s attr={valid=1s ino=14882351580851647878 size=0 mode=drwxr-xr-x}
2021/03/16 14:14:47 DEBUG : fuse: <- Open [ID=0x1cb Node=0xf Uid=0 Gid=0 Pid=356] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1cb] Open 0x2 fl=0
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1cc Node=0xf Uid=0 Gid=0 Pid=356] 0x2 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dira/: ReadDirAll:
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dira: Removed virtual directory entry vAddFile: "test.txt"
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dira/: >ReadDirAll: item=2, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1cc] Read 64
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1cd Node=0xf Uid=0 Gid=0 Pid=356] 0x2 4096 @0x40 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1cd] Read 0
2021/03/16 14:14:47 DEBUG : fuse: <- Release [ID=0x1ce Node=0xf Uid=0 Gid=0 Pid=0] 0x2 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1ce] Release
2021/03/16 14:14:47 DEBUG : fuse: <- Lookup [ID=0x1cf Node=0x11 Uid=0 Gid=0 Pid=356] "dirb"
2021/03/16 14:14:47 DEBUG : March16_3/dira/: Lookup: name="dirb"
2021/03/16 14:14:47 DEBUG : March16_3/dira/: >Lookup: node=March16_3/diraa/dirb/, err=
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dirb/: Attr:
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dirb/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1cf] Lookup 0x10 gen=17 valid=1s attr={valid=1s ino=14882350481340019667 size=0 mode=drwxr-xr-x}
2021/03/16 14:14:47 DEBUG : fuse: <- Open [ID=0x1d0 Node=0x10 Uid=0 Gid=0 Pid=356] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1d0] Open 0x2 fl=0
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1d1 Node=0x10 Uid=0 Gid=0 Pid=356] 0x2 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dirb/: ReadDirAll:

2021/03/16 14:14:47 DEBUG : March16_3/diraa/dirb: Removed virtual directory entry vAddFile: "test.txt"
2021/03/16 14:14:47 DEBUG : March16_3/diraa/dirb/: >ReadDirAll: item=2, err=
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1d1] Read 64
2021/03/16 14:14:47 DEBUG : fuse: <- Read [ID=0x1d2 Node=0x10 Uid=0 Gid=0 Pid=356] 0x2 4096 @0x40 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1d2] Read 0
2021/03/16 14:14:47 DEBUG : fuse: <- Release [ID=0x1d3 Node=0x10 Uid=0 Gid=0 Pid=0] 0x2 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1d3] Release
2021/03/16 14:14:47 DEBUG : fuse: <- Release [ID=0x1d4 Node=0x11 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1d4] Release
2021/03/16 14:14:47 DEBUG : fuse: <- Release [ID=0x1d5 Node=0x9 Uid=0 Gid=0 Pid=0] 0x1 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:14:47 DEBUG : fuse: -> [ID=0x1d5] Release

!rclone mount :s3:rclonejs /rclone333 -vv --s3-acl=private --s3-env-auth=false --s3-access-key-id=75aab79105c744a39d8eef33644b78a2 --s3-secret-access-key=e1a06601ba1280a4f1193ab7d1319abb8485bb8c788042ad --s3-endpoint=s3.us-south.cloud-object-storage.appdomain.cloud --s3-location-constraint=us-south-standard --debug-fuse -v --vfs-cache-mode writes

2021/03/12 08:59:53 DEBUG : rclone: Version "v1.55.0-beta.5249.59ed70ca9" starting with par

Jue_Sch · March 16, 2021, 2:38pm

I also now paused between all the commands for at least 5 seconds to wait till the cache writes and see this behaviour

Find after is empty and here are the logs

2021/03/16 14:34:13 DEBUG : fuse: <- Lookup [ID=0x256 Node=0x1 Uid=0 Gid=0 Pid=392] "March16_7"
2021/03/16 14:34:13 DEBUG : /: Lookup: name="March16_7"
2021/03/16 14:34:13 DEBUG : /: >Lookup: node=March16_7/, err=
2021/03/16 14:34:13 DEBUG : March16_7/: Attr:
2021/03/16 14:34:13 DEBUG : March16_7/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:34:13 DEBUG : fuse: -> [ID=0x256] Lookup 0xe gen=22 valid=1s attr={valid=1s ino=11301529950936761786 size=0 mode=drwxr-xr-x}
2021/03/16 14:34:13 DEBUG : fuse: <- Lookup [ID=0x257 Node=0xe Uid=0 Gid=0 Pid=392] "dira"
2021/03/16 14:34:13 DEBUG : March16_7/: Lookup: name="dira"
2021/03/16 14:34:13 DEBUG : March16_7/: >Lookup: node=, err=no such file or directory
2021/03/16 14:34:13 DEBUG : fuse: -> [ID=0x257] Lookup error=ENOENT
2021/03/16 14:34:13 DEBUG : fuse: <- Lookup [ID=0x258 Node=0xe Uid=0 Gid=0 Pid=392] "diraa"
2021/03/16 14:34:13 DEBUG : March16_7/: Lookup: name="diraa"
2021/03/16 14:34:13 DEBUG : March16_7/: >Lookup: node=March16_7/diraa/, err=
2021/03/16 14:34:13 DEBUG : March16_7/diraa/: Attr:
2021/03/16 14:34:13 DEBUG : March16_7/diraa/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:34:13 DEBUG : fuse: -> [ID=0x258] Lookup 0x19 gen=23 valid=1s attr={valid=1s ino=15308389385792068975 size=0 mode=drwxr-xr-x}
2021/03/16 14:34:13 DEBUG : fuse: <- Lookup [ID=0x259 Node=0xe Uid=0 Gid=0 Pid=392] "dira"
2021/03/16 14:34:13 DEBUG : March16_7/: Lookup: name="dira"
2021/03/16 14:34:13 DEBUG : March16_7/: >Lookup: node=, err=no such file or directory
2021/03/16 14:34:13 DEBUG : fuse: -> [ID=0x259] Lookup error=ENOENT
2021/03/16 14:34:13 DEBUG : fuse: <- Lookup [ID=0x25a Node=0xe Uid=0 Gid=0 Pid=392] "dira"
2021/03/16 14:34:13 DEBUG : March16_7/: Lookup: name="dira"
2021/03/16 14:34:13 DEBUG : March16_7/: >Lookup: node=, err=no such file or directory
2021/03/16 14:34:13 DEBUG : fuse: -> [ID=0x25a] Lookup error=ENOENT
2021/03/16 14:34:13 DEBUG : fuse: <- Rename [ID=0x25b Node=0xe Uid=0 Gid=0 Pid=392] from "diraa" to dirnode 0xe "dira"
2021/03/16 14:34:13 DEBUG : March16_7/: Rename: oldName="diraa", newName="dira", newDir=March16_7/
2021/03/16 14:34:13 DEBUG : March16_7/diraa/dira/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/16 14:34:13 INFO : March16_7/diraa/dira/test.txt: Copied (server-side copy) to: March16_7/dira/dira/test.txt
2021/03/16 14:34:13 DEBUG : March16_7/diraa/dirb/test.txt: MD5 = d8e8fca2dc0f896fd7cb4cb0031ba249 OK
2021/03/16 14:34:13 INFO : March16_7/diraa/dirb/test.txt: Copied (server-side copy) to: March16_7/dira/dirb/test.txt
2021/03/16 14:34:14 INFO : March16_7/diraa/dira/test.txt: Deleted
2021/03/16 14:34:14 INFO : March16_7/diraa/dirb/test.txt: Deleted
2021/03/16 14:34:14 DEBUG : March16_7/diraa: Updating dir with March16_7/dira 0xc000646fc0
2021/03/16 14:34:14 DEBUG : March16_7/diraa: forgetting directory cache
2021/03/16 14:34:14 DEBUG : March16_7/diraa/dira: forgetting directory cache
2021/03/16 14:34:14 DEBUG : March16_7/diraa/dirb: forgetting directory cache
2021/03/16 14:34:14 DEBUG : March16_7: Added virtual directory entry vDel: "diraa"
2021/03/16 14:34:14 DEBUG : March16_7: Added virtual directory entry vAddDir: "dira"
2021/03/16 14:34:14 DEBUG : March16_7/: >Rename: err=
2021/03/16 14:34:14 DEBUG : fuse: -> [ID=0x25b] Rename
2021/03/16 14:34:14 DEBUG : fuse: => InvalidateEntry 0xe "diraa" Err:node not cached
2021/03/16 14:34:14 DEBUG : fuse: => InvalidateEntry 0xe "dira"
2021/03/16 14:34:14 DEBUG : fuse: <- BatchForget [ID=0x25c Node=0x0 Uid=0 Gid=0 Pid=0] 24x1 23x1 25x2
2021/03/16 14:34:14 DEBUG : fuse: -> [ID=0x25c] BatchForget
2021/03/16 14:34:15 DEBUG : fuse: <- Lookup [ID=0x25d Node=0x1 Uid=0 Gid=0 Pid=395] "March16_7"
2021/03/16 14:34:15 DEBUG : /: Lookup: name="March16_7"
2021/03/16 14:34:15 DEBUG : /: >Lookup: node=March16_7/, err=
2021/03/16 14:34:15 DEBUG : March16_7/: Attr:
2021/03/16 14:34:15 DEBUG : March16_7/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x25d] Lookup 0xe gen=22 valid=1s attr={valid=1s ino=11301529950936761786 size=0 mode=drwxr-xr-x}
2021/03/16 14:34:15 DEBUG : fuse: <- Open [ID=0x25e Node=0xe Uid=0 Gid=0 Pid=395] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x25e] Open 0x1 fl=0
2021/03/16 14:34:15 DEBUG : fuse: <- Read [ID=0x25f Node=0xe Uid=0 Gid=0 Pid=395] 0x1 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : March16_7/: ReadDirAll:
2021/03/16 14:34:15 DEBUG : March16_7/: >ReadDirAll: item=3, err=
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x25f] Read 96
2021/03/16 14:34:15 DEBUG : fuse: <- Read [ID=0x260 Node=0xe Uid=0 Gid=0 Pid=395] 0x1 4096 @0x60 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x260] Read 0
2021/03/16 14:34:15 DEBUG : fuse: <- Lookup [ID=0x261 Node=0xe Uid=0 Gid=0 Pid=395] "dira"
2021/03/16 14:34:15 DEBUG : March16_7/: Lookup: name="dira"
2021/03/16 14:34:15 DEBUG : March16_7/: >Lookup: node=March16_7/dira/, err=
2021/03/16 14:34:15 DEBUG : March16_7/dira/: Attr:
2021/03/16 14:34:15 DEBUG : March16_7/dira/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x261] Lookup 0x19 gen=26 valid=1s attr={valid=1s ino=6698490372359634740 size=0 mode=drwxr-xr-x}
2021/03/16 14:34:15 DEBUG : fuse: <- Open [ID=0x262 Node=0x19 Uid=0 Gid=0 Pid=395] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x262] Open 0x3 fl=0
2021/03/16 14:34:15 DEBUG : fuse: <- Read [ID=0x263 Node=0x19 Uid=0 Gid=0 Pid=395] 0x3 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : March16_7/dira/: ReadDirAll:

2021/03/16 14:34:15 DEBUG : March16_7/dira: Removed virtual directory entry vAddDir: "dira"
2021/03/16 14:34:15 DEBUG : March16_7/dira: Removed virtual directory entry vAddDir: "dirb"
2021/03/16 14:34:15 DEBUG : March16_7/dira/: >ReadDirAll: item=4, err=
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x263] Read 128
2021/03/16 14:34:15 DEBUG : fuse: <- Read [ID=0x264 Node=0x19 Uid=0 Gid=0 Pid=395] 0x3 4096 @0x80 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x264] Read 0
2021/03/16 14:34:15 DEBUG : fuse: <- Lookup [ID=0x265 Node=0x19 Uid=0 Gid=0 Pid=395] "dira"
2021/03/16 14:34:15 DEBUG : March16_7/dira/: Lookup: name="dira"
2021/03/16 14:34:15 DEBUG : March16_7/dira/: >Lookup: node=March16_7/diraa/dira/, err=
2021/03/16 14:34:15 DEBUG : March16_7/diraa/dira/: Attr:
2021/03/16 14:34:15 DEBUG : March16_7/diraa/dira/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x265] Lookup 0x17 gen=27 valid=1s attr={valid=1s ino=8948523067796462443 size=0 mode=drwxr-xr-x}
2021/03/16 14:34:15 DEBUG : fuse: <- Open [ID=0x266 Node=0x17 Uid=0 Gid=0 Pid=395] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x266] Open 0x2 fl=0
2021/03/16 14:34:15 DEBUG : fuse: <- Read [ID=0x267 Node=0x17 Uid=0 Gid=0 Pid=395] 0x2 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : March16_7/diraa/dira/: ReadDirAll:
2021/03/16 14:34:15 DEBUG : March16_7/diraa/dira/: >ReadDirAll: item=2, err=
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x267] Read 64
2021/03/16 14:34:15 DEBUG : fuse: <- Read [ID=0x268 Node=0x17 Uid=0 Gid=0 Pid=395] 0x2 4096 @0x40 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x268] Read 0
2021/03/16 14:34:15 DEBUG : fuse: <- Release [ID=0x269 Node=0x17 Uid=0 Gid=0 Pid=0] 0x2 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x269] Release
2021/03/16 14:34:15 DEBUG : fuse: <- Lookup [ID=0x26a Node=0x19 Uid=0 Gid=0 Pid=395] "dirb"
2021/03/16 14:34:15 DEBUG : March16_7/dira/: Lookup: name="dirb"
2021/03/16 14:34:15 DEBUG : March16_7/dira/: >Lookup: node=March16_7/diraa/dirb/, err=
2021/03/16 14:34:15 DEBUG : March16_7/diraa/dirb/: Attr:
2021/03/16 14:34:15 DEBUG : March16_7/diraa/dirb/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x26a] Lookup 0x18 gen=28 valid=1s attr={valid=1s ino=8948524167308090654 size=0 mode=drwxr-xr-x}
2021/03/16 14:34:15 DEBUG : fuse: <- Open [ID=0x26b Node=0x18 Uid=0 Gid=0 Pid=395] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : fuse: -> [ID=0x26b] Open 0x2 fl=0
2021/03/16 14:34:15 DEBUG : fuse: <- Read [ID=0x26c Node=0x18 Uid=0 Gid=0 Pid=395] 0x2 4096 @0x0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:15 DEBUG : March16_7/diraa/dirb/: ReadDirAll:
2021/03/16 14:34:16 DEBUG : March16_7/diraa/dirb/: >ReadDirAll: item=2, err=
2021/03/16 14:34:16 DEBUG : fuse: -> [ID=0x26c] Read 64
2021/03/16 14:34:16 DEBUG : fuse: <- Read [ID=0x26d Node=0x18 Uid=0 Gid=0 Pid=395] 0x2 4096 @0x40 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000
2021/03/16 14:34:16 DEBUG : fuse: -> [ID=0x26d] Read 0
2021/03/16 14:34:16 DEBUG : fuse: <- Release [ID=0x26e Node=0x18 Uid=0 Gid=0 Pid=0] 0x2 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:34:16 DEBUG : fuse: -> [ID=0x26e] Release
2021/03/16 14:34:16 DEBUG : fuse: <- Release [ID=0x26f Node=0x19 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:34:16 DEBUG : fuse: -> [ID=0x26f] Release
2021/03/16 14:34:16 DEBUG : fuse: <- Release [ID=0x270 Node=0xe Uid=0 Gid=0 Pid=0] 0x1 fl=OpenReadOnly+OpenDirectory+OpenNonblock+0x20000 rfl=0 owner=0
2021/03/16 14:34:16 DEBUG : fuse: -> [ID=0x270] Release
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test_March_16/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_1/diraa/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_1/diraa/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_2/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_3/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_5/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_7/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_2/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_3/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_5/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_7/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:34:34 INFO : vfs cache: cleaned: objects 11 (was 11) in use 0, to upload 0, uploading 0, total size 60 (was 60)
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_1/diraa/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_1/diraa/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_2/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_3/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_5/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_7/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test_March_16/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_3/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_5/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_7/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_2/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:35:34 INFO : vfs cache: cleaned: objects 11 (was 11) in use 0, to upload 0, uploading 0, total size 60 (was 60)
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test_March_16/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_1/diraa/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_1/diraa/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_2/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_3/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_5/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_7/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_2/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_3/dira/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_5/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item March16_7/dirb/test.txt not removed, freed 0 bytes
2021/03/16 14:36:34 INFO : vfs cache: cleaned: objects 11 (was 11) in use 0, to upload 0, uploading 0, total size 60 (was 60)

ncw · March 16, 2021, 6:04pm

It looks like I spoke too soon.

It sometimes fixes the issue but other times doesn't. Do you find that?

Will investigate further...

ncw · March 17, 2021, 3:20pm

OK here is the next version. This works for me for all sleep values 5 times in a row! So I hope it is fixed for you.

v1.55.0-beta.5316.5eb19dab1.fix-4977-mount-caching on branch fix-4977-mount-caching (uploaded in 15-30 mins)

Jue_Sch · March 18, 2021, 9:17am

Thanks. I tried it and the results are fine now. (The only small caveat is that the very first run showed an issue in the before trace (dirb was not displayed) but I missed to catch logs and then could not reproduce. That was the very first run since yesterday evening so not sure if there was any warm up involved. I killed my container a couple of times but could never reproduce)

ncw · March 22, 2021, 9:11am

Thanks for testing.

I think there still may be small opportunities for the directory view to be out of sync due to kernel caching being out of sync, but they should be very small now.

I've merged this to master now since it is a definite improvement which means it will be in the latest beta in 15-30 mins and released in v1.55

If you find a way of reproducing any further problems then let me know

Jue_Sch · March 31, 2021, 10:38am

Hello.

Can you maybe have a look at the attached small test script and see if it works with Object Storage for you? It was created as it seems that in some cases files get lost during copying so the script tries to compare the expected vs the actual.

(You need to create an empty dir and den call testcp <dir_path>)

testCP.txt (2.0 KB)

When I run it I face this error in the second copy cycle (The first cycle worked so it seems not to be a general isssue)

As always, any help is greatly appreciated.

cp: cannot open 'testdira/testdira/script0.py' for reading: Input/output error
...

My config is:

2021/03/31 10:24:05 DEBUG : rclone: Version "v1.55.0-beta.5351.d0f8b4f47" starting with parameters ["rclone" "mount" ":s3:rclonejs" "/rclone222" "-vv" "--transfers=50" "--s3-acl=private" "--s3-env-auth=false" "--s3-access-key-id=" "--s3-secret-access-key=" "--s3-endpoint=s3.us-south.cloud-object-storage.appdomain.cloud" "--s3-location-constraint=us-south-standard" "--debug-fuse" "-v" "--vfs-write-back=1s" "--vfs-cache-mode" "writes"]

and the logs says

2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/testdira/: ReadDirAll:
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/testdira/: >ReadDirAll: item=12, err=
2021/03/31 10:25:40 DEBUG : fuse: -> [ID=0x138] Read 464
2021/03/31 10:25:40 DEBUG : fuse: <- Read [ID=0x139 Node=0xe Uid=0 Gid=0 Pid=205] 0x1 4096 @0x1d0 dir=true fl=0 owner=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock
2021/03/31 10:25:40 DEBUG : fuse: -> [ID=0x139] Read 0
2021/03/31 10:25:40 DEBUG : fuse: <- Release [ID=0x13a Node=0xe Uid=0 Gid=0 Pid=0] 0x1 fl=OpenReadOnly+OpenDirectory+OpenNonblock rfl=0 owner=0
2021/03/31 10:25:40 DEBUG : fuse: -> [ID=0x13a] Release
2021/03/31 10:25:40 DEBUG : fuse: <- Lookup [ID=0x13b Node=0xe Uid=0 Gid=0 Pid=205] "script2.py"
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/testdira/: Lookup: name="script2.py"
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/testdira/: >Lookup: node=testscriptMarh31_2/testdira/script2.py, err=
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/script2.py: Attr:
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/script2.py: >Attr: a=valid=1s ino=0 size=29 mode=-rw-r--r--, err=
2021/03/31 10:25:40 DEBUG : fuse: -> [ID=0x13b] Lookup 0x12 gen=6 valid=1s attr={valid=1s ino=2566033983488613770 size=29 mode=-rw-r--r--}
2021/03/31 10:25:40 DEBUG : fuse: <- Open [ID=0x13c Node=0x12 Uid=0 Gid=0 Pid=205] dir=false fl=OpenReadOnly+0x20000
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/script2.py: Open: flags=OpenReadOnly+0x20000
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/script2.py: Open: flags=O_RDONLY|0x20000
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/script2.py: >Open: fd=<nil *ReadFileHandle>, err=can't open file - writer failed
2021/03/31 10:25:40 DEBUG : testscriptMarh31_2/testdira/script2.py: >Open: fh=, err=can't open file - writer failed
2021/03/31 10:25:40 DEBUG : fuse: -> [ID=0x13c] Open error=EIO: can't open file - writer failed

ncw · April 1, 2021, 4:25pm

Hmm, I think this is some sort of race condition between writing a file and reading it back.

So I think the file might have been written but not completed and then the read times out waiting for the file to become available.

Is this always reproducible?

Can you reproduce it with --vfs-cache-mode full?

Can you try to find a smaller reproduction as a log where 100s of files are created is going to be impossible to look through!

Jue_Sch · April 3, 2021, 7:33am

Hi, yes , this is always reproducible with my original settings.

Using --vfs-cache-mode full removed the issues around

 cp: cannot open 'testdira/testdira/script0.py' for reading: Input/output error

Now the script shows reproducible what I sensed before, which is files get lost during the iterations.

It always seems to happen in round 3 of the script now. The first 2 work as expected.

Regarding a smaller reproduction size, I will try to provide that.

I am not available for 1 week but will share results when I am back.

ncw · April 3, 2021, 7:40pm

Thanks.

The other thing which helps for a reproduction is seeing if you can get the failure to happen against a local backend - so mount a local directory.

Or you could also try reproducing against the :memory: backend which is a bucket based in-memory backend.

system · June 3, 2021, 3:40pm

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.