VFS cache backend not caching files via rclone rc

mikethebone · August 14, 2023, 1:06pm

What is the problem you are having with rclone?

I am attempting to mount a remote via an "rclone rcd" instance that is running a docker container. When I mount the remote with "rclone rc" the mount is successful, however the VFS filesystem options don't seem to work. The CacheMaxAge is being picked up as its reference in the logs, but others such as the cache path are not working.

Problem (1) The VFS cache path reverts to /root/.cache despite being instructed to be elsewhere - but that's OK, I just worked around this for now

Problem (2) There are no files being created in the VFS filesystem on disk in either location, although it does create the vfs and vfsMeta directories within /root/.cache

When I copy files off of this remote I expect to see them in the VFS cache directory but they are not present, then apparently get evicted despite having a long CacheMaxAge.

Run the command 'rclone version' and share the full output of the command.

rclone v1.63.1

os/version: alpine 3.18.2 (64 bit)
os/kernel: 5.10.0-23-amd64 (x86_64)
os/type: linux
os/arch: amd64
go/version: go1.20.6
go/linking: static
go/tags: none

(via docker)

Which cloud storage system are you using? (eg Google Drive)

I am using a public open FTP that I found for testing purposes, but I have tried other remote types and they are behaving the same.

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

 rclone rc mount/mount fs=rebex: mountPoint=/mnt/rclone/rebex 'vfsOpt={
  "CacheMode": 2,
  "CacheMaxSize": "500G",
  "CacheMaxAge": 2592000,
  "CacheDir": "/config/.cache",
  "ReadAhead": "16M",
  "ReadChunkSize": "16M",
  "ReadChunkSizeLimit": "2G",
  "FastFingerprint": true
}' 'mountOpt={
  "AllowOther": true,
  "AllowNonEmpty": true,
  "LogLevel": "DEBUG"
}'

The rclone config contents with secrets removed.

[rebex]
type = ftp
host = test.rebex.net
user = demo
pass = password

A log from the command with the `-vv` flag

2023/08/14 12:52:35 DEBUG : rc: "mount/mount": with parameters map[fs:rebex: mountOpt:{
  "AllowOther": true,
  "AllowNonEmpty": true,
  "LogLevel": "DEBUG"
} mountPoint:/mnt/rclone/rebex vfsOpt:{
  "CacheMode": 2,
  "CacheMaxSize": "500G",
  "CacheMaxAge": 2592000,
  "CacheDir": "/config/.cache",
  "ReadAhead": "16M",
  "ReadChunkSize": "16M",
  "ReadChunkSizeLimit": "2G",
  "FastFingerprint": true
}]
2023/08/14 12:52:35 DEBUG : Creating backend with remote "rebex:"
2023/08/14 12:52:35 DEBUG : ftp://test.rebex.net:21: Connecting to FTP server
2023/08/14 12:52:35 DEBUG : ftp://test.rebex.net:21: dial("tcp","test.rebex.net:21")
2023/08/14 12:52:35 DEBUG : ftp://test.rebex.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/08/14 12:52:35 INFO  : ftp://test.rebex.net:21: poll-interval is not supported by this remote
2023/08/14 12:52:35 DEBUG : vfs cache: root is "/root/.cache/rclone"
2023/08/14 12:52:35 DEBUG : vfs cache: data root is "/root/.cache/rclone/vfs/rebex"
2023/08/14 12:52:35 DEBUG : vfs cache: metadata root is "/root/.cache/rclone/vfsMeta/rebex"
2023/08/14 12:52:35 DEBUG : Creating backend with remote "/root/.cache/rclone/vfs/rebex/"
2023/08/14 12:52:35 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfs/rebex/" to be canonical "/root/.cache/rclone/vfs/rebex"
2023/08/14 12:52:35 DEBUG : Creating backend with remote "/root/.cache/rclone/vfsMeta/rebex/"
2023/08/14 12:52:35 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfsMeta/rebex/" to be canonical "/root/.cache/rclone/vfsMeta/rebex"
2023/08/14 12:52:35 DEBUG : ftp://test.rebex.net:21: Mounting on "/mnt/rclone/rebex"
2023/08/14 12:52:35 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/08/14 12:52:35 DEBUG : Mount for ftp://test.rebex.net:21 created at /mnt/rclone/rebex using mount
2023/08/14 12:52:35 DEBUG : rc: "mount/mount": reply map[]: <nil>
2023/08/14 12:52:35 DEBUG : : Root:
2023/08/14 12:52:35 DEBUG : : >Root: node=/, err=<nil>
2023/08/14 12:52:40 DEBUG : : Statfs:
2023/08/14 12:52:40 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:52:40 DEBUG : : Statfs:
2023/08/14 12:52:40 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:52:50 DEBUG : : Statfs:
2023/08/14 12:52:50 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:52:50 DEBUG : : Statfs:
2023/08/14 12:52:50 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:52:57 DEBUG : /: Attr:
2023/08/14 12:52:57 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/08/14 12:52:57 DEBUG : /: Attr:
2023/08/14 12:52:57 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/08/14 12:52:58 DEBUG : /: Attr:
2023/08/14 12:52:58 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/08/14 12:52:58 DEBUG : /: ReadDirAll:
2023/08/14 12:52:58 DEBUG : ftp://test.rebex.net:21: dial("tcp","194.108.117.16:1146")
2023/08/14 12:52:58 DEBUG : ftp://test.rebex.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/08/14 12:52:59 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2023/08/14 12:52:59 DEBUG : /: Lookup: name="pub"
2023/08/14 12:52:59 DEBUG : /: >Lookup: node=pub/, err=<nil>
2023/08/14 12:52:59 DEBUG : pub/: Attr:
2023/08/14 12:52:59 DEBUG : pub/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/08/14 12:52:59 DEBUG : /: Lookup: name="readme.txt"
2023/08/14 12:52:59 DEBUG : /: >Lookup: node=readme.txt, err=<nil>
2023/08/14 12:52:59 DEBUG : readme.txt: Attr:
2023/08/14 12:52:59 DEBUG : readme.txt: Set virtual modtime to 2021-12-17 10:58:48 +0000 UTC
2023/08/14 12:52:59 DEBUG : readme.txt: >Attr: a=valid=1s ino=0 size=405 mode=-rw-r--r--, err=<nil>
2023/08/14 12:53:00 DEBUG : : Statfs:
2023/08/14 12:53:00 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:00 DEBUG : : Statfs:
2023/08/14 12:53:00 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:01 DEBUG : /: Attr:
2023/08/14 12:53:01 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/08/14 12:53:01 DEBUG : /: ReadDirAll:
2023/08/14 12:53:01 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2023/08/14 12:53:01 DEBUG : /: Attr:
2023/08/14 12:53:01 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/08/14 12:53:01 DEBUG : /: Lookup: name="readme.txt"
2023/08/14 12:53:01 DEBUG : /: >Lookup: node=readme.txt, err=<nil>
2023/08/14 12:53:01 DEBUG : readme.txt: Attr:
2023/08/14 12:53:01 DEBUG : readme.txt: Returning virtual modtime 2021-12-17 10:58:48 +0000 UTC
2023/08/14 12:53:01 DEBUG : readme.txt: >Attr: a=valid=1s ino=0 size=405 mode=-rw-r--r--, err=<nil>
2023/08/14 12:53:02 DEBUG : /: Attr:
2023/08/14 12:53:02 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/08/14 12:53:02 DEBUG : /: Lookup: name="readme.txt"
2023/08/14 12:53:02 DEBUG : /: >Lookup: node=readme.txt, err=<nil>
2023/08/14 12:53:02 DEBUG : readme.txt: Attr:
2023/08/14 12:53:02 DEBUG : readme.txt: Returning virtual modtime 2021-12-17 10:58:48 +0000 UTC
2023/08/14 12:53:02 DEBUG : readme.txt: >Attr: a=valid=1s ino=0 size=405 mode=-rw-r--r--, err=<nil>
2023/08/14 12:53:02 DEBUG : readme.txt: Open: flags=OpenReadOnly
2023/08/14 12:53:02 DEBUG : readme.txt: Open: flags=O_RDONLY
2023/08/14 12:53:02 DEBUG : readme.txt: >Open: fd=readme.txt (r), err=<nil>
2023/08/14 12:53:02 DEBUG : readme.txt: >Open: fh=&{readme.txt (r)}, err=<nil>
2023/08/14 12:53:02 DEBUG : &{readme.txt (r)}: Read: len=4096, offset=0
2023/08/14 12:53:02 DEBUG : readme.txt: ChunkedReader.openRange at 0 length 134217728
2023/08/14 12:53:02 DEBUG : ftp://test.rebex.net:21: dial("tcp","194.108.117.16:1138")
2023/08/14 12:53:02 DEBUG : ftp://test.rebex.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/08/14 12:53:02 DEBUG : readme.txt: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
2023/08/14 12:53:02 DEBUG : &{readme.txt (r)}: >Read: read=405, err=<nil>
2023/08/14 12:53:02 DEBUG : &{readme.txt (r)}: Flush:
2023/08/14 12:53:02 DEBUG : &{readme.txt (r)}: >Flush: err=<nil>
2023/08/14 12:53:02 DEBUG : &{readme.txt (r)}: Release:
2023/08/14 12:53:02 DEBUG : readme.txt: ReadFileHandle.Release closing
2023/08/14 12:53:02 DEBUG : &{readme.txt (r)}: >Release: err=<nil>
2023/08/14 12:53:10 DEBUG : : Statfs:
2023/08/14 12:53:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:10 DEBUG : : Statfs:
2023/08/14 12:53:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:20 DEBUG : : Statfs:
2023/08/14 12:53:20 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:20 DEBUG : : Statfs:
2023/08/14 12:53:20 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:30 DEBUG : : Statfs:
2023/08/14 12:53:30 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:30 DEBUG : : Statfs:
2023/08/14 12:53:30 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/08/14 12:53:35 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/08/14 12:53:35 INFO  : vfs cache RemoveNotInUse (maxAge=2592000, emptyOnly=false): item readme.txt was removed, freed 0 bytes
2023/08/14 12:53:35 INFO  : vfs cache: cleaned: objects 0 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)

At this stage I expected the file to appear in the vfs filesystem cache, but no file was created, and then it indicated that the item was removed from cache (memory?)

Thank you

kapitainsky · August 14, 2023, 1:36pm

You set cache mode to write and expect data to be cached for reads? Here you are description of different cache modes.

When you change the cache mode to full I would double check CacheMaxAge duration. Of course time duration for one person can be long and short for another. Definitely it is relative... but I still prefer to check if you know that 2,592,000 nanoseconds is only 0.002592 seconds... Maybe it is long in what you use computer for - some sort of nuclear science data?

mikethebone · August 14, 2023, 2:05pm

Thank you! I was definitely getting some rclone fatigue trying to figure that out. I was under the impression that "2" was the same as "full". I've set it to "full" and it seems to be caching writes now.

Regarding CacheMaxAge, I was attempting to set it to 2 million seconds (30 days) because I have tried standard notiation but it doesn't appear to work: e.g. "1000h" or "30d" results in:

2023/08/14 14:02:11 ERROR : rc: "mount/mount": error: key "vfsOpt": json: cannot unmarshal string into Go struct field Options.CacheMaxAge of type time.Duration

kapitainsky · August 14, 2023, 2:18pm

hahah - it is not difficult to get lost in so many flags and parameters:) we all do sometimes.

You are right with setting duration - either it should be fixed or documentation made clear (somebody has to submit PR:)) that only nanoseconds are accepted,

but CacheMode cat be set using string value:

$ rclone rc options/set --json '{"vfs": {"CacheMode": "full"}}'
{}

$ rclone rc options/get | grep CacheMode
		"CacheMode": 3,

system · September 13, 2023, 2:19pm

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