Cached webdav mount fingerprints get nuked on `ls`?

nicobrevin · January 13, 2024, 1:36am

What is the problem you are having with rclone?

We have a custom webdav backend that we're mounting with rclone, because rclone has awesome caching features that we don't have to implement ourselves, yay! We found at first that rclone was using only the file size as part of the cache fingerprint, which we resolved by upgrading to 1.65.1 and setting --webdav-vendor to rclone. This was enough to get the fingerprint to include both the file size and the last-modified header from the GET request (for the cached content).

However, I am finding that if I do the following steps, I get a stale cache entry but with updated contents' key:

Mount the external webdav source with cache set to full mode
View the file, e.g. cat /mnt/webdav/subdir/hello.txt
Edit the file in the external webdav source and make a trivial change to it
Run ls /mnt/webdav/subdir/hello.txt && cat /mnt/webdav/subdir/hello.txt

80% of the time the file is the old version, but some of the time I will get back the correct file. In the logs I can see rclone reporting that the cache fingerprint is empty (for the file I fetched) whereas it was definitely set the first time I fetched the file:

2024/01/13 13:58:12 DEBUG : projects/tta/default/monster-analysis/project.ini: vfs cache: checking remote fingerprint "1714,2024-01-13 00:58:09 +0000 UTC" against cached fingerprint ""

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

$ rclone --version
rclone v1.65.1
- os/version: ubuntu 20.04 (64 bit)
- os/kernel: 5.15.0-91-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.21.5
- go/linking: static
- go/tags: none

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

A custom webdav implementation

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

rclone -vvv mount --webdav-vendor=rclone --read-only --cache-tmp-upload-path=/tmp --cache-chunk-path=/tmp --cache-workers=8 --cache-writes --cache-dir=/tmp --cache-db-path=/tmp --vfs-cache-mode=full --stats=0 --checkers=16 --bwlimit=40M --transfers=1 --dir-cache-time=1s --cache-info-age=1s webdav-local: /home/nickg/mnt/

The rclone config contents with secrets removed.

[webdav-local]
type = webdav
url = http://localhost:8080/dav
user = REDACTED
pass = REDACTED

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

Log showing start up and initial fetch:

2024/01/13 14:30:13 INFO  : Starting bandwidth limiter at 40Mi Byte/s
2024/01/13 14:30:13 DEBUG : rclone: Version "v1.65.1" starting with parameters ["rclone" "-vvv" "mount" "--webdav-vendor=rclone" "--read-only" "--cache-tmp-upload-path=/tmp" "--cache-chunk-path=/tmp" "--cache-workers=8" "--cache-writes" "--cache-dir=/tmp" "--cache-db-path=/tmp" "--vfs-cache-mode=full" "--stats=0" "--checkers=16" "--bwlimit=40M" "--transfers=1" "--dir-cache-time=1s" "--cache-info-age=1s" "webdav-local:" "/home/nickg/mnt/"]
2024/01/13 14:30:13 DEBUG : Creating backend with remote "webdav-local:"
2024/01/13 14:30:13 DEBUG : Using config file from "/home/nickg/.config/rclone/rclone.conf"
2024/01/13 14:30:13 DEBUG : webdav-local: detected overridden config - adding "{Q1VxD}" suffix to name
2024/01/13 14:30:13 DEBUG : found headers: 
2024/01/13 14:30:13 DEBUG : fs cache: renaming cache item "webdav-local:" to be canonical "webdav-local{Q1VxD}:"
2024/01/13 14:30:13 INFO  : webdav root '': poll-interval is not supported by this remote
2024/01/13 14:30:13 DEBUG : vfs cache: root is "/tmp"
2024/01/13 14:30:13 DEBUG : vfs cache: data root is "/tmp/vfs/webdav-local{Q1VxD}"
2024/01/13 14:30:13 DEBUG : vfs cache: metadata root is "/tmp/vfsMeta/webdav-local{Q1VxD}"
2024/01/13 14:30:13 DEBUG : Creating backend with remote "/tmp/vfs/webdav-local{Q1VxD}/"
2024/01/13 14:30:13 DEBUG : fs cache: renaming cache item "/tmp/vfs/webdav-local{Q1VxD}/" to be canonical "/tmp/vfs/webdav-local{Q1VxD}"
2024/01/13 14:30:13 DEBUG : Creating backend with remote "/tmp/vfsMeta/webdav-local{Q1VxD}/"
2024/01/13 14:30:13 DEBUG : fs cache: renaming cache item "/tmp/vfsMeta/webdav-local{Q1VxD}/" to be canonical "/tmp/vfsMeta/webdav-local{Q1VxD}"
2024/01/13 14:30:13 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2024/01/13 14:30:13 DEBUG : webdav root '': Mounting on "/home/nickg/mnt/"
2024/01/13 14:30:13 DEBUG : : Root: 
2024/01/13 14:30:13 DEBUG : : >Root: node=/, err=<nil>
2024/01/13 14:30:13 DEBUG : /: Lookup: name=".Trash"
2024/01/13 14:30:13 ERROR : Failed to parse time "Thu, 1 Jan 1970 12:00:00 +1200" - using the epoch
2024/01/13 14:30:13 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/01/13 14:30:13 DEBUG : /: Attr: 
2024/01/13 14:30:13 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2024/01/13 14:30:13 DEBUG : /: Lookup: name=".xdg-volume-info"
2024/01/13 14:30:13 DEBUG : /: Lookup: name="autorun.inf"
2024/01/13 14:30:13 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/01/13 14:30:13 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/01/13 14:30:13 DEBUG : /: Lookup: name=".Trash-10283"
2024/01/13 14:30:13 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: ReadDirAll: 
2024/01/13 14:30:13 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2024/01/13 14:30:13 DEBUG : /: Lookup: name="autorun.inf"
2024/01/13 14:30:13 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2024/01/13 14:30:13 DEBUG : : Statfs: 
2024/01/13 14:30:14 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2024/01/13 14:30:15 DEBUG : : forgetting directory cache
2024/01/13 14:30:15 DEBUG : users: forgetting directory cache
2024/01/13 14:30:15 DEBUG : projects: forgetting directory cache
2024/01/13 14:30:15 DEBUG : users: forgetting directory cache
2024/01/13 14:30:15 DEBUG : projects: forgetting directory cache
2024/01/13 14:30:18 DEBUG : /: Lookup: name="projects"
2024/01/13 14:30:18 DEBUG : /: >Lookup: node=projects/, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/: Attr: 
2024/01/13 14:30:18 DEBUG : projects/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/: Lookup: name="tta"
2024/01/13 14:30:18 DEBUG : projects/: >Lookup: node=projects/tta/, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/: Attr: 
2024/01/13 14:30:18 DEBUG : projects/tta/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/: Lookup: name="default"
2024/01/13 14:30:18 DEBUG : projects/tta/: >Lookup: node=projects/tta/default/, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/: Attr: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/: Lookup: name="monster-analysis"
2024/01/13 14:30:18 DEBUG : projects/tta/default/: >Lookup: node=projects/tta/default/monster-analysis/, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/: Attr: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/: Lookup: name="project.ini"
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/: >Lookup: node=projects/tta/default/monster-analysis/project.ini, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: Attr: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: >Attr: a=valid=1s ino=0 size=1717 mode=-rw-rw-r--, err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: Open: flags=OpenReadOnly
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: Open: flags=O_RDONLY
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: newRWFileHandle: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: >newRWFileHandle: err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: >Open: fd=projects/tta/default/monster-analysis/project.ini (rw), err=<nil>
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: >Open: fh=&{projects/tta/default/monster-analysis/project.ini (rw)}, err=<nil>
2024/01/13 14:30:18 DEBUG : &{projects/tta/default/monster-analysis/project.ini (rw)}: Read: len=4096, offset=0
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): _readAt: size=4096, off=0
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): openPending: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: vfs cache: checking remote fingerprint "1717,2024-01-13 01:18:08 +0000 UTC" against cached fingerprint ""
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: vfs cache: truncate to size=1717
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis: Added virtual directory entry vAddFile: "project.ini"
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): >openPending: err=<nil>
2024/01/13 14:30:18 DEBUG : vfs cache: looking for range={Pos:0 Size:1717} in [] - present false
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: ChunkedReader.RangeSeek from -1 to 0 length -1
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: ChunkedReader.openRange at 0 length 134217728
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): >_readAt: n=1717, err=EOF
2024/01/13 14:30:18 DEBUG : &{projects/tta/default/monster-analysis/project.ini (rw)}: >Read: read=1717, err=<nil>
2024/01/13 14:30:18 DEBUG : &{projects/tta/default/monster-analysis/project.ini (rw)}: Flush: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): RWFileHandle.Flush
2024/01/13 14:30:18 DEBUG : &{projects/tta/default/monster-analysis/project.ini (rw)}: >Flush: err=<nil>
2024/01/13 14:30:18 DEBUG : &{projects/tta/default/monster-analysis/project.ini (rw)}: Release: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): RWFileHandle.Release
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): close: 
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini: vfs cache: setting modification time to 2024-01-13 14:18:08 +1300 NZDT
2024/01/13 14:30:18 DEBUG : projects/tta/default/monster-analysis/project.ini(0xc00074f880): >close: err=<nil>
2024/01/13 14:30:18 DEBUG : &{projects/tta/default/monster-analysis/project.ini (rw)}: >Release: err=<nil>
2024/01/13 14:30:20 DEBUG : users: forgetting directory cache
2024/01/13 14:30:20 DEBUG : : forgetting directory cache
2024/01/13 14:30:20 DEBUG : projects: forgetting directory cache
2024/01/13 14:30:20 DEBUG : projects/tta: forgetting directory cache
2024/01/13 14:30:20 DEBUG : projects/tta/default: forgetting directory cache
2024/01/13 14:30:20 DEBUG : projects/tta/default/monster-analysis: forgetting directory cache
2024/01/13 14:30:20 DEBUG : projects/tta/default/monster-analysis: Removed virtual directory entry vAddFile: "project.ini"
2024/01/13 14:30:20 DEBUG : projects/fenz: forgetting directory cache
2024/01/13 14:30:20 DEBUG : projects/gns: forgetting directory cache
2024/01/13 14:30:20 DEBUG : projects/niwa: forgetting directory cache
2024/01/13 14:30:20 DEBUG : users: forgetting directory cache

Then I did the "change file then ls && cat" steps from earlier. First one succeeded, second one failed. I can see in the logs that it says the cache fingerprint has disappeared (`checking remote fingerprint "1718,2024-01-13 01:34:34 +0000 UTC" against cached fingerprint ""``.

If it succeeds, I can see that the checking remote fingerprint log shows a correct cached fingerprint. Note that if I leave out the ls it works fine as long as I do the GET straight after the file change (maybe before the cache checker runs?).

Is this a bug? Have I misconfigured something? Is our webdav implementation missing some crucial header in the PROPFIND response?

asdffdsa · January 13, 2024, 1:42am

welcome to the forum,

as far as i know, these most/all of these flags do nothing, was for the old, deprecated cache remote

--cache-tmp-upload-path
--cache-chunk-path
--cache-workers
--cache-writes
--cache-info-age
--cache-db-path

and --checkers does nothing on a mount command

nicobrevin · January 13, 2024, 1:43am

Here's what our PROPFIND looks like:

<?xml version="1.0" encoding="utf-8" ?>
<D:multistatus xmlns:D="DAV:">
<D:response>
<D:href>/dav/projects/tta/default/</D:href>
<D:propstat>
<D:prop>
<D:creationdate>1970-01-01T00:00:00Z</D:creationdate>
<D:displayname><![CDATA[default]]></D:displayname>
<D:getlastmodified>Thu, 1 Jan 1970 12:00:00 +1200</D:getlastmodified>
<D:resourcetype>
<D:collection/>
</D:resourcetype>
<D:source></D:source>
</D:prop>
<D:status>HTTP/1.1 200 </D:status>
</D:propstat>
</D:response>
<D:response>
<D:href>/dav/projects/tta/default/monster-analysis/</D:href>
<D:propstat>
<D:prop>
<D:creationdate>1970-01-01T00:00:00Z</D:creationdate>
<D:displayname><![CDATA[Monster Analysis]]></D:displayname>
<D:getlastmodified>Thu, 1 Jan 1970 12:00:00 +1200</D:getlastmodified>
<D:resourcetype>
<D:collection/>
</D:resourcetype>
<D:source></D:source>
</D:prop>
<D:status>HTTP/1.1 200 </D:status>
</D:propstat>
</D:response>
<D:response>
<D:href>/dav/projects/tta/default/monster-analysis/project.ini</D:href>
<D:propstat>
<D:prop>
<D:creationdate>2024-01-10T00:22:27Z</D:creationdate>
<D:displayname><![CDATA[project.ini]]></D:displayname>
<D:getlastmodified>Sat, 13 Jan 2024 14:41:05 +1300</D:getlastmodified>
<D:getcontentlength>1714</D:getcontentlength>
<D:getcontenttype>application/octet-stream</D:getcontenttype>
<D:getetag>null</D:getetag>
<D:resourcetype/>
<D:source></D:source>
</D:prop>
<D:status>HTTP/1.1 200 </D:status>
</D:propstat>
</D:response>
<D:response>
<D:href>/dav/projects/tta/default/monster-analysis/cities.csv</D:href>
<D:propstat>
<D:prop>
<D:creationdate>2024-01-10T00:22:27Z</D:creationdate>
<D:displayname><![CDATA[cities.csv]]></D:displayname>
<D:getlastmodified>Thu, 11 Jan 2024 11:43:28 +1300</D:getlastmodified>
<D:getcontentlength>108</D:getcontentlength>
<D:getcontenttype>text/plain</D:getcontenttype>
<D:getetag>null</D:getetag>
<D:resourcetype/>
<D:source></D:source>
</D:prop>
<D:status>HTTP/1.1 200 </D:status>
</D:propstat>
</D:response>
</D:multistatus>

nicobrevin · January 13, 2024, 1:54am

And this is a HEAD:

HTTP/1.1 200 OK
Date: Sat, 13 Jan 2024 01:53:28 GMT
Content-Type: application/octet-stream
ETag: AAABjQB60CA=
Last-Modified: Sat, 13 Jan 2024 14:41:05 +1300
Content-Length: 1714
Server: Jetty(9.4.46.v20220331)

nicobrevin · January 13, 2024, 8:24am

Looks like rclone caches everything properly when it's mounting itself, e.g. rclone serve webdav /some/dir and then mount that locally, so I'm guessing it's something about our webdav service - figures!

Ah, no, I get the same behaviour with rclone serving itself - I just wasn't waiting long enough between changing the file and then fetching it again. I think I have a reduced test case.

mkdir mnt
mkdir data

# run this in one window
rclone -vv serve webdav $(pwd)/data --dir-cache-time=1s

# this in another
rclone -vvv mount \
       --webdav-vendor=rclone  \
       --read-only   \
       --cache-dir=/tmp \
       --vfs-cache-mode=full \
       --dir-cache-time=1s  \
       ':webdav,url="http://localhost:8080":' \
       $(pwd)/mnt

# keep doing this, with a 5s pause between echo and sleep
echo foo1 > data/test
cat mnt/test

Eventually you'll see some missing foo in the test file and if you look in the logs you'll see the empty cache entry. I think I've actually found a bug?

darthShadow · January 13, 2024, 7:43pm

Looks like your time format is wrong.

Note the error:

2024/01/13 14:30:13 ERROR : Failed to parse time "Thu, 1 Jan 1970 12:00:00 +1200" - using the epoch

The date needs to be 0-prefixed so 01.

Example: The Go Playground

darthShadow · January 13, 2024, 7:46pm

Just for reference, these are the supported formats: rclone/backend/webdav/api/types.go at master · rclone/rclone · GitHub

ncw · January 14, 2024, 12:30pm

Very nice test case

I changed the demo bit to

for i in $(seq -w 1000); do echo foo$i > data/test ; sleep 5 ; cat mnt/test ; done

Because I am lazy, and it printed this which demonstrates the problem nicely.

foo0001
foo0002
foo0002
foo0004
foo0004
foo0006
foo0006

I then tried this to see where the caching is happening... It looks like the caching isn't happening in the serve webdav

$ for i in $(seq -w 1000); do echo foo$i > data/test ; sleep 2 ; rclone cat ':webdav,vendor=rclone,url="http://localhost:8080":test'  ; done
foo0001
foo0002
foo0003
foo0004
foo0005
foo0006
foo0007
foo0008
foo0009
foo0010
foo0011

I then took the webdav server out of the equation with

rclone -vvv mount \
       --read-only   \
       --cache-dir=/tmp \
       --vfs-cache-mode=full \
       --dir-cache-time=1s  \
       $(pwd)/data \
       $(pwd)/mnt

$ for i in $(seq -w 1000); do echo foo$i > data/test ; sleep 5 ; cat mnt/test ; done
foo0001
foo0001
foo0003
foo0003
foo0005
foo0005
foo0007
foo0007

So this is nothing to do with either the webdav server or backend, but is a bug in the rclone VFS/mount interface.

In fact when it has gone wrong I see

2024/01/14 12:06:43 DEBUG : test: vfs cache: checking remote fingerprint "8,2024-01-14 12:06:11.364622473 +0000 UTC,bf5d2f440e80b3bfc821d22b4b8a8201" against cached fingerprint "8,2024-01-14 12:06:11.364622473 +0000 UTC,bf5d2f440e80b3bfc821d22b4b8a8201"

Where those MD5SUMS are of the new data, but rclone isn't returning it.

So this makes it the same bug as #6053

Which I have been trying to track down for ages, but now have a reproduction for

I've updated the issue with the reproducer and now hopefully I'll have a chance of tracking it down - thank you!

ncw · January 14, 2024, 6:00pm

Here is a potential fix for you to try

v1.66.0-beta.7607.558264b2a.fix-6053-vfs-stale-data on branch fix-6053-vfs-stale-data (uploaded in 15-30 mins)

This fixes the stale data issue when not using webdav - didn't try with webdav yet.

Let me know what you think @nicobrevin

(That took about 2 hours to find the 1 line fix needed!)

nicobrevin · January 14, 2024, 8:37pm

That looks pretty good so far! It's no longer failing in the way it was.

~~Have you got a link to the fix I can cast me eye over? I spent a bit of time eyeballing the webdav and vfs code so am interested to see the fix.~~ Never mind, found it

Is that build 'safe' to use for a while as we wait for an official release?

Thanks for the speedy response and for producing such an excellent bit of software!

ncw · January 15, 2024, 11:50am

I've made a unit test and integration tests for the fix.

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.66

If we end up making a v1.65.2 I'll put it in that too.

This is now in the beta. The betas are integration tested just like the releases are, so yes, I would say they are safe to use.

Now would be a particularly good time to take the beta as we haven't merged a lot of code in this dev cycle yet, but I plan to this week!

You are welcome! And thanks for making a nice repro for this long standing bug.