Rclone mount vfs azureblob

daniele · January 29, 2021, 4:08pm

I tried this on a new test machine with v1.53.4

Here you can see the rename and a "cat" to the test.txt file:

2021/01/29 17:05:02 DEBUG : /: Attr:
2021/01/29 17:05:02 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/01/29 17:05:02 DEBUG : /: Lookup: name="rclonetest"
2021/01/29 17:05:02 DEBUG : /: >Lookup: node=rclonetest/, err=
2021/01/29 17:05:02 DEBUG : rclonetest/: Attr:
2021/01/29 17:05:02 DEBUG : rclonetest/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/01/29 17:05:02 DEBUG : /: Lookup: name="rclone1test"
2021/01/29 17:05:02 DEBUG : /: >Lookup: node=, err=no such file or directory
2021/01/29 17:05:02 DEBUG : /: Rename: oldName="rclonetest", newName="rclone1test", newDir=/
2021/01/29 17:05:03 DEBUG : rclonetest/test.txt: MD5 = e19c1283c925b3206685ff522acfe3e6 OK
2021/01/29 17:05:03 INFO : rclonetest/test.txt: Copied (server side copy)
2021/01/29 17:05:03 INFO : rclonetest/test.txt: Deleted
2021/01/29 17:05:03 DEBUG : rclonetest: Updating dir with rclone1test 0xc00027e000
2021/01/29 17:05:03 DEBUG : rclonetest: forgetting directory cache
2021/01/29 17:05:03 DEBUG : : Added virtual directory entry vDel: "rclonetest"
2021/01/29 17:05:03 DEBUG : : Added virtual directory entry vAdd: "rclone1test"
2021/01/29 17:05:03 DEBUG : /: >Rename: err=
2021/01/29 17:05:53 DEBUG : /: Attr:
2021/01/29 17:05:53 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/01/29 17:05:53 DEBUG : /: Lookup: name="rclone1test"
2021/01/29 17:05:53 DEBUG : /: >Lookup: node=rclone1test/, err=
2021/01/29 17:05:53 DEBUG : rclone1test/: Attr:
2021/01/29 17:05:53 DEBUG : rclone1test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2021/01/29 17:05:53 DEBUG : rclone1test/: Lookup: name="test.txt"
2021/01/29 17:05:53 DEBUG : rclone1test: Removed virtual directory entry vAdd: "test.txt"
2021/01/29 17:05:53 DEBUG : rclone1test/: >Lookup: node=rclonetest/test.txt, err=
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: Attr:
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: >Attr: a=valid=1s ino=0 size=15 mode=-rw-r--r--, err=
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: Open: flags=OpenReadOnly
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: Open: flags=O_RDONLY
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: newRWFileHandle:
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: >newRWFileHandle: err=
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: >Open: fd=rclonetest/test.txt (rw), err=
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: >Open: fh=&{rclonetest/test.txt (rw)}, err=
2021/01/29 17:05:53 DEBUG : &{rclonetest/test.txt (rw)}: Read: len=4096, offset=0
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): _readAt: size=4096, off=0
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): openPending:
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: vfs cache: checking remote fingerprint "15,2021-01-29 16:03:43.531766408 +0000 UTC,e19c1283c925b3206685ff522acfe3e6" against cached fingerprint "15,2021-01-29 16:03:43.531766408 +0000 UTC,e19c1283c925b3206685ff522acfe3e6"
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: vfs cache: truncate to size=15
2021/01/29 17:05:53 DEBUG : rclone1test: Added virtual directory entry vAdd: "test.txt"
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): >openPending: err=
2021/01/29 17:05:53 DEBUG : vfs cache: looking for range={Pos:0 Size:15} in [{Pos:0 Size:15}] - present true
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): >_readAt: n=15, err=EOF
2021/01/29 17:05:53 DEBUG : &{rclonetest/test.txt (rw)}: >Read: read=15, err=
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: Attr:
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: >Attr: a=valid=1s ino=0 size=15 mode=-rw-r--r--, err=
2021/01/29 17:05:53 DEBUG : &{rclonetest/test.txt (rw)}: Flush:
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): RWFileHandle.Flush
2021/01/29 17:05:53 DEBUG : &{rclonetest/test.txt (rw)}: >Flush: err=
2021/01/29 17:05:53 DEBUG : &{rclonetest/test.txt (rw)}: Release:
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): RWFileHandle.Release
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): close:
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt: vfs cache: setting modification time to 2021-01-29 17:03:43.531766408 +0100 CET
2021/01/29 17:05:53 DEBUG : rclonetest/test.txt(0xc000b3b8c0): >close: err=
2021/01/29 17:05:53 DEBUG : &{rclonetest/test.txt (rw)}: >Release: err=

ncw · January 30, 2021, 1:02pm

I have managed to replicate this in the beta

I ran

rclone mount --vfs-cache-mode full -vv azure:rclone /mnt/tmp/

Then

$ cd /mnt/tmp/
$ mkdir rclonetest
$ echo "this is a test" > rclonetest/test.txt
$ cat rclonetest/test.txt
this is a test
$ mv rclonetest rclone1test
$ cat rclone1test/test.txt
this is a test

Very clearly in the log we can see that the second cat is accessing the old object

2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: Open: flags=OpenReadOnly
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: Open: flags=O_RDONLY
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: newRWFileHandle: 
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: >newRWFileHandle: err=<nil>
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: >Open: fd=rclonetest/test.txt (rw), err=<nil>
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: >Open: fh=&{rclonetest/test.txt (rw)}, err=<nil>
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: Attr: 
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: >Attr: a=valid=1s ino=0 size=15 mode=-rw-rw-r--, err=<nil>
2021/01/30 11:30:06 DEBUG : &{rclonetest/test.txt (rw)}: Read: len=4096, offset=0
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): _readAt: size=4096, off=0
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): openPending: 
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: vfs cache: checking remote fingerprint "15,2021-01-30 11:29:37.83851914 +0000 UTC,e19c1283c925b3206685ff522acfe3e6" against cached fingerprint "15,2021-01-30 11:29:37.83851914 +0000 UTC,e19c1283c925b3206685ff522acfe3e6"
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: vfs cache: truncate to size=15
2021/01/30 11:30:06 DEBUG : rclone1test: Added virtual directory entry vAddFile: "test.txt"
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): >openPending: err=<nil>
2021/01/30 11:30:06 DEBUG : vfs cache: looking for range={Pos:0 Size:15} in [{Pos:0 Size:15}] - present true
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): >_readAt: n=15, err=EOF
2021/01/30 11:30:06 DEBUG : &{rclonetest/test.txt (rw)}: >Read: read=15, err=<nil>
2021/01/30 11:30:06 DEBUG : &{rclonetest/test.txt (rw)}: Flush: 
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): RWFileHandle.Flush
2021/01/30 11:30:06 DEBUG : &{rclonetest/test.txt (rw)}: >Flush: err=<nil>
2021/01/30 11:30:06 DEBUG : &{rclonetest/test.txt (rw)}: Release: 
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): RWFileHandle.Release
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): close: 
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt: vfs cache: setting modification time to 2021-01-30 11:29:37.83851914 +0000 UTC
2021/01/30 11:30:06 DEBUG : rclonetest/test.txt(0xc0005c7b80): >close: err=<nil>
2021/01/30 11:30:06 DEBUG : &{rclonetest/test.txt (rw)}: >Release: err=<nil>

This problem does not replicate with rclone cmount which means it is almost certainly due to caching in the kernel.

It replicates in a simpler way with --vfs-cache-mode off

rclone mount --vfs-cache-mode off -vv azure:rclone /mnt/tmp/

$ mkdir /mnt/tmp/rclonetest
$ echo "this is a test" > /mnt/tmp/rclonetest/test.txt
$ cat /mnt/tmp/rclonetest/test.txt
this is a test
$ mv /mnt/tmp/rclonetest /mnt/tmp/rclone1test
$ cat /mnt/tmp/rclone1test/test.txt
cat: /mnt/tmp/rclone1test/test.txt: Input/output error

With the same underlying cause of reading the wrong object.

I can prove this is due to kernel caching, as if I execute this as root after the second cat

sync; echo 2 > /proc/sys/vm/drop_caches

Then repeating the cat works fine.

$ mkdir /mnt/tmp/rclonetest
$ echo "this is a test" > /mnt/tmp/rclonetest/test.txt
$ cat /mnt/tmp/rclonetest/test.txt
this is a test
$ mv /mnt/tmp/rclonetest /mnt/tmp/rclone1test
$ cat /mnt/tmp/rclone1test/test.txt
cat: /mnt/tmp/rclone1test/test.txt: Input/output error
# sync; echo 2 > /proc/sys/vm/drop_caches executed from a root shell here
$ cat /mnt/tmp/rclone1test/test.txt
this is a test

Lots of digging around in the source and logs later I find that when the fuse library creates directories, it sets their valid time to 60 seconds,

I haven't found a way to decrease this yet.

I've also been trying to invalidate the entry in the kernel cache, but I haven't succeeded with that yet either!

ncw · January 30, 2021, 1:44pm

Probably the best thing to do now, since this isn't an easy fix, is for you to please make a new issue on github - put a link to this forum page in.

I'll fill in more details once you have done that.

I'll then make an issue with the upstream bazil/fuse library to try to get it fixed.

daniele · January 30, 2021, 6:02pm

Did that. Thank you!

https://github.com/rclone/rclone/issues/4977

system · April 1, 2021, 2:02pm

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