Cache fingerprint miss behavior leading to false positive stalen cache

What is the problem you are having with rclone?

Fingerprint generation is not stable, sometimes it does integrate millisecond in the timestamp, sometimes it does not.
This lead to compare different and cache clear and download again files.
I can reproduce the issue on x86_64 and arm (rpi3, 32 bits mode)

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

rclone v1.60.0-DEV

  • os/version: kaos 2022 (64 bit)
  • os/kernel: 5.18.17-1 (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.19.1
  • go/linking: dynamic
  • go/tags: cmount

rclone v1.60.0-DEV

  • os/version: libreelec 10.0.2
  • os/kernel: 5.10.95 (armv7l)
  • os/type: linux
  • os/arch: arm
  • go/version: go1.19.1
  • go/linking: static
  • go/tags: none

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

StorJ via le S3 gateway

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

./rclone mount storj-s3-pasnox-XXX:xxx /var/media/XXX --async-read --allow-other --attr-timeout=1h --dir-cache-time=720h --poll-interval=0 --vfs-cache-max-age=720h --no-checksum --no-modtime --no-seek --read-only --use-server-modtime --vfs-cache-mode=full --config /storage/rclone/config/rclone.conf --cache-dir=/storage/rclone/cache --verbose

The rclone config contents with secrets removed.

[storj-s3-pasnox-XXX]
type = s3
provider = Other
access_key_id = 
secret_access_key = 
endpoint = https://gateway.eu1.storjshare.io

A log from the command with the -vv flag

<3>ERROR : XXX/005.zip.rclonelink: vfs cache: removing cached entry as stale (remote fingerprint "37,2022-02-11 21:34:44 +0000 UTC,5bb7dd962b1a73fb6968df03fae64f27" != cached fingerprint "37,2022-02-11 21:34:44.557 +0000 UTC,5bb7dd962b1a73fb6968df03fae64f27")
<6>INFO  : XXX/005.zip.rclonelink: vfs cache: removed cache file as stale (remote is different)

Please note that to then trigger the issue, just try to cat same file twice

cat /path/to/mount/XXX/005.zip.rclonelink &> /dev/null
cat /path/to/mount/XXX/005.zip.rclonelink &> /dev/null
...
cat /path/to/mount/XXX/19xxh.zip &> /dev/null
cat /path/to/mount/XXX/19xxh.zip &> /dev/null

Any chance you can recreate it and share the full debug log for one instance?

<7>DEBUG : rclone: Version "v1.60.0-DEV" starting with parameters ["./rclone" "mount" "storj-s3-pasnox-xxx:xxx" "/home/pasnox/Projects/rclone/_tmp/bin/../XXXX" "--async-read" "--allow-other" "--attr-timeout=1h" "--dir-cache-time=720h" "--poll-interval=0" "--vfs-cache-max-age=720h" "--no-checksum" "--no-modtime" "--no-seek" "--read-only" "--use-server-modtime" "--vfs-cache-mode=full" "--config" "/home/pasnox/Projects/rclone/_tmp/bin/../config/rclone.conf" "--cache-dir=/home/pasnox/Projects/rclone/_tmp/bin/../cache" "-vv"]
<7>DEBUG : rclone: systemd logging support activated
<7>DEBUG : Creating backend with remote "storj-s3-pasnox-xxx:xxx"
<7>DEBUG : Using config file from "/home/pasnox/Projects/rclone/_tmp/config/rclone.conf"
<7>DEBUG : vfs cache: root is "/home/pasnox/Projects/rclone/_tmp/cache"
<7>DEBUG : vfs cache: data root is "/home/pasnox/Projects/rclone/_tmp/cache/vfs/storj-s3-pasnox-xxx/xxx"
<7>DEBUG : vfs cache: metadata root is "/home/pasnox/Projects/rclone/_tmp/cache/vfsMeta/storj-s3-pasnox-xxx/xxx"
<7>DEBUG : Creating backend with remote "/home/pasnox/Projects/rclone/_tmp/cache/vfs/storj-s3-pasnox-xxx/xxx"
<7>DEBUG : Creating backend with remote "/home/pasnox/Projects/rclone/_tmp/cache/vfsMeta/storj-s3-pasnox-xxx/xxx"
<7>DEBUG : S3 bucket xxx: Mounting on "/home/pasnox/Projects/rclone/_tmp/bin/../XXXX"
<6>INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<7>DEBUG : : Root: 
<7>DEBUG : : >Root: node=/, err=<nil>
<7>DEBUG : /: Lookup: name="XXXX"
<7>DEBUG : /: >Lookup: node=XXXX/, err=<nil>
<7>DEBUG : XXXX/: Attr: 
<7>DEBUG : XXXX/: >Attr: attr=valid=1h0m0s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
<7>DEBUG : XXXX/: Lookup: name="Sub"
<7>DEBUG : XXXX/: >Lookup: node=XXXX/Sub/, err=<nil>
<7>DEBUG : XXXX/Sub/: Attr: 
<7>DEBUG : XXXX/Sub/: >Attr: attr=valid=1h0m0s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
<7>DEBUG : XXXX/Sub/: Lookup: name="file.zip"
<7>DEBUG : XXXX/Sub/: >Lookup: node=XXXX/Sub/file.zip, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip: Attr: 
<7>DEBUG : XXXX/Sub/file.zip: >Attr: a=valid=1h0m0s ino=0 size=1548250 mode=-rw-r--r--, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip: Open: flags=OpenReadOnly
<7>DEBUG : XXXX/Sub/file.zip: Open: flags=O_RDONLY
<7>DEBUG : XXXX/Sub/file.zip: newRWFileHandle: 
<7>DEBUG : XXXX/Sub/file.zip: >newRWFileHandle: err=<nil>
<7>DEBUG : XXXX/Sub/file.zip: >Open: fd=XXXX/Sub/file.zip (rw), err=<nil>
<7>DEBUG : XXXX/Sub/file.zip: >Open: fh=&{XXXX/Sub/file.zip (rw)}, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=0
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=0
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=131072
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): openPending: 
<7>DEBUG : XXXX/Sub/file.zip: vfs cache: checking remote fingerprint "1548250,2022-02-11 21:34:47.93 +0000 UTC,b5bb0b2b8657ebf16dd0821ebd5459bd" against cached fingerprint ""
<7>DEBUG : XXXX/Sub/file.zip: vfs cache: truncate to size=1548250
<7>DEBUG : XXXX/Sub: Added virtual directory entry vAddFile: "file.zip"
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >openPending: err=<nil>
<7>DEBUG : vfs cache: looking for range={Pos:0 Size:131072} in [] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=131072
<7>DEBUG : vfs cache: looking for range={Pos:131072 Size:131072} in [] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.openRange at 0 length 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=262144
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=262144
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=393216
<7>DEBUG : vfs cache: looking for range={Pos:262144 Size:131072} in [{Pos:0 Size:258048}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=393216
<7>DEBUG : vfs cache: looking for range={Pos:393216 Size:131072} in [{Pos:0 Size:258048}] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=524288
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=655360
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=524288
<7>DEBUG : vfs cache: looking for range={Pos:524288 Size:131072} in [{Pos:0 Size:520192}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=655360
<7>DEBUG : vfs cache: looking for range={Pos:655360 Size:131072} in [{Pos:0 Size:520192}] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=917504
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=917504
<7>DEBUG : vfs cache: looking for range={Pos:917504 Size:131072} in [{Pos:0 Size:1044480}] - present false
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=786432
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=786432
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=1048576
<7>DEBUG : vfs cache: looking for range={Pos:786432 Size:131072} in [{Pos:0 Size:1044480}] - present true
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=1048576
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=1179648
<7>DEBUG : vfs cache: looking for range={Pos:1048576 Size:131072} in [{Pos:0 Size:1044480}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=1179648
<7>DEBUG : vfs cache: looking for range={Pos:1179648 Size:131072} in [{Pos:0 Size:1044480}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=1310720
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=106496, offset=1441792
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=131072, off=1310720
<7>DEBUG : vfs cache: looking for range={Pos:1310720 Size:131072} in [{Pos:0 Size:1548250}] - present true
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): _readAt: size=106496, off=1441792
<7>DEBUG : vfs cache: looking for range={Pos:1441792 Size:106458} in [{Pos:0 Size:1548250}] - present true
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >_readAt: n=106458, err=EOF
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=106458, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Flush: 
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): RWFileHandle.Flush
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Flush: err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Release: 
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): RWFileHandle.Release
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): close: 
<7>DEBUG : XXXX/Sub/file.zip: vfs cache: setting modification time to 2022-02-11 21:34:47 +0000 UTC
<7>DEBUG : XXXX/Sub/file.zip(0xc0012fc0c0): >close: err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Release: err=<nil>
<7>DEBUG : XXXX/Sub/file.zip: Open: flags=OpenReadOnly
<7>DEBUG : XXXX/Sub/file.zip: Open: flags=O_RDONLY
<7>DEBUG : XXXX/Sub/file.zip: newRWFileHandle: 
<7>DEBUG : XXXX/Sub/file.zip: >newRWFileHandle: err=<nil>
<7>DEBUG : XXXX/Sub/file.zip: >Open: fd=XXXX/Sub/file.zip (rw), err=<nil>
<7>DEBUG : XXXX/Sub/file.zip: >Open: fh=&{XXXX/Sub/file.zip (rw)}, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=0
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=0
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=131072
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): openPending: 
<7>DEBUG : XXXX/Sub/file.zip: vfs cache: checking remote fingerprint "1548250,2022-02-11 21:34:47 +0000 UTC,b5bb0b2b8657ebf16dd0821ebd5459bd" against cached fingerprint "1548250,2022-02-11 21:34:47.93 +0000 UTC,b5bb0b2b8657ebf16dd0821ebd5459bd"
<6>INFO  : XXXX/Sub/file.zip: vfs cache: removed cache file as stale (remote is different)
<7>DEBUG : XXXX/Sub/file.zip: vfs cache: removed metadata from cache as stale (remote is different)
<7>DEBUG : XXXX/Sub/file.zip: vfs cache: truncate to size=1548250
<7>DEBUG : XXXX/Sub: Added virtual directory entry vAddFile: "file.zip"
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >openPending: err=<nil>
<7>DEBUG : vfs cache: looking for range={Pos:0 Size:131072} in [] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.RangeSeek from -1 to 0 length -1
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=131072
<7>DEBUG : vfs cache: looking for range={Pos:131072 Size:131072} in [] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.openRange at 0 length 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=262144
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=262144
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=393216
<7>DEBUG : vfs cache: looking for range={Pos:262144 Size:131072} in [{Pos:0 Size:258048}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=393216
<7>DEBUG : vfs cache: looking for range={Pos:393216 Size:131072} in [{Pos:0 Size:258048}] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=524288
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=655360
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=524288
<7>DEBUG : vfs cache: looking for range={Pos:524288 Size:131072} in [{Pos:0 Size:520192}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=655360
<7>DEBUG : vfs cache: looking for range={Pos:655360 Size:131072} in [{Pos:0 Size:520192}] - present false
<7>DEBUG : XXXX/Sub/file.zip: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=786432
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=786432
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=1048576
<7>DEBUG : vfs cache: looking for range={Pos:786432 Size:131072} in [{Pos:0 Size:1044480}] - present true
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=917504
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=1179648
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=1048576
<7>DEBUG : vfs cache: looking for range={Pos:1048576 Size:131072} in [{Pos:0 Size:1044480}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=917504
<7>DEBUG : vfs cache: looking for range={Pos:917504 Size:131072} in [{Pos:0 Size:1044480}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=1179648
<7>DEBUG : vfs cache: looking for range={Pos:1179648 Size:131072} in [{Pos:0 Size:1044480}] - present false
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=131072, offset=1310720
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Read: len=106496, offset=1441792
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=131072, off=1310720
<7>DEBUG : vfs cache: looking for range={Pos:1310720 Size:131072} in [{Pos:0 Size:1548250}] - present true
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=131072, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=131072, err=<nil>
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): _readAt: size=106496, off=1441792
<7>DEBUG : vfs cache: looking for range={Pos:1441792 Size:106458} in [{Pos:0 Size:1548250}] - present true
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >_readAt: n=106458, err=EOF
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Read: read=106458, err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Flush: 
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): RWFileHandle.Flush
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Flush: err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: Release: 
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): RWFileHandle.Release
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): close: 
<7>DEBUG : XXXX/Sub/file.zip: vfs cache: setting modification time to 2022-02-11 21:34:47 +0000 UTC
<7>DEBUG : XXXX/Sub/file.zip(0xc000067900): >close: err=<nil>
<7>DEBUG : &{XXXX/Sub/file.zip (rw)}: >Release: err=<nil>

I tried to replicate this with AWS S3 and it doesn't replicate.

It does reproduce with Storj S3.

What is happening is that Storj is giving back different times in the listing

<ListBucketResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/">
[snip]
  <Contents>
    <Key>test.txt</Key>
    <LastModified>2022-03-01T16:22:11.445Z</LastModified>                      ###### This has decimal places
    <ETag>&#34;6a6d8d4533507d490ab007dfe8314ab7-1&#34;</ETag>
    <Size>6</Size>
    <Owner>
      <ID>02d6176db174dc93cb1b899f7c6078f08654445fe8cf1b6ce98d8855f66bdbf4</ID>
      <DisplayName>minio</DisplayName>
    </Owner>
    <StorageClass>STANDARD</StorageClass>
  </Contents>
[snip]

And in HEAD/GET requests

2022/10/08 10:34:03 DEBUG : GET /test.txt HTTP/1.1
Host: rclone.gateway.eu1.storjshare.io
User-Agent: rclone/v1.60.0-beta.6480.9bf78d037
Accept-Encoding: gzip
Authorization: XXXX
Range: bytes=0-5
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20221008T093403Z

2022/10/08 10:34:04 DEBUG : HTTP RESPONSE (req 0xc000b36c00)
2022/10/08 10:34:04 DEBUG : HTTP/2.0 206 Partial Content
Content-Length: 6
Accept-Ranges: bytes
Content-Range: bytes 0-5/6
Content-Security-Policy: block-all-mixed-content
Content-Type: text/plain; charset=utf-8
Date: Sat, 08 Oct 2022 09:34:04 GMT
Etag: "6a6d8d4533507d490ab007dfe8314ab7-1"
Last-Modified: Tue, 01 Mar 2022 16:22:11 GMT                ###### this has no decimal places
S3: etag: 6a6d8d4533507d490ab007dfe8314ab7-1
Server: MinIO
Vary: Origin
X-Amz-Request-Id: 171C0E432EC6155A
X-Xss-Protection: 1; mode=block

hello

I think this could happen on AWS too if you had versions enabled - normally times have .000 timestamps in AWS unless you have versions - do you have versions enabled on your bucket?

Ultimately this is caused by the --use-server-modtime flag.

I had a go at fixing this - this tries to preserve the precision in the last modified flag.

v1.60.0-beta.6481.42722a311.fix-s3-use-server-modtime on branch fix-s3-use-server-modtime (uploaded in 15-30 mins)

PS you'd be better off removing --no-modtime from your flags - using --use-server-modtime alone will give better results I think.

Hi Nick,

Thanks for your quick and prompt reply.
I did not enabled versions on my own, so I don't know.
I tried to check in the various settings the storj interface give me and I did not found something related to versioning of files either.

I removed the --no-modtime and it indeed fix the cat case, but, If I try to ls -al /path/to/files then the issue come back again (using the same binary as before, ie, I did not yet tested your provided binary because it does not have the mount symlinks support).

Does your workaround pass for you when using ls -al /path/to/files ?

EDIT: I tested your binary, and it fix both cat and ls, but I would also like/want to test it with my mount symlinks support.
Can you merge it and rebase the pasnox -symlinks branch on that please ?

I tested both the normal binaries and the mount/symlinks variant and it now works fine with this change (and the removal of the --no-modtime flag).
We can close this issues as fixed.

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

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