Rclone mount macOS local cache not updated

Suspected Bug
1

What is the problem you are having with rclone?

On macOS, rclone mount randomly doesn't update detected changes in the cache. It updates the last change time of file when using ls but doesn't update the file itself (twice on 3).
I have tried several rclone version, from curl, from source, without and with cmount tag (current version).
As I use the full cache mode, it seems that the problem occurs when there is already cached files. If I remove the files in the cache before starting the rclone mount, the updates seem to work.

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

./rclone version
rclone v1.58.0-beta.5979.051685baa

  • os/version: darwin 12.1 (64 bit)
  • os/kernel: 21.2.0 (x86_64)
  • os/type: darwin
  • os/arch: amd64
  • go/version: go1.17.6
  • go/linking: dynamic
  • go/tags: cmount

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

Google Drive

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

./rclone mount --cache-dir /cache_dir --vfs-cache-mode full --vfs-cache-max-age 240h --vfs-read-chunk-size 1M --vfs-read-chunk-size-limit 5M /path/to/drive /local/path/ -vv > rclone.log 2>&1

The rclone config contents with secrets removed.

[Drive]
type = drive
client_id = XXX.apps.googleusercontent.com
client_secret = XXX
scope = drive
token = {"access_token":"my_token","token_type":"Bearer","refresh_token":"refresh","expiry":"2022-01-29T21:28:51.943254+01:00"}
team_drive =

A log from the command with the -vv flag

2

How do you recreate the issue?

  1. File is downloaded in the mount
  2. File is read from the mount
  3. What changes the file? You modify outside the mount?
  4. Changed file is read but different?

What file is the log shows this behavior?
What's the timestamp of when it was changed in the log?

3

Hi,
On my macOS machine, rclone mount from Google drive to a local folder with, I guess, an existing cache. Any changes on the drive from another machine (also mounted) will cause this behavior. rclone shows that the file has changed but doesn't update the local cache with it.
In the log file, we can see (line 1526) that it succeeded to update the cache but then we don't see it anymore for others test changes I made (then no particular log I guess as it doesn't consider there is a change).

However, any change I made in the macOS machine will be uploaded.

4

Without very specific steps/details, I have no idea what you are doing.

2022/01/29 20:52:12 DEBUG : file.ad: vfs cache: removing cached entry as stale (remote fingerprint "168554,2022-01-29 19:50:19.502 +0000 UTC,8e95994590975a51fa121b90829d735b" != cached fingerprint "168552,2022-01-29 19:47:56.595 +0000 UTC,5bd8cf1d0d7149843ea85647c373172e")
2022/01/29 20:52:12 DEBUG : /: Access: mask=00
2022/01/29 20:52:12 DEBUG : /: >Access: errc=0
2022/01/29 20:52:12 INFO  : file.ad: vfs cache: removed cache file as stale (remote is different)
2022/01/29 20:52:12 DEBUG : file.ad: vfs cache: removed metadata from cache as stale (remote is different)
2022/01/29 20:52:12 DEBUG : file.ad: vfs cache: truncate to size=168554
2022/01/29 20:52:12 DEBUG : : Added virtual directory entry vAddFile: "file.ad"
2022/01/29 20:52:12 DEBUG : file.ad(0xc0009da180): >openPending: err=<nil>
2022/01/29 20:52:12 DEBUG : vfs cache: looking for range={Pos:0 Size:4096} in [] - present false
2022/01/29 20:52:12 DEBUG : file.ad: ChunkedReader.RangeSeek from -1 to 0 length -1
2022/01/29 20:52:12 DEBUG : file.ad: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 1048576
2022/01/29 20:52:12 DEBUG : file.ad: ChunkedReader.openRange at 0 length 1048576
2022/01/29 20:52:12 DEBUG : /: Access: mask=01
2022/01/29 20:52:12 DEBUG : /: >Access: errc=0
2022/01/29 20:52:12 DEBUG : /-: Getattr: fh=0xFFFFFFFFFFFFFFFF
2022/01/29 20:52:12 DEBUG : /-: >Getattr: errc=-2
2022/01/29 20:52:13 DEBUG : file.ad: ChunkedReader.Read at 32768 length 32768 chunkOffset 0 chunkSize 1048576
2022/01/29 20:52:13 DEBUG : file.ad(0xc0009da180): >_readAt: n=4096, err=<nil>
2022/01/29 20:52:13 DEBUG : /file.ad: >Read: n=4096
2022/01/29 20:52:13 DEBUG : /file.ad: Read: ofst=4096, fh=0x0
2022/01/29 20:52:13 DEBUG : file.ad(0xc0009da180): _readAt: size=4096, off=4096
2022/01/29 20:52:13 DEBUG : vfs cache: looking for range={Pos:4096 Size:4096} in [{Pos:0 Size:32768}] - present true
2022/01/29 20:52:13 DEBUG : file.ad(0xc0009da180): >_readAt: n=4096, err=<nil>

That line 1526 looks fine as it found a change, invalidated the cache and re-read the file.

What other changes? What's the other machine? What mount is it running? What OS? What version? What log file that shows a change?

5

I use rclone mount on another machine (archlinux), with the last rclone version, in order to have a shared folder (with the macOS one). When I perform a change on the Arch machine, the cache on the other macOS machine doesn't update (most of the time).

In this log file, the first change I made from the Arch machine triggered an update ont eh macOS machine involving a log:
2022/01/29 20:52:12 INFO : file.ad: vfs cache: removed cache file as stale (remote is different)

However, I made other changes after this moment and there is no other log entries specifying the same event. And this is my issue. 2 times on 3, on vfs changes it doesn't update the cache.

6

Need the rclone version output.

I can't see your machine.

If you want to take the time to write up the steps, share the logs from both machines and be specific in what you are doing, we can figure out if there is an issue.

7

The rclone version of my archlinux machine

rclone version
rclone v1.57.0
- os/version: arch rolling (64 bit)
- os/kernel: 5.16.1-arch1-1 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.17.5
- go/linking: dynamic
- go/tags: none

The steps

Purpose

I want to share folders between two machines (macOS and archlinux) to work on synchronized data in either machines.

Configuration

I use rclone mount on the 2 machine.

When I perform a change on the archlinux machine, the cache on the macOS machine doesn't update (most of the time). But it seems to work perfectly in the other way. So I think the problem is only on the macOS machine and it is not needed to investigate the archlinux machine. Then I don't see the point to furnish these logs.

I have the impression that my explanations are clear enough and my investigation specific enough to focus on what it seems (to me) to be the problem. The macOS machine always see the changes after a poll (every minute) and is able to indicate the changes (by time) with a ls command but doesn't update the files. Do you have an idea about what is concerned by the update process ?

Also, it seems that if there is no cache on the macOS machine when performing the mount, the issue doesn't happen.

8

Good luck as without logs from each side, I can't do anything else.

9

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