Rclone: Directory cache goes to unrestorable state when deleting cached file outside rclone (cache remote)

[idk-whatever]

What is the problem you are having with rclone?

When deleting a file outside rclone while using the cache remote it will never be deleted from the directory cache.

This happens because when a cold listing occurs, it will only cache new files/directories but doesn’t store the deletion of the deleted files.

Cold listings currently return the correct directory structure because they ignore the current cache. When a warm listing later occurs it will return a list of all the files that were ever in the cache because they are still in the cache database.

The only workaround for when a file is deleted outside rclone is to delete the cache manually and restart rclone.

My idea was to compare the cached entries to the entries from the parent remote and the locally stored temporary files in cache.List() and remove the deleted files from the directory cache but I have never used Go and I’m not familiar enough with the codebase so it will take me too much time to do it, sorry.

What is your rclone version (eg output from rclone -V)

Tested with both v1.42-005-g56e1e820β and v1.42.

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Ubuntu 18.04, 64 bit

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

Cache remote in front of the Google Drive remote

Configuration

[drive]
type = drive
client_id = ...
client_secret = ...
scope = drive
root_folder_id =
service_account_file =
token = {...}

[cache]
type = cache
remote = drive:/test
plex_url =
plex_username =
plex_password =
chunk_size = 5M
info_age = 24h
chunk_total_size = 1G

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

rclone mount -vv --allow-other --rc cache: /clouddata # Mount rclone

# Now add a file with the Google Drive web app to your drive, in my case 'file_to_be_removed.txt'
ls /clouddata # The file is not shown, as expected

rclone rc vfs/forget # Flush vfs cache
ls /clouddata # The file is not shown, as expected

rclone rc cache/expire remote=/ withData=true # Expire cache
ls /clouddata # Now the file shows up, as expected

# Remove the new file with the Google Drive web app and with the web app from the Google Drive trash
ls /clouddata # The file doesn't show up anymore. As expected. Cold listing occured because the Google Drive remote noticed the change and expired the cache during polling

rclone rc vfs/forget # Flush vfs cache
ls /clouddata # The file is back, shouldnt happen, warm listing happens and doesnt know about the file deletion

rclone rc cache/expire remote=/ withData=true # Expire cache
ls /clouddata # The file is gone again, as expected

# Now stop rclone mount and mount it again
rclone mount -vv --allow-other --rc cache: /clouddata # Mount rclone

ls /clouddata # The file is back again, shouldnt happen, warm listing happens and doesnt know about the file deletion

A log from the command with the -vv flag (eg output from rclone -vv copy /tmp remote:tmp)

/ $ rclone mount -vv --allow-other --rc cache: /clouddata
2018/06/19 17:27:34 DEBUG : rclone: Version "v1.42" starting with parameters ["rclone" "mount" "-vv" "--allow-other" "--rc" "cache:" "/clouddata"]
2018/06/19 17:27:34 DEBUG : Using config file from "/config/.config/rclone/rclone.conf"
2018/06/19 17:27:34 NOTICE: Serving remote control on http://127.0.0.1:5572/
2018/06/19 17:27:34 DEBUG : cache: wrapped drive:test at root
2018/06/19 17:27:34 INFO  : cache: Cache DB path: /config/.cache/rclone/cache-backend/cache.db
2018/06/19 17:27:34 INFO  : cache: Cache chunk path: /config/.cache/rclone/cache-backend/cache
2018/06/19 17:27:34 INFO  : cache: Chunk Memory: true
2018/06/19 17:27:34 INFO  : cache: Chunk Size: 5M
2018/06/19 17:27:34 INFO  : cache: Chunk Total Size: 1G
2018/06/19 17:27:34 INFO  : cache: Chunk Clean Interval: 1m0s
2018/06/19 17:27:34 INFO  : cache: Workers: 4
2018/06/19 17:27:34 INFO  : cache: File Age: 24h0m0s
2018/06/19 17:27:34 DEBUG : Adding path "cache/expire" to remote control registry
2018/06/19 17:27:34 DEBUG : Adding path "cache/stats" to remote control registry
2018/06/19 17:27:34 DEBUG : Cache remote cache:: Mounting on "/clouddata"
2018/06/19 17:27:34 DEBUG : Cache remote cache:: subscribing to ChangeNotify
2018/06/19 17:27:34 DEBUG : Adding path "vfs/forget" to remote control registry
2018/06/19 17:27:34 DEBUG : : Root:
2018/06/19 17:27:34 DEBUG : : >Root: node=/, err=<nil>
2018/06/19 17:27:35 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:27:35 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
2018/06/19 17:27:38 DEBUG : /: Attr:
2018/06/19 17:27:38 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:27:38 DEBUG : /: ReadDirAll:
2018/06/19 17:27:38 DEBUG : Cache remote cache:: list ''
2018/06/19 17:27:38 DEBUG : : list: error: missing cached dir:
2018/06/19 17:27:38 DEBUG : : list: read 1 from source
2018/06/19 17:27:38 DEBUG : : list: source entries: [unrelated_file.txt]
2018/06/19 17:27:38 DEBUG : : list: cached object: unrelated_file.txt
2018/06/19 17:27:38 DEBUG : : list: cached directories: 0
2018/06/19 17:27:38 DEBUG : : list: cached dir: '', cache ts: 2018-06-19 17:27:38.347478612 +0000 UTC m=+3.831839541
2018/06/19 17:27:38 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2018/06/19 17:27:38 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:27:38 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:27:38 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:27:38 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:28:13 DEBUG : /: Attr:
2018/06/19 17:28:13 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:28:13 DEBUG : /: ReadDirAll:
2018/06/19 17:28:13 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2018/06/19 17:28:13 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:28:13 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:28:13 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:28:13 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:28:13 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:28:13 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:28:13 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:28:13 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:28:20 DEBUG : form = map[]
2018/06/19 17:28:20 DEBUG : rc: "vfs/forget": with parameters map[]
2018/06/19 17:28:20 DEBUG : : forgetting directory cache
2018/06/19 17:28:20 DEBUG : rc: "vfs/forget": reply map[forgotten:[]]: <nil>
2018/06/19 17:28:24 DEBUG : /: Attr:
2018/06/19 17:28:24 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:28:24 DEBUG : /: ReadDirAll:
2018/06/19 17:28:24 DEBUG : Cache remote cache:: list ''
2018/06/19 17:28:24 DEBUG : : list: warm 1 from cache for: , expiring on: 2018-06-20 17:27:38.347478612 +0000 UTC
2018/06/19 17:28:24 DEBUG : : list: cached entries: [unrelated_file.txt]
2018/06/19 17:28:24 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2018/06/19 17:28:24 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:28:24 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:28:24 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:28:24 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:28:24 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:28:24 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:28:24 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:28:24 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:28:34 DEBUG : Cache remote cache:: starting cleanup
2018/06/19 17:28:35 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:28:35 INFO  : file_to_be_removed.txt: received cache expiry notification
2018/06/19 17:28:35 DEBUG : : forgetting directory cache
2018/06/19 17:28:35 DEBUG : Cache remote cache:: got change notification for non cached entry file_to_be_removed.txt
2018/06/19 17:28:35 DEBUG : : cache: expired
2018/06/19 17:28:35 DEBUG : file_to_be_removed.txt: notify: expired ''
2018/06/19 17:28:35 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
2018/06/19 17:29:08 DEBUG : form = map[]
2018/06/19 17:29:08 DEBUG : rc: "cache/expire": with parameters map[remote:/ withData:true]
2018/06/19 17:29:08 DEBUG : : cache: expired
2018/06/19 17:29:08 DEBUG : : forgetting directory cache
2018/06/19 17:29:08 DEBUG : rc: "cache/expire": reply map[message:cached directory cleared: / status:ok]: <nil>
2018/06/19 17:29:09 DEBUG : /: Attr:
2018/06/19 17:29:09 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:29:09 DEBUG : /: ReadDirAll:
2018/06/19 17:29:09 DEBUG : Cache remote cache:: list ''
2018/06/19 17:29:09 DEBUG : : list: cold listing: 2018-06-18 17:29:08.341999689 +0000 UTC
2018/06/19 17:29:10 DEBUG : : list: read 2 from source
2018/06/19 17:29:10 DEBUG : : list: source entries: [file_to_be_removed.txt unrelated_file.txt]
2018/06/19 17:29:10 DEBUG : : list: cached object: file_to_be_removed.txt
2018/06/19 17:29:10 DEBUG : : list: cached object: unrelated_file.txt
2018/06/19 17:29:10 DEBUG : : list: cached directories: 0
2018/06/19 17:29:10 DEBUG : : list: cached dir: '', cache ts: 2018-06-19 17:29:10.124801567 +0000 UTC m=+95.609162513
2018/06/19 17:29:10 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2018/06/19 17:29:10 DEBUG : /: Lookup: name="file_to_be_removed.txt"
2018/06/19 17:29:10 DEBUG : /: >Lookup: node=file_to_be_removed.txt, err=<nil>
2018/06/19 17:29:10 DEBUG : file_to_be_removed.txt: Attr:
2018/06/19 17:29:10 DEBUG : file_to_be_removed.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:29:10 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:29:10 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:29:10 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:29:10 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:29:10 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:29:10 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:29:10 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:29:10 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:29:34 DEBUG : Cache remote cache:: starting cleanup
2018/06/19 17:29:35 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:29:35 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
2018/06/19 17:30:34 DEBUG : Cache remote cache:: starting cleanup
2018/06/19 17:30:35 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:30:36 INFO  : file_to_be_removed.txt: received cache expiry notification
2018/06/19 17:30:36 DEBUG : : forgetting directory cache
2018/06/19 17:30:36 DEBUG : : cache: expired
2018/06/19 17:30:36 DEBUG : file_to_be_removed.txt: notify: expired ''
2018/06/19 17:30:36 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
2018/06/19 17:31:34 DEBUG : Cache remote cache:: starting cleanup
2018/06/19 17:31:36 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:31:36 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
2018/06/19 17:31:40 DEBUG : /: Attr:
2018/06/19 17:31:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:31:40 DEBUG : /: ReadDirAll:
2018/06/19 17:31:40 DEBUG : Cache remote cache:: list ''
2018/06/19 17:31:40 DEBUG : : list: cold listing: 2018-06-18 17:30:36.055451792 +0000 UTC
2018/06/19 17:31:40 DEBUG : : list: read 1 from source
2018/06/19 17:31:40 DEBUG : : list: source entries: [unrelated_file.txt]
2018/06/19 17:31:40 DEBUG : : list: cached object: unrelated_file.txt
2018/06/19 17:31:40 DEBUG : : list: cached directories: 0
2018/06/19 17:31:40 DEBUG : : list: cached dir: '', cache ts: 2018-06-19 17:31:40.601323778 +0000 UTC m=+246.085684695
2018/06/19 17:31:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2018/06/19 17:31:40 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:31:40 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:31:40 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:31:40 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:31:40 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:31:40 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:31:40 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:31:40 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:32:34 DEBUG : Cache remote cache:: starting cleanup
2018/06/19 17:32:36 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:32:36 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
2018/06/19 17:32:37 DEBUG : form = map[]
2018/06/19 17:32:37 DEBUG : rc: "vfs/forget": with parameters map[]
2018/06/19 17:32:37 DEBUG : : forgetting directory cache
2018/06/19 17:32:37 DEBUG : rc: "vfs/forget": reply map[forgotten:[]]: <nil>
2018/06/19 17:32:39 DEBUG : /: Attr:
2018/06/19 17:32:39 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:32:39 DEBUG : /: ReadDirAll:
2018/06/19 17:32:39 DEBUG : Cache remote cache:: list ''
2018/06/19 17:32:39 DEBUG : : list: warm 2 from cache for: , expiring on: 2018-06-20 17:31:40.601323778 +0000 UTC
2018/06/19 17:32:39 DEBUG : : list: cached entries: [file_to_be_removed.txt unrelated_file.txt]
2018/06/19 17:32:39 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:32:39 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2018/06/19 17:32:39 DEBUG : /: Lookup: name="file_to_be_removed.txt"
2018/06/19 17:32:39 DEBUG : /: >Lookup: node=file_to_be_removed.txt, err=<nil>
2018/06/19 17:32:39 DEBUG : file_to_be_removed.txt: Attr:
2018/06/19 17:32:40 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:32:40 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:32:40 DEBUG : file_to_be_removed.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:32:40 DEBUG : /: Lookup: name="file_to_be_removed.txt"
2018/06/19 17:32:40 DEBUG : /: >Lookup: node=file_to_be_removed.txt, err=<nil>
2018/06/19 17:32:40 DEBUG : file_to_be_removed.txt: Attr:
2018/06/19 17:32:40 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:32:40 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:32:40 DEBUG : file_to_be_removed.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:32:40 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:32:40 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:32:40 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:32:40 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:32:40 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:32:40 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:32:40 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:32:40 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:33:21 DEBUG : form = map[]
2018/06/19 17:33:21 DEBUG : rc: "cache/expire": with parameters map[remote:/ withData:true]
2018/06/19 17:33:21 DEBUG : : cache: expired
2018/06/19 17:33:21 DEBUG : : forgetting directory cache
2018/06/19 17:33:21 DEBUG : rc: "cache/expire": reply map[status:ok message:cached directory cleared: /]: <nil>
2018/06/19 17:33:34 DEBUG : Cache remote cache:: starting cleanup
2018/06/19 17:33:35 DEBUG : /: Attr:
2018/06/19 17:33:35 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:33:35 DEBUG : /: ReadDirAll:
2018/06/19 17:33:35 DEBUG : Cache remote cache:: list ''
2018/06/19 17:33:35 DEBUG : : list: cold listing: 2018-06-18 17:33:21.382760928 +0000 UTC
2018/06/19 17:33:35 DEBUG : : list: read 1 from source
2018/06/19 17:33:35 DEBUG : : list: source entries: [unrelated_file.txt]
2018/06/19 17:33:35 DEBUG : : list: cached object: unrelated_file.txt
2018/06/19 17:33:35 DEBUG : : list: cached directories: 0
2018/06/19 17:33:35 DEBUG : : list: cached dir: '', cache ts: 2018-06-19 17:33:35.450929913 +0000 UTC m=+360.935290850
2018/06/19 17:33:35 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2018/06/19 17:33:35 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:33:35 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:33:35 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:33:35 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:33:35 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:33:35 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:33:35 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:33:35 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:33:36 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:33:36 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
^C2018/06/19 17:34:18 DEBUG : rclone: Version "v1.42" finishing with parameters ["rclone" "mount" "-vv" "--allow-other" "--rc" "cache:" "/clouddata"]
2018/06/19 17:34:18 DEBUG : Cache remote cache:: Services stopped
/ $ rclone mount -vv --allow-other --rc cache: /clouddata
2018/06/19 17:35:11 DEBUG : rclone: Version "v1.42" starting with parameters ["rclone" "mount" "-vv" "--allow-other" "--rc" "cache:" "/clouddata"]
2018/06/19 17:35:11 DEBUG : Using config file from "/config/.config/rclone/rclone.conf"
2018/06/19 17:35:11 NOTICE: Serving remote control on http://127.0.0.1:5572/
2018/06/19 17:35:12 DEBUG : cache: wrapped drive:test at root
2018/06/19 17:35:12 INFO  : cache: Cache DB path: /config/.cache/rclone/cache-backend/cache.db
2018/06/19 17:35:12 INFO  : cache: Cache chunk path: /config/.cache/rclone/cache-backend/cache
2018/06/19 17:35:12 INFO  : cache: Chunk Memory: true
2018/06/19 17:35:12 INFO  : cache: Chunk Size: 5M
2018/06/19 17:35:12 INFO  : cache: Chunk Total Size: 1G
2018/06/19 17:35:12 INFO  : cache: Chunk Clean Interval: 1m0s
2018/06/19 17:35:12 INFO  : cache: Workers: 4
2018/06/19 17:35:12 INFO  : cache: File Age: 24h0m0s
2018/06/19 17:35:12 DEBUG : Adding path "cache/expire" to remote control registry
2018/06/19 17:35:12 DEBUG : Adding path "cache/stats" to remote control registry
2018/06/19 17:35:12 DEBUG : Cache remote cache:: Mounting on "/clouddata"
2018/06/19 17:35:12 DEBUG : Cache remote cache:: subscribing to ChangeNotify
2018/06/19 17:35:12 DEBUG : Adding path "vfs/forget" to remote control registry
2018/06/19 17:35:12 DEBUG : : Root:
2018/06/19 17:35:12 DEBUG : : >Root: node=/, err=<nil>
2018/06/19 17:35:12 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:35:12 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.
2018/06/19 17:35:35 DEBUG : /: Attr:
2018/06/19 17:35:35 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/06/19 17:35:35 DEBUG : /: ReadDirAll:
2018/06/19 17:35:35 DEBUG : Cache remote cache:: list ''
2018/06/19 17:35:35 DEBUG : : list: warm 2 from cache for: , expiring on: 2018-06-20 17:33:35.450929913 +0000 UTC
2018/06/19 17:35:35 DEBUG : : list: cached entries: [file_to_be_removed.txt unrelated_file.txt]
2018/06/19 17:35:36 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:35:36 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2018/06/19 17:35:36 DEBUG : /: Lookup: name="file_to_be_removed.txt"
2018/06/19 17:35:36 DEBUG : /: >Lookup: node=file_to_be_removed.txt, err=<nil>
2018/06/19 17:35:36 DEBUG : file_to_be_removed.txt: Attr:
2018/06/19 17:35:36 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:35:36 ERROR : file_to_be_removed.txt: error refreshing object in : in cache fs Google drive root 'test': object not found
2018/06/19 17:35:36 DEBUG : file_to_be_removed.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2018/06/19 17:35:36 DEBUG : /: Lookup: name="unrelated_file.txt"
2018/06/19 17:35:36 DEBUG : /: >Lookup: node=unrelated_file.txt, err=<nil>
2018/06/19 17:35:36 DEBUG : unrelated_file.txt: Attr:
2018/06/19 17:35:36 DEBUG : unrelated_file.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
^C2018/06/19 17:35:53 DEBUG : rclone: Version "v1.42" finishing with parameters ["rclone" "mount" "-vv" "--allow-other" "--rc" "cache:" "/clouddata"]
2018/06/19 17:35:53 DEBUG : Cache remote cache:: Services stopped
/ $

[ncw]

Thank you for your informative bug report.

From this bit of your log

2018/06/19 17:28:35 DEBUG : Google drive root 'test': Checking for changes on remote
2018/06/19 17:28:35 INFO  : file_to_be_removed.txt: received cache expiry notification
2018/06/19 17:28:35 DEBUG : : forgetting directory cache
2018/06/19 17:28:35 DEBUG : Cache remote cache:: got change notification for non cached entry file_to_be_removed.txt
2018/06/19 17:28:35 DEBUG : : cache: expired
2018/06/19 17:28:35 DEBUG : file_to_be_removed.txt: notify: expired ''
2018/06/19 17:28:35 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.

It looks like rclone successfully got a change request from drive and flushed the cache at that point.

I tried your above experiment, but after deleting the file I waited until I saw the Google drive root 'test': All changes were processed. Waiting for more. before listing the mount. At that point the file was gone - no flushing anything required.

Do you see this too?

Note that by default the change poll interval is 1 minute.

  --poll-interval duration             Time to wait between polling for changes. Must be smaller than dir-cache-time. Only on supported remotes. Set to 0 to disable. (default 1m0s)

[idk-whatever]

Thank you! Yes, that is expected.

When the Google Drive remote polls the changes, or when you manually expire the cache both the vfs cache and the cache remote cache are expired. (vfs cache is logged as: forgetting directory cache and cache remote cache is logged as: cache: expired).

It comes back when the vfs cache is expired and the cache remote cache isn’t expired. So if you list the directory structure and --dir-cache-time is expired while --cache-info-age isn’t expired it should show the files again.

You can see the code I mean in the issue here: backend/cache/cache.go#L673-L773

When List() is called and the CacheTs of a directory is expired or the directory is non-existent in the cache, it does a cold listing, so it retrieves the directory structure from Google Drive and returns that structure merged with the temporary files stored locally. If an object doesn’t exist in the current cache it adds it to the cache. This happens on line 710 for new temporary files and line 741 for files that are uploaded externally. But when a file is deleted it doesn’t remove it from the cache.

So later, when List() is called and the CacheTs of the directory isn’t expired, it returns the directory structure with GetDirEntries but the deleted files are still in there.

I think this also applies to subdirectories of the listed directory but I’m not sure.

When I was writing this I also saw line 692 // FIXME need to clean existing cached listing (I completely overlooked it the whole time). That is actually what I think is causing the issue.

[ncw]

It comes back when the vfs cache is expired and the cache remote cache isn’t expired. So if you list the directory structure and --dir-cache-time is expired while --cache-info-age isn’t expired it should show the files again.

Oh I see...

@remusb any idea how to fix this?

(We should really get our heads together and work out how to make the vfs caching layer use the cache backend directly if it can.)