Is this a VFS Cache bug?

eligible · August 19, 2023, 8:56am

I have a azure blob remote that is setup to be immutable. I mount it with:

#!/bin/bash

mount_opt="--vfs-cache-mode full \
--vfs-cache-max-age 999999h \
--read-only  \
--attr-timeout 999999h \
--dir-cache-time 999999h \
--no-checksum  \
--no-modtime \
--cache-dir /tmp/rclone_cache \
--vfs-cache-poll-interval 10000h \
--async-read   \
--log-level DEBUG \
"

dest=/dev/shm/tmp
src="image:image-storage/testDir"

rclone mount $src $dest $mount_opt

The rclone config:

[image]
type = azureblob
account = REDACTED
env_auth = true

Output when I do a first cat /dev/shm/tmp/test.txt:

2023/08/17 21:09:54 DEBUG : /: Lookup: name="test.txt"
2023/08/17 21:09:54 DEBUG : /: >Lookup: node=test.txt, err=<nil>
2023/08/17 21:09:54 DEBUG : test.txt: Attr: 
2023/08/17 21:09:54 DEBUG : test.txt: >Attr: a=valid=999999h0m0s ino=0 size=12 mode=-rw-rw-r--, err=<nil>
2023/08/17 21:09:54 DEBUG : test.txt: Open: flags=OpenReadOnly
2023/08/17 21:09:54 DEBUG : test.txt: Open: flags=O_RDONLY
2023/08/17 21:09:54 DEBUG : test.txt: newRWFileHandle: 
2023/08/17 21:09:54 DEBUG : test.txt: >newRWFileHandle: err=<nil>
2023/08/17 21:09:54 DEBUG : test.txt: >Open: fd=test.txt (rw), err=<nil>
2023/08/17 21:09:54 DEBUG : test.txt: >Open: fh=&{test.txt (rw)}, err=<nil>
2023/08/17 21:09:54 DEBUG : &{test.txt (rw)}: Read: len=4096, offset=0
2023/08/17 21:09:54 DEBUG : test.txt(0xc0008ee1c0): _readAt: size=4096, off=0
2023/08/17 21:09:54 DEBUG : test.txt(0xc0008ee1c0): openPending: 
2023/08/17 21:09:54 DEBUG : test.txt: vfs cache: checking remote fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC,e59ff97941044f85df5297e1c302d260" against cached fingerprint ""
2023/08/17 21:09:54 DEBUG : test.txt: vfs cache: truncate to size=12
2023/08/17 21:09:54 DEBUG : : Added virtual directory entry vAddFile: "test.txt"
2023/08/17 21:09:54 DEBUG : test.txt(0xc0008ee1c0): >openPending: err=<nil>
2023/08/17 21:09:54 DEBUG : vfs cache: looking for range={Pos:0 Size:12} in [] - present false
2023/08/17 21:09:54 DEBUG : test.txt: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/08/17 21:09:54 DEBUG : test.txt: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2023/08/17 21:09:54 DEBUG : test.txt: ChunkedReader.openRange at 0 length 134217728
2023/08/17 21:09:55 DEBUG : test.txt(0xc0008ee1c0): >_readAt: n=12, err=EOF
2023/08/17 21:09:55 DEBUG : &{test.txt (rw)}: >Read: read=12, err=<nil>
2023/08/17 21:09:55 DEBUG : &{test.txt (rw)}: Flush: 
2023/08/17 21:09:55 DEBUG : test.txt(0xc0008ee1c0): RWFileHandle.Flush
2023/08/17 21:09:55 DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
2023/08/17 21:09:55 DEBUG : &{test.txt (rw)}: Release: 
2023/08/17 21:09:55 DEBUG : test.txt(0xc0008ee1c0): RWFileHandle.Release
2023/08/17 21:09:55 DEBUG : test.txt(0xc0008ee1c0): close: 
2023/08/17 21:09:55 DEBUG : test.txt: vfs cache: setting modification time to 2023-08-17 20:53:15.486022255 +1200 NZST
2023/08/17 21:09:55 DEBUG : test.txt(0xc0008ee1c0): >close: err=<nil>
2023/08/17 21:09:55 DEBUG : &{test.txt (rw)}: >Release: err=<nil>

Then I do another cat of the same file 30s later:

2023/08/17 21:10:25 DEBUG : test.txt: Open: flags=OpenReadOnly
2023/08/17 21:10:25 DEBUG : test.txt: Open: flags=O_RDONLY
2023/08/17 21:10:25 DEBUG : test.txt: newRWFileHandle: 
2023/08/17 21:10:25 DEBUG : test.txt: >newRWFileHandle: err=<nil>
2023/08/17 21:10:25 DEBUG : test.txt: >Open: fd=test.txt (rw), err=<nil>
2023/08/17 21:10:25 DEBUG : test.txt: >Open: fh=&{test.txt (rw)}, err=<nil>
2023/08/17 21:10:25 DEBUG : &{test.txt (rw)}: Read: len=4096, offset=0
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): _readAt: size=4096, off=0
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): openPending: 
2023/08/17 21:10:25 DEBUG : test.txt: vfs cache: checking remote fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC," against cached fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC,e59ff97941044f85df5297e1c302d260"
2023/08/17 21:10:25 DEBUG : test.txt: vfs cache: removing cached entry as stale (remote fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC," != cached fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC,e59ff97941044f85df5297e1c302d260")
2023/08/17 21:10:25 INFO  : test.txt: vfs cache: removed cache file as stale (remote is different)
2023/08/17 21:10:25 DEBUG : test.txt: vfs cache: removed metadata from cache as stale (remote is different)
2023/08/17 21:10:25 DEBUG : test.txt: vfs cache: truncate to size=12
2023/08/17 21:10:25 DEBUG : : Added virtual directory entry vAddFile: "test.txt"
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): >openPending: err=<nil>
2023/08/17 21:10:25 DEBUG : vfs cache: looking for range={Pos:0 Size:12} in [] - present false
2023/08/17 21:10:25 DEBUG : test.txt: ChunkedReader.RangeSeek from -1 to 0 length -1
2023/08/17 21:10:25 DEBUG : test.txt: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2023/08/17 21:10:25 DEBUG : test.txt: ChunkedReader.openRange at 0 length 134217728
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): >_readAt: n=12, err=EOF
2023/08/17 21:10:25 DEBUG : &{test.txt (rw)}: >Read: read=12, err=<nil>
2023/08/17 21:10:25 DEBUG : &{test.txt (rw)}: Flush: 
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): RWFileHandle.Flush
2023/08/17 21:10:25 DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
2023/08/17 21:10:25 DEBUG : &{test.txt (rw)}: Release: 
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): RWFileHandle.Release
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): close: 
2023/08/17 21:10:25 DEBUG : test.txt: vfs cache: setting modification time to 2023-08-17 20:53:15.486022255 +1200 NZST
2023/08/17 21:10:25 DEBUG : test.txt(0xc0008ee7c0): >close: err=<nil>
2023/08/17 21:10:25 DEBUG : &{test.txt (rw)}: >Release: err=<nil>

Why is it now fingerprinting with hash and invalidate the cache ??

Then did a third time cat:

2023/08/17 21:11:48 DEBUG : test.txt: Open: flags=OpenReadOnly
2023/08/17 21:11:48 DEBUG : test.txt: Open: flags=O_RDONLY
2023/08/17 21:11:48 DEBUG : test.txt: newRWFileHandle: 
2023/08/17 21:11:48 DEBUG : test.txt: >newRWFileHandle: err=<nil>
2023/08/17 21:11:48 DEBUG : test.txt: >Open: fd=test.txt (rw), err=<nil>
2023/08/17 21:11:48 DEBUG : test.txt: >Open: fh=&{test.txt (rw)}, err=<nil>
2023/08/17 21:11:48 DEBUG : &{test.txt (rw)}: Read: len=4096, offset=0
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): _readAt: size=4096, off=0
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): openPending: 
2023/08/17 21:11:48 DEBUG : test.txt: vfs cache: checking remote fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC," against cached fingerprint ""
2023/08/17 21:11:48 DEBUG : test.txt: vfs cache: truncate to size=12 (not needed as size correct)
2023/08/17 21:11:48 DEBUG : : Added virtual directory entry vAddFile: "test.txt"
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): >openPending: err=<nil>
2023/08/17 21:11:48 DEBUG : vfs cache: looking for range={Pos:0 Size:12} in [{Pos:0 Size:12}] - present true
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): >_readAt: n=12, err=EOF
2023/08/17 21:11:48 DEBUG : &{test.txt (rw)}: >Read: read=12, err=<nil>
2023/08/17 21:11:48 DEBUG : &{test.txt (rw)}: Flush: 
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): RWFileHandle.Flush
2023/08/17 21:11:48 DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
2023/08/17 21:11:48 DEBUG : &{test.txt (rw)}: Release: 
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): RWFileHandle.Release
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): close: 
2023/08/17 21:11:48 DEBUG : test.txt: vfs cache: setting modification time to 2023-08-17 20:53:15.486022255 +1200 NZST
2023/08/17 21:11:48 DEBUG : test.txt(0xc0005fc040): >close: err=<nil>
2023/08/17 21:11:48 DEBUG : &{test.txt (rw)}: >Release: err=<nil>

Somehow the cache fingerprint is "" ? But it ignore based on size matching.
Then another cat

2023/08/17 21:13:53 DEBUG : test.txt: Open: flags=OpenReadOnly
2023/08/17 21:13:53 DEBUG : test.txt: Open: flags=O_RDONLY
2023/08/17 21:13:53 DEBUG : test.txt: newRWFileHandle: 
2023/08/17 21:13:53 DEBUG : test.txt: >newRWFileHandle: err=<nil>
2023/08/17 21:13:53 DEBUG : test.txt: >Open: fd=test.txt (rw), err=<nil>
2023/08/17 21:13:53 DEBUG : test.txt: >Open: fh=&{test.txt (rw)}, err=<nil>
2023/08/17 21:13:53 DEBUG : &{test.txt (rw)}: Read: len=4096, offset=0
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): _readAt: size=4096, off=0
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): openPending: 
2023/08/17 21:13:53 DEBUG : test.txt: vfs cache: checking remote fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC," against cached fingerprint "12,2023-08-17 08:53:15.486022255 +0000 UTC,"
2023/08/17 21:13:53 DEBUG : test.txt: vfs cache: truncate to size=12 (not needed as size correct)
2023/08/17 21:13:53 DEBUG : : Added virtual directory entry vAddFile: "test.txt"
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): >openPending: err=<nil>
2023/08/17 21:13:53 DEBUG : vfs cache: looking for range={Pos:0 Size:12} in [{Pos:0 Size:12}] - present true
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): >_readAt: n=12, err=EOF
2023/08/17 21:13:53 DEBUG : &{test.txt (rw)}: >Read: read=12, err=<nil>
2023/08/17 21:13:53 DEBUG : &{test.txt (rw)}: Flush: 
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): RWFileHandle.Flush
2023/08/17 21:13:53 DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
2023/08/17 21:13:53 DEBUG : &{test.txt (rw)}: Release: 
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): RWFileHandle.Release
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): close: 
2023/08/17 21:13:53 DEBUG : test.txt: vfs cache: setting modification time to 2023-08-17 20:53:15.486022255 +1200 NZST
2023/08/17 21:13:53 DEBUG : test.txt(0xc0005fc040): >close: err=<nil>
2023/08/17 21:13:53 DEBUG : &{test.txt (rw)}: >Release: err=<nil>

Now the cache have fingerprint ?

Couple questions:

Why this flip flop of cache fingerprint ?
Does each time, rclone do a request to the remote to get the remote file size ?
Can the file be cached by the kernel, and should not even request rclone ?

I am using:

$ rclone --version
rclone v1.63.1-DEV
- os/version: opensuse-leap 15.4 (64 bit)
- os/kernel: 5.14.21-150400.24.60-default (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.18.1
- go/linking: dynamic
- go/tags: none

eligible · September 8, 2023, 9:51pm

Should I put this as github issue?

ncw · September 8, 2023, 10:22pm

This does look odd. You have rather a lot of mount options though. Can you retry the test with as few options as possible to narrow it down?

system · November 8, 2023, 6:23pm

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