Google Drive change polling and cache invalidation


#1

I’ve been having trouble with new files not showing up on my google drive mount when using the cache backend in Rclone v1.40. I have dir-cache-time and cache-info-age both set to 1 week (168h).

I’m under the impression that the GD change polling should be invalidating the cache automatically… is that correct? If so, does this affect both dir-cache-time and cache-info-age? Should I be setting one or the other? The docs are rather confusing as to what the actual difference is between those options.

Any advice would be appreciated. :slight_smile:


Rclone move not updating cache mount
Using rclone cache with unionfs?
#2

I had the same question. I added a few things via an rclone upload and I don’t see them showing up on my cached mount.


#3

currently if you add a file in a new parent directory that is not known to rclone cache, it will not show up in the rclone mount.
please see this issue https://github.com/ncw/rclone/issues/2155


#4

I’ve been following that issue as well, but in my case I’m seeing issues with the cache when adding files to existing directories that are already cached. I’ve run a test-case as follows:

  • I have a directory on my encrypted GD in the root called test, with an existing file named test1.txt.
  • After I mount the drive with rclone, I cd to test and run ls to cache the directory.
  • On a separate server, I copy a new file called test2.txt into the “test” directory.
  • I wait for the rclone mount to poll for changes, it recognizes that a new file has been added, but when I then ls in the test directory, the new file does not appear.

Here is the log from rclone:

2018/03/28 08:17:17 DEBUG : /: Lookup: name="test"
2018/03/28 08:17:17 DEBUG : /: >Lookup: node=test/, err=<nil>
2018/03/28 08:17:17 DEBUG : test/: Attr:
2018/03/28 08:17:17 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/03/28 08:17:17 DEBUG : test/: ReadDirAll:
2018/03/28 08:17:17 DEBUG : Cache remote gd-cache:: list 'oupc4hetvha5gb7uergu2toc2g'
2018/03/28 08:17:17 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: empty listing
2018/03/28 08:17:17 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: read 1 from source
2018/03/28 08:17:17 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: source entries: [oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js]
2018/03/28 08:17:17 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached object: oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js
2018/03/28 08:17:17 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached dir: 'oupc4hetvha5gb7uergu2toc2g', cache ts: 2018-03-28 08:17:17.926294745 -0700 PDT m=+10.589023451
2018/03/28 08:17:17 DEBUG : test/: >ReadDirAll: item=1, err=<nil>
2018/03/28 08:18:07 DEBUG : Cache remote gd-cache:: starting cleanup
2018/03/28 08:18:08 DEBUG : Cache remote gd-cache:: starting cleanup
2018/03/28 08:18:08 DEBUG : Google drive root 'crypt': Checking for changes on remote
2018/03/28 08:18:08 DEBUG : Google drive root 'crypt': Checking for changes on remote
2018/03/28 08:18:08 INFO  : test/test2.txt: received cache expiry notification
2018/03/28 08:18:08 DEBUG : test: forgetting directory cache
2018/03/28 08:18:08 DEBUG : Cache remote gd-cache:: ignoring change notification for non cached entry oupc4hetvha5gb7uergu2toc2g/68sdr2ldjo6l6oa5e5r8094b1k
2018/03/28 08:18:08 DEBUG : Google drive root 'crypt': All changes were processed. Waiting for more.
2018/03/28 08:18:08 DEBUG : Google drive root 'crypt': All changes were processed. Waiting for more.
2018/03/28 08:18:12 DEBUG : test/: ReadDirAll:
2018/03/28 08:18:12 DEBUG : Cache remote gd-cache:: list 'oupc4hetvha5gb7uergu2toc2g'
2018/03/28 08:18:12 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: warm 1 from cache for: oupc4hetvha5gb7uergu2toc2g, expiring on: 2018-04-04 08:17:17.926294745 -0700 PDT
2018/03/28 08:18:12 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached entries: [oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js]
2018/03/28 08:18:12 DEBUG : test/: >ReadDirAll: item=1, err=<nil>
2018/03/28 08:19:07 DEBUG : Cache remote gd-cache:: starting cleanup
2018/03/28 08:19:08 DEBUG : Cache remote gd-cache:: starting cleanup
2018/03/28 08:19:08 DEBUG : Google drive root 'crypt': Checking for changes on remote
2018/03/28 08:19:08 DEBUG : Google drive root 'crypt': Checking for changes on remote
2018/03/28 08:19:09 DEBUG : Google drive root 'crypt': All changes were processed. Waiting for more.
2018/03/28 08:19:09 DEBUG : Google drive root 'crypt': All changes were processed. Waiting for more.

I noticed that one of the log entries says ignoring change notification for non cached entry even though the directory is cached, so perhaps there’s some confusion going on there.

I can provide additional details if it’s helpful.


#5

That is the same thing I’m seeing that I just posted a thread on. I do think that ignoring change notification message is the key.


#6

I thought this was working fine in earlier betas, so I’ve been trying the same test with older versions, and I’ve narrowed it down to a change that was implemented between v1.39 beta 211 and beta 215. I’ve reverted back to beta 211 and it’s working fine, here’s the log for the same test:

2018/03/29 09:29:55 DEBUG : test/: >Attr: attr=valid=0s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/03/29 09:29:55 DEBUG : /: Lookup: name="test"
2018/03/29 09:29:55 DEBUG : /: >Lookup: node=test/, err=<nil>
2018/03/29 09:29:55 DEBUG : test/: Attr:
2018/03/29 09:29:55 DEBUG : test/: >Attr: attr=valid=0s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/03/29 09:29:55 DEBUG : test/: ReadDirAll:
2018/03/29 09:29:55 DEBUG : Cache remote gd-cache:: list 'oupc4hetvha5gb7uergu2toc2g'
2018/03/29 09:29:55 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: empty listing
2018/03/29 09:29:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: read 1 from source
2018/03/29 09:29:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: source entries: [oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js]
2018/03/29 09:29:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached object: oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js
2018/03/29 09:29:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached dir: 'oupc4hetvha5gb7uergu2toc2g', cache ts: 2018-03-29 09:29:56.145864521 -0700 PDT m=+8.788960074
2018/03/29 09:29:56 DEBUG : test/: >ReadDirAll: item=1, err=<nil>
2018/03/29 09:30:24 DEBUG : test/: ReadDirAll:
2018/03/29 09:30:24 DEBUG : test/: >ReadDirAll: item=1, err=<nil>
2018/03/29 09:30:47 DEBUG : Cache remote gd-cache:: starting cleanup
2018/03/29 09:30:48 DEBUG : Cache remote gd-cache:: starting cleanup
2018/03/29 09:30:48 DEBUG : Google drive root 'crypt': Checking for changes on remote
2018/03/29 09:30:48 DEBUG : Google drive root 'crypt': Checking for changes on remote
2018/03/29 09:30:48 DEBUG : Google drive root 'crypt': All changes were processed. Waiting for more.
2018/03/29 09:30:48 DEBUG : Cache remote gd-cache:: notify: expiring cache for 'oupc4hetvha5gb7uergu2toc2g'
2018/03/29 09:30:48 DEBUG : test: forgetting directory cache
2018/03/29 09:30:48 DEBUG : oupc4hetvha5gb7uergu2toc2g: notify: expired oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js
2018/03/29 09:30:48 DEBUG : oupc4hetvha5gb7uergu2toc2g: cache: expired oupc4hetvha5gb7uergu2toc2g
2018/03/29 09:30:48 DEBUG : oupc4hetvha5gb7uergu2toc2g: cache: expired
2018/03/29 09:30:48 DEBUG : oupc4hetvha5gb7uergu2toc2g: notify: expired 'oupc4hetvha5gb7uergu2toc2g'
2018/03/29 09:30:48 DEBUG : Google drive root 'crypt': All changes were processed. Waiting for more.
2018/03/29 09:30:56 DEBUG : test/: ReadDirAll:
2018/03/29 09:30:56 DEBUG : Cache remote gd-cache:: list 'oupc4hetvha5gb7uergu2toc2g'
2018/03/29 09:30:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cold listing: 2018-03-22 09:30:48.848002163 -0700 PDT
2018/03/29 09:30:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: read 2 from source
2018/03/29 09:30:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: source entries: [oupc4hetvha5gb7uergu2toc2g/68sdr2ldjo6l6oa5e5r8094b1k oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js]
2018/03/29 09:30:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached object: oupc4hetvha5gb7uergu2toc2g/68sdr2ldjo6l6oa5e5r8094b1k
2018/03/29 09:30:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached object: oupc4hetvha5gb7uergu2toc2g/07j4c1j7gsptiuksfd096ne0js
2018/03/29 09:30:56 DEBUG : oupc4hetvha5gb7uergu2toc2g: list: cached dir: 'oupc4hetvha5gb7uergu2toc2g', cache ts: 2018-03-29 09:30:56.639506272 -0700 PDT m=+69.282601969
2018/03/29 09:30:56 DEBUG : test/: >ReadDirAll: item=2, err=<nil>

Notice there’s no ignoring change notification for non cached entry error like with v1.40.


#7

Great info. I’m going to try that now. Thanks


#8

This is the version I’m currently using:

https://beta.rclone.org/v1.39-211-g572ee5ec/

Let me know how it goes!


#9

Ran some preliminary tests with 1.39-211 and seems to be working good. I’ll let it run for a bit and see how plex finding new shows works.

I guess an issue needs to be opened on this because this seems separate from the directory creation issue.


#10

It is almost certainly this commit https://github.com/ncw/rclone/commit/70f07fd3ac2bc6e98dbf19b43da28d168e261aab which is the problem - it is in the range and it changed the polling.

Opening a new issue on github is a good idea I think.


#11

https://beta.rclone.org/v1.40-031-ge42cee5e/

This beta should fix the issue replicated here - the parent folder was not expired when an object was received as changed even though it was done in vfs.


#12

The new beta seems to be working great! Thanks for following up on this, remus!! Much appreciated :slight_smile:


#13

I’m running v1.40-061-gd5b2ec32 with a crypt/cache wrapped drive remote mounted, and am still seeing issues with newly created directories not showing in the mount until I did a full expire with a HUP (didn’t try targeting the parent folder through the rc expire command, but assume that would work as well).

For a cached remote, can dir-cache-time be safely lowered, as the mount shouldn’t incur much of a penalty if it’s just hitting the bolt cache? Either way, it seems like a notification from drive should still bubble all the way up through the crypt and cache to the mount, no?

This is a read-only mount merged with a local dir with unionfs as well so I have vfs turned off, and I’m wondering if that may be related. Thoughts?

I’ve switched to debug logging now as well so I’ll have some more details if/when this happens again.


#14

How are the new files getting there? I’d say to use the cache-tmp-upload and ditch the unionfs as it just adds an unneeded layer of complexity.

If you capture the polling change via the debug log, that should point out if there’s an issue.


#15

I’m doing a nightly cronjob that does a combination of rclone copy and rclone move with different exclusion lists and file age limits. I’d still prefer to keep this to control when specifically uploads happen, and to be able to keep some files local all the time. Worst-case scenario, I can have the script trigger rc cache/expire for files/directories that changed.


#16

are you getting a .unionfs in your local dir that’s causing something to be hidden?

If you run the job by hand, you should see the expiration in the debug too if it’s not working properly.


#17

Nope, nothing related to files masked anywhere with a .unionfs folder.

I’ve just manually done a rclone copy of a folder that didn’t exist on the remote when I mounted it, and the next check for changes on drive didn’t seem to find anything that needed doing:

rclone[26169]: 2018/04/10 21:28:01 DEBUG : Google drive root 'Plex': Checking for changes on remote
rclone[26169]: 2018/04/10 21:28:01 DEBUG : Google drive root 'Plex': All changes were processed. Waiting for more.
rclone[26169]: 2018/04/10 21:28:02 DEBUG : Google drive root 'Plex': Checking for changes on remote
rclone[26169]: 2018/04/10 21:28:02 DEBUG : Google drive root 'Plex': All changes were processed. Waiting for more.

rclone rc vfs/forget did nothing as expected since I don’t have VFS enabled.

rclone rc cache/expire remote="existingDirectory/newDirectory" confirmed that this wasn’t in the cache:

2018/04/10 21:33:37 Failed to rc: operation "cache/expire" failed: remote control command failed: 4pd8m573jua2rm9g0iscn82tac/0cr7kkd898l3o6lnmm7lmlvvk8 doesn't exist in cache

The only thing that worked was rclone rc cache/expire remote="existingDirectory/"

My current config for reference:

[gdrive]
type = drive
client_id = REDACTED
client_secret = REDACTED
token = {"access_token":"REDACTED","token_type":"Bearer","refresh_token":"REDACTED","expiry":"2018-04-10T22:07:58.232237126-04:00"}

[gdrive-cache]
type = cache
remote = gdrive:Plex
plex_url = http://127.0.0.1:32400
plex_token = REDACTED
chunk_total_size = 50G

[gdrive-cache-crypt]
type = crypt
remote = gdrive-cache:
filename_encryption = standard
directory_name_encryption = true
password = REDACTED
password2 = REDACTED

# Used for copy/move operations
[crypt]
type = crypt
remote = gdrive:Plex
filename_encryption = standard
password = REDACTED
password2 = REDACTED

And my current mount command /usr/bin/rclone mount gdrive-cache-crypt: /data/.gdrive --read-only --allow-other --dir-cache-time=6h --cache-chunk-size=5M --cache-info-age=168h --cache-workers=8 --buffer-size 0M --attr-timeout=1s --umask 002 --rc --log-level DEBUG --gid 1001 --uid 1000 (dropped dir-cache-time to 6hrs to avoid things going going missing for a week if I didn’t notice, was 168h before)


#18

When you copy the file in, you don’t see any cache expiry notifications?

I just tested and I get:

Apr 10 22:16:02 gemini rclone[4198]: hosts: received cache expiry notification

I’m running:

[felix@gemini gmedia]$ rclone -V
rclone v1.40-040-g6e11a25dβ

I just did a rclone copy /etc/hosts into my GD follow your same config with a crypt secondary config.


#19

Nope, no cache expiry notifications for a new directory. I had notifications from last night’s copy operation when files that were already on the remote were overwritten/updated, but nothing for the copy operation of this new directory and file.

The only thing I’m doing that seems slightly non-standard is having the mount read-only?

Any thoughts on where to look next @ncw?


Plex with rclone mount - possible to auto update/partial scan?
#20

New directories not showing up is a known issue as mentioned by seuffert, you can follow the issue on github here: https://github.com/ncw/rclone/issues/2155