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…
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.
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:
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.
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
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
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
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!
