Polling/mount cache issue after server-side move

renzz · July 28, 2020, 10:38am

What is the problem you are having with rclone?

I have an issue where a server side move on my mounted Gdrive is not being fully picked up by polling on other systems where I have GDrive mounted.

Scenario: I have an unlimited Gdrive which I access from three different boxes. The first is a mount on a shared seedbox, running things like Sonarr, Radarr etc, and this is where the majority of updates are done to the mount. The second is an Ubuntu VPS where I run Plex so access is largely read only (although the mount is read/write, same as the seedbox). Thirdly, I have a mount on my Windows 10 PC for ad-hoc access.

On the seedbox mount, if I do a server side move of a file (normally using Thunar file manager on an xfce desktop), all works as it should - the file appears in the destination folder and disappears from the original folder. However, on the Ubuntu VPS and the Windows client, and after the polling interval passes, the file correctly appears in the destination folder, but does NOT disappear from the orginal folder, and so seems to exist in both. This seems to continue until --dir-cache-time expires, which in my case is 24hrs. Oddly, the entry in the original folder continues to be accessable.

I have produced a debug log on the seedbox and on Windows showing the issue. On the seedbox you can see the file being moved from sub1/subsub1 to sub1/subsub2 successfully. On the Windows client you can see the change being picked up by polling, and it invalidating the cache for the local sub1\subsub2 (ie the destination folder):

2020/07/28 11:27:02 DEBUG : Google drive root 'Encrypted': Checking for changes on remote
2020/07/28 11:27:02 DEBUG : : changeNotify: relativePath="sub1/subsub2/Newfile1.txt", type=3
2020/07/28 11:27:02 DEBUG : sub1/subsub2: invalidating directory cache
2020/07/28 11:27:02 DEBUG : : >changeNotify:

However, it does not seem to invalidate the cache for the original folder, sub1/subsub1, and I'm guessing this is the problem.

I should say this is only an issue with the mount - if I do "rclone ls" on the windows sub1/subsub1 it does NOT show the file is still there, so it's obviously a problem with the mount cache not refreshing.

I should also say I also see the issue on the Ubuntu VPS server, so it's not just a Windows problem.

Hope this can be fixed

What is your rclone version (output from `rclone version`)

Seedbox: 1.52.0
Windows: 1.52.2

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

Seedbox: Debian 9 64bit
Windows 10 64bit

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

GDrive

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

Windows: c:\video\rclone\rclone.exe mount Gsuite-Crypt: x: --dir-cache-time 24h --drive-chunk-size 512M --vfs-cache-mode writes --log-file c:\video\rclone\rclone-test-mount.log --user-agent Laurie --buffer-size 256M --config C:\Users\renzz\.config\rclone\rclone-test.conf -vv --poll-interval 15s

Seedbox: 
```/home18/renzz27/rclonenew/rclone mount Gsuite-Crypt: /home18/renzz27/files/Test-mount/ --dir-cache-time 24h --allow-other --drive-chunk-size 512M --vfs-cache-mode writes --log-file /home18/renzz27/files/rclone-test-mount.log --user-agent Laurie --buffer-size 256M --config /home18/renzz27/files/rclone-test.conf -vv --poll-interval 15s

The rclone config contents with secrets removed.

[Gsuite]
type = drive
client_id = xxxx
client_secret = xxxx
scope = drive
root_folder_id = xxxx
service_account_file = 
token = {"access_token":"xxxx

[Gsuite-Crypt]
type = crypt
remote = Gsuite:Encrypted
filename_encryption = standard
password = xxxx
password2 = xxxx

A log from the command with the `-vv` flag

https://we.tl/t-WoMjdPeBMr

asdffdsa · July 28, 2020, 12:54pm

hi,
i think this is a bug, that was discussed somewhere in the forum.
that there is a beta fix for it.
i cannot remember, still drinking my first coffee of the day.

renzz · July 28, 2020, 1:08pm

Your'e not thinking of a similar bug I reported a few months ago with the cache on a Windows mount not updating using polling, are you? - Windows mount polling not recognising all changes made by another box

If so, this is something different, specifically to do with server-side moves.

asdffdsa · July 28, 2020, 1:12pm

yeah, that is the post. i just searched/found it and was going to post it.

i am still on that first coffee.

in the morning, jojo is in monkey mode.
jojo needs coffee to switch to human mode.

renzz · July 28, 2020, 1:14pm

I think this is one that @ncw will need to comment on, as it does look like a bug where it's not handling the delete part of the move.

ncw · July 28, 2020, 6:54pm

@renzz can you try this with the latest beta and see if it still has the problem?

renzz · July 29, 2020, 8:40am

@ncw, unfortunately the latest beta (rclone-v1.52.2-273-g4441e012-beta-windows-amd64) doesn't fix it - same problem. Logs attached. seedbox-rclone-test-mount.log (31.6 KB) windows-rclone-test-mount.log (187.2 KB)

As an aside, I notice with that beta on Windows, you don't get the name of the remote as part of the mounted drive's name, ie this is what you normally see for the mapped drive:

With that beta all you see is "Local Disk (X:)"

ncw · July 29, 2020, 1:26pm

Thanks for that - will investigate.

Hmm, I wonder what has broken that... Oh I see, try this

v1.52.2-274-g3daa63ca-fix-volumename-beta on branch fix-volumename (uploaded in 15-30 mins)

ncw · July 29, 2020, 2:20pm

Just been having a look through the logs...

On the Seedbox I see you moving a file between directories

2020/07/29 10:34:53 DEBUG : sub1/subsub2/: Rename: oldName="Newfile1.txt", newName="Newfile1.txt", newDir=sub1/subsub1/

2020/07/29 10:35:26 DEBUG : sub1/subsub1/: Rename: oldName="Newfile1.txt", newName="Newfile1.txt", newDir=sub1/subsub2/

On the windows box I see

2020/07/29 09:35:31 DEBUG : : changeNotify: relativePath="sub1/subsub2/Newfile1.txt", type=3
2020/07/29 09:35:31 DEBUG : sub1/subsub2: invalidating directory cache
2020/07/29 09:35:31 DEBUG : : >changeNotify:

And as you wrote originally

This is the problem and I'm not sure how to solve it...

The problem is that we don't get the directory ID of the original directory in the changes request, we only get the ID of the file and ID of the new directory.

If we had the ID of the original directory then we could invalidate it easily.

It is possible in theory for rclone to search through all the cached directories looking for the file ID and to remove it. However that is potentially a lot of work as there can be 1,000s of cached directories and rclone would have to search through all the files in all the directories.

Rclone cloud also keep a map of ID to directory ID but might potentially take loads of memory.

The revisions don't keep the directory IDs in them.

Any thoughts? Here is the changes API if you want to double check (which would be appreciated!)

renzz · July 29, 2020, 2:42pm

Yes, this fixes the volumename issue - thanks.

renzz · July 29, 2020, 2:48pm

A bit of lateral thinking....

What about, in my example, after the file has been moved on the seedbox, Rclone creates an empty file in the original folder, and then immediately deletes it. Would that trigger a change on Gdrive, which other systems (ie my Windows PC) would pick up by polling, and invalidate the cache for the old folder?

A bit of a fudge, but I can't think of any other easy way to do it. What do you think?

ncw · July 29, 2020, 3:18pm

Thanks for testing I've merged the fix for that into master

v1.52.2-274-g3daa63ca-beta on branch master (uploaded in 15-30 mins)

That would work I think. Maybe something simpler would work too like setting the modification time of the folder?

Could you add something like this to your workflow?

renzz · July 29, 2020, 3:46pm

If changing the modification time works, then that's the way to go. I just tried a quick test using the 'touch -t' command on the seedbox to change the modification time of sub1/subsub1 but the change was not picked up on the Windows PC, but maybe that's not a good test.

Not sure what you mean by this but if this fixes the issue, then that's fine by me. If you want to knock up a test build, I'm happy to give it a go.

darthShadow · July 29, 2020, 9:30pm

Could this also be the root cause for this issue:

It seems to be similar behaviour from what I have understood.

Does that go as part of the changes API? At least currently, any modtime changes don't seem to be reflected.

As an aside, the Activity API (https://developers.google.com/drive/activity/v2/) seems to be much more comprehensive than the Changes API. Perhaps we could consider switching over to it eventually?

ncw · July 30, 2020, 3:37pm

I think that issue is caused by the virtual directory entry problem, however the activity API would make the virtual directory entries much easier to get rid of.

The Activity API does have the level of detail required: https://developers.google.com/drive/activity/v2/reference/rest/v2/activity/move#Move

It is also quite complicated!

I'd quite like to redesign the change notify protocol. It is too complicated internally and not flexible enough. We also haven't implemented it for very many backends.

darthShadow · July 30, 2020, 4:23pm

I was going through the changeNotifyRunner code for drive and I was unable to see where it detects the file deletions at all, doesn't matter whether it was moved or outright deleted.

Could you perhaps point that out?

ncw · July 31, 2020, 12:00pm

This is the code

github.com

rclone/rclone/blob/c2f3949dedc93f08e0c7bd899ef863e6d699c1bb/backend/drive/drive.go#L2673-L2705


		for _, change := range changeList.Changes {
			// find the previous path
			if path, ok := f.dirCache.GetInv(change.FileId); ok {
				if change.File != nil && change.File.MimeType != driveFolderType {
					pathsToClear = append(pathsToClear, entryType{path: path, entryType: fs.EntryObject})
				} else {
					pathsToClear = append(pathsToClear, entryType{path: path, entryType: fs.EntryDirectory})
				}
			}

			// find the new path
			if change.File != nil {
				change.File.Name = f.opt.Enc.ToStandardName(change.File.Name)
				changeType := fs.EntryDirectory
				if change.File.MimeType != driveFolderType {
					changeType = fs.EntryObject
				}

				// translate the parent dir of this object
				if len(change.File.Parents) > 0 {

This file has been truncated. show original

It looks up the parent ID of the file or directory in the dircache and invalidates the parent directory.

The directory itself is invalidated too if it is a directory.

Note that looking things up in the dircache will fail if we haven't listed that directory yet...

darthShadow · July 31, 2020, 12:14pm

Based on the changes resource documentation, I assumed that the file object is itself not present when the file has been deleted.

Extracts from the docs:

fileId | string | The ID of the file which has changed.
removed | boolean | Whether the file or shared drive has been removed from this list of changes, for example by deletion or loss of access.
file |  nested object | The updated state of the file. Present if the type is file and the file has not been removed from this list of changes.

From the above, my understanding is that removed files (either via deletion or via loss of access) won't have the file object and hence, no parents to invalidate.

Am I understanding this wrong?

Note: I haven't tried it out locally yet and am just basing my assumptions on the docs. I will try it out later today and see if the behaviour is different.

ncw · July 31, 2020, 2:08pm

You may well be correct. I didn't write that code it was written by @B4dM4n some time ago...

The activity API looks a lot more comprehensive so we should probably swap to using that.

darthShadow · August 2, 2020, 7:10pm

Looks like there is already a similar issue on GH with the same problem: