Rclone move not updating cache mount

I created a cached mount [gdrive -> cache -> crypt]. When I upload files with ‘rclone move crypt’ it doesn’t seem to update the mount. I have a week long cache (–dir-cache-time 168h) so wonder if this is expected behavior or not? I assumed that as I was working on the same remote, that this would trigger a cache expiration on that directory. Is it only changes directly on the mount that causes the cache expiration or should a rclone move cause this as well?

If only changes within the mount cause this am I best just to have a really short dir cache time? If it’s set to 1h or lower this almost negates the whole purpose of using a cache in the first place…

Anyone?

I notice when doing rclone moves that there are log entries suggesting it’s expiring items in the cache.

2018/05/30 16:12:37 INFO : dkul6vmd479pb76qfp3bivve7c/t7ar9kgeevpio3ijn3l9n0608s/k38p88h8j1t7tpmico9cqeanog: put: cache expired

When checking the mount after this it’s still an old version without the changes.

Are you moving the files into the mounted directory or directly into the cloud?

If moving directly to the cloud it should update the directory using the --poll-interval mechanism - so it will happen every 60s by default. This should work through crypt and cache too…

If moving into the mount then cache should know that you updated the directory.

You can alternatively use rclone rc cache/expire and or rclone rc vfs/forget to give things a poke manually.

Thanks @ncw.

I’m not making any changes to the mount directly, it’s effectively read only. All changes are directly to the cloud using ‘rclone move’. I have tried a polling interval of 60m (as well as the default) and I can’t get it to show the new files. Any thoughts on how I go about troubleshooting this?

All of the cache remote’s settings are default, mount settings are currently:

–allow-other --dir-cache-time 168h --poll-interval 60m --buffer-size 64M

Killing the mount daemon and restarting it (even without the purge db flag) results in the new folders being seen.

For what it’s worth, I’m running rclone v1.41 and debian 9.4.

With 60m you’ll only see new files every 60 minutes - is that what you intended?

If the polling is working you should see the directories being expired in the logs - do you see that?

Happy with an hour, but it just isn’t working. I see cache expiration messages in the rclone log files (generated by ‘rclone move’). To be honest, I don’t have logging enabled for the mount itself so I will enable this to see if anything is obvious.

2018/05/30 21:14:27 INFO : dkul6vmd479pb76qfp3bivve7c/1o9dvait8eaih1vb3u655i8g44/2e2o7lfkp0dehul2u6l62r79ug: put: cache expired
2018/05/30 21:14:27 INFO : Linux/Debian/arm64/iso-cd/debian-9.4.0-arm64-netinst.iso: Copied (new)
2018/05/30 21:14:27 INFO : Linux/Debian/arm64/iso-cd/debian-9.4.0-arm64-netinst.iso: Deleted

These files were uploaded last night (once again using rclone move) and I still don’t see them on the mount.

No log entries regarding cache/poller stuff:

root@frog:/home/reticent/scripts# tail -f /var/log/rclone-mount.log
2018/05/31 09:41:10 INFO : GsuiteC: File Age: 6h0m0s
2018/05/31 09:41:10 INFO : GsuiteC: Cache DB path: /home/cache/rclone/GsuiteC.db
2018/05/31 09:41:10 INFO : GsuiteC: Cache chunk path: /home/cache/rclone/GsuiteC
2018/05/31 09:41:10 INFO : GsuiteC: Chunk Memory: true
2018/05/31 09:41:10 INFO : GsuiteC: Chunk Size: 5M
2018/05/31 09:41:10 INFO : GsuiteC: Chunk Total Size: 10G
2018/05/31 09:41:10 INFO : GsuiteC: Chunk Clean Interval: 1m0s
2018/05/31 09:41:10 INFO : GsuiteC: Workers: 4
2018/05/31 09:41:10 INFO : GsuiteC: File Age: 6h0m0s
2018/05/31 09:41:10 INFO : Encrypted drive ‘Decrypt:’: Modify window is 1ms

It’s now ~11:21 so there hasn’t been anything since 9:41 when I started logging. Logging level is set to INFO.

What you should see are log entries which look like this

2018/05/31 13:37:44 DEBUG : Google drive root '': Checking for changes on remote
2018/05/31 13:37:44 DEBUG : test: forgetting directory cache
2018/05/31 13:37:44 DEBUG : Google drive root '': All changes were processed. Waiting for more.

They are DEBUG level so you won’t see them with INFO level.

What I did to get that log was to create a file in test and you can see a bit later it was picked up by the mount and the test directory was invalidated.

That isn’t using cache though.

If you use it with cache you should see something like

$ rclone mount -vv --dir-cache-time 168h --poll-interval 10s  cachedrive: /mnt/tmp/
2018/05/31 13:43:09 DEBUG : Google drive root 'test': Checking for changes on remote
2018/05/31 13:43:09 INFO  : t3/hello3.txt: received cache expiry notification
2018/05/31 13:43:09 DEBUG : t3/folder1: forgetting directory cache
2018/05/31 13:43:09 DEBUG : t3/folder2: forgetting directory cache
2018/05/31 13:43:09 DEBUG : t3: forgetting directory cache
2018/05/31 13:43:09 DEBUG : Cache remote cachedrive:: ignoring change notification for non cached entry t3/hello3.txt
2018/05/31 13:43:09 DEBUG : t3: cache: expired t3
2018/05/31 13:43:09 DEBUG : t3: cache: expired 
2018/05/31 13:43:09 DEBUG : t3/hello3.txt: notify: expired 't3'
2018/05/31 13:43:09 DEBUG : Google drive root 'test': All changes were processed. Waiting for more.

or with a crypt wrapped cached drive

$ rclone mount -vv --dir-cache-time 168h --poll-interval 10s  cryptcachedrive: /mnt/tmp/
2018/05/31 13:50:41 DEBUG : Cache remote cachedrive:: starting cleanup
2018/05/31 13:50:42 DEBUG : Google drive root 'test/secret': Checking for changes on remote
2018/05/31 13:50:42 DEBUG : Cache remote cachedrive:: starting cleanup
2018/05/31 13:50:42 INFO  : mmo10erns110o5n8l0s9394ijk: received cache expiry notification
2018/05/31 13:50:42 DEBUG : Cache remote cachedrive:: ignoring change notification for non cached entry mmo10erns110o5n8l0s9394ijk
2018/05/31 13:50:42 DEBUG : : cache: expired 
2018/05/31 13:50:42 DEBUG : mmo10erns110o5n8l0s9394ijk: notify: expired ''
2018/05/31 13:50:42 DEBUG : Google drive root 'test/secret': All changes were processed. Waiting for more.
2018/05/31 13:50:42 DEBUG : Google drive root 'test/secret': Checking for changes on remote
2018/05/31 13:50:43 INFO  : hello2.txt: received cache expiry notification
2018/05/31 13:50:43 DEBUG : : forgetting directory cache
2018/05/31 13:50:43 DEBUG : Cache remote cachedrive:: ignoring change notification for non cached entry mmo10erns110o5n8l0s9394ijk
2018/05/31 13:50:43 DEBUG : : cache: expired 
2018/05/31 13:50:43 DEBUG : mmo10erns110o5n8l0s9394ijk: notify: expired ''
2018/05/31 13:50:43 DEBUG : Google drive root 'test/secret': All changes were processed. Waiting for more.

And I think that test is pretty much exactly what you are doing and it seemed to work :frowning:

What can you see with the -vv log? Anything similar?

I’ve enabled debug logging and see more of the cache type stuff. I created a new directory named “Test” and a file within it test.txt and pushed these to the cache remote using ‘rclone move’ as usual.

Watching the mount logs all I see (amongst other non-pertinent stuff) is:

2018/05/31 14:11:35 DEBUG : Cache remote GsuiteC:: starting cleanup
2018/05/31 14:11:36 DEBUG : Cache remote GsuiteC:: starting cleanup
2018/05/31 14:11:38 DEBUG : Google drive root ‘Stuff’: Checking for changes on remote
2018/05/31 14:11:38 DEBUG : Google drive root ‘Stuff’: All changes were processed. Waiting for more.
2018/05/31 14:11:38 DEBUG : Google drive root ‘Stuff’: Checking for changes on remote
2018/05/31 14:11:39 DEBUG : Google drive root ‘Stuff’: All changes were processed. Waiting for more.

Based on your output above, it’s almost like the polling mechanism is not detecting new files and therefore not making any cache changes right?

Not sure why it’s doing that check twice at the same time. It’s also doing it every minute even though I have --poll-interval 5m in my mount command at the moment :confused:

The logs from the move were as follows:

2018/05/31 14:07:07 INFO : Encrypted drive ‘Decrypt:’: Modify window is 1ms
2018/05/31 14:07:07 ERROR : snha8qbcsuvdhjiongmurfd1t0: error refreshing object in : in cache fs Google drive root ‘Stuff’: object not found
2018/05/31 14:07:07 INFO : Encrypted drive ‘Decrypt:’: Waiting for checks to finish
2018/05/31 14:07:07 INFO : Encrypted drive ‘Decrypt:’: Waiting for transfers to finish
2018/05/31 14:07:10 INFO : dkul6vmd479pb76qfp3bivve7c: put: cache expired
2018/05/31 14:07:10 INFO : TV/test.txt: Copied (new)
2018/05/31 14:07:10 INFO : TV/test.txt: Deleted

Yes that does look like what is going on.

The two polls are the cache. Not quite sure why it does two polls - something to do with encrypted and unencrypted I think.

The cache seems to override the poll time too hence why it ignores your 5m.

This looks like it is related to Google Drive change polling and cache invalidation

It looks like there was a potential fix there too so have a go with the latest beta and see if that works.

Ah, that looks like it’s done the trick. Just re-pushed that Test directory and it showed up a few minutes later. I’ve used rclone long enough that I should have known to try a beta, just surprised there weren’t more people fussing about it not working in 1.40!

As always, thanks a lot for your help with this (and the continued development of the tool).

Great - glad it is working! I should have got you to try the beta sooner! The cache/vfs stuff always seems to be under heavy development - I guess it is complicated and has lots of bugs!