Rclone cache expiry notification / accessing same remote with & without cache

disclaimer: This is long and most likely silliness of mine

What is your rclone version (output from rclone version)

rclone v1.45

  • os/arch: linux/amd64
  • go version: go1.11.6

OS: Debian 10 x86 64bit
remote: Google Drive

What is the problem you are having with rclone?

I have been using r1: GDrive -> crypt for few weeks and wanted to try the cache, so I created a new remote r2: GDrive -> cache -> crypt.
Once I mounted r2 I saw the logs being swamped with fileX: received cache expiry notification on pretty much all files. From what I could see it did this for multiple passes till I unmounted the remote.
Furthermore in the logs (set to INFO) I saw some lines like 6djg4: received cache expiry notification which looks like an encrypted dir name.
So there was a mix of decrypted paths and encrypted dir names. I did not see something resembling an encrypted dir/filename.

After remounting r2 it appeared to work ok.

ps: while I was trying the above & below I was running rclone copy -vP --transfers=1 --log-file=rclone.log --drive-chunk-size 32M /local/ r1: to update the remote so only adding a couple of files in like < 1% of the dirs in the remote.

I unmounted r2 and tried again after a bit using -vv (DEBUG). Same cache expiry notification, but looked like it did it once for all files. As a bonus when I tried to ls -l /mnt/somedir the ls got stuck and got (most likely this):

2020/02/12 21:39:08 DEBUG : /: Attr:
2020/02/12 21:39:08 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/02/12 21:39:10 DEBUG : /: Attr:
2020/02/12 21:39:10 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/02/12 21:39:10 DEBUG : /: ReadDirAll:
2020/02/12 21:39:10 DEBUG : /: >ReadDirAll: item=1187, err=<nil>
2020/02/12 21:39:11 DEBUG : /: Attr:
2020/02/12 21:39:11 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/02/12 21:39:11 DEBUG : /: ReadDirAll:
2020/02/12 21:39:11 DEBUG : /: >ReadDirAll: item=1187, err=<nil>
2020/02/12 21:39:11 DEBUG : /: Attr:
2020/02/12 21:39:11 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/02/12 21:39:11 DEBUG : /: Lookup: name="naruto_shippuuden"
2020/02/12 21:39:11 DEBUG : /: >Lookup: node=naruto_shippuuden/, err=<nil>
2020/02/12 21:39:11 DEBUG : naruto_shippuuden/: Attr:
2020/02/12 21:39:11 DEBUG : naruto_shippuuden/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/02/12 21:39:11 DEBUG : /: Lookup: name="naruto_shippuuden"
2020/02/12 21:39:11 DEBUG : /: >Lookup: node=naruto_shippuuden/, err=<nil>
2020/02/12 21:39:11 DEBUG : naruto_shippuuden/: Attr:
2020/02/12 21:39:11 DEBUG : naruto_shippuuden/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/02/12 21:39:12 DEBUG : naruto_shippuuden/: ReadDirAll:
2020/02/12 21:39:37 DEBUG : Cache remote google_cache:: starting cleanup

I could replicate that by opening another terminal. After several minutes it started working again.

In the log with debug entries appeared fine, INFO had the decrypted and DEBUG had the encrypted names:

2020/02/12 21:41:35 INFO  : shounen_ashibe/[HorribleSubs] Shounen Ashibe Go! Go! Goma-chan - 22 [720p].mkv: received cache expiry notification
2020/02/12 21:41:35 DEBUG : b1m: cache: expired b1m
2020/02/12 21:41:35 DEBUG : b1m: cache: expired
2020/02/12 21:41:35 DEBUG : b1m/r5huai7v1q0: notify: expired 'b1m'

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

rclone mount --allow-other --log-level INFO --log-file=cache_rclone.log r2: /mnt

To me it looks like the copy is messing with the cache. I would expect that for the dirs the copy is not adding files in, the cache shouldn't be affected at all. Unless it gets nuked on remount. Though most likely I am mixing up something basic!

I am including my config.

[g1]
type = drive

[r1]
type = crypt
remote = g1:top_dir
filename_encryption = standard
directory_name_encryption = true

[g1_cache]
type = cache
remote = g1:top_dir
info_age = 1h0m0s

[r2]
type = crypt
remote = g1_cache:
filename_encryption = standard
directory_name_encryption = true

Can you retry with a later rclone? The latest release is 1.51.0

EDIT: messed up versions - post updated

v1.51.0 works fine. There is no cache expiry at mount, tried some combos with the copy for sanity's sake.
Only got some file re-uploaded due to different way of handling invalid UTF-8 characters between v1.45 and v1.51

For v1.45 found the cause for the ls freeze.
The combination of starting the copy (quite a lot of checks) + remounting (which causes the caches to expire - even more actions) + ls == limits

2020/02/12 22:37:47 DEBUG : pacer: Rate limited, sleeping for 8.737205064s (4 consecutive low level retries)
2020/02/12 22:37:47 DEBUG : pacer: low level retry 4/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API
 and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=0, userRateLimitExceeded)

Great!

That is annoying but to be expected.

That will only be a problem if it reaches 10/10 but it will cause delays. 1.51 has a better pacer so it doesn't trip this so often.

Max it reached was 4, it hit 2-3 couple of times though. It's quite troublesome 1.45 is the latest in buster.

I should create a new post for some questions about configuring cache right?