vfs: losing data when doing writeback

[Zvezdin]

What is the problem you are having with rclone?

When running the below command and downloading an arbitrary file from chromium (in my case - a pdf from google drive) directly into a mounted rclone remote, the file appears successfully downloaded in the directory, and is accessible by file managers and reader programs. However after remounting the rclone mount, the file disappears, as rclone actually silently failed uploading it. This is very dangerous for users who do not constantly monitor rclone mount's terminal output, where we can see the following transmission errors: https://termbin.com/g2o30

Even after enabling the options --retries 99 --retries-sleep 10s, which should force rclone to retry the same process after a delay, the upload still fails once it is initiated and is not retried. This can lead to involuntary data loss as was for my case.

I haven't tried, but I suspect that using cache as a wrapper backend could work as a temporary workaround. I presume that rclone gets confused due to chrome's way of downloading files and then renaming them to the target name.

What is your rclone version (output from rclone version)

rclone v1.51.0

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

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

Onedrive for Business, without extra chained remotes sych as crypt, chunker, or cache.

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

rclone -vv --retries 99 --retries-sleep 10s --vfs-cache-mode full mount remote: ~/somedir

A log from the command with the -vv flag (eg output from rclone -vv copy /tmp remote:tmp)

I've emailed it to @ncw as it may contain sensitive information.

[Animosity022]

I am trying to make sure I'm following.

You copy a file to the mount.
It fails uploading because of something.
You remount and the file that was there is gone?

The error you had posted looks like a file was changed during upload.

[Zvezdin]

You use chrome to download a file with a target destination somewhere in the mount.
It fails. You remount and it's gone.

[Animosity022]

How does it fail though? When you a copy a file to the mount and the upload fails, it normally returns an IO write error on the mount.

I'd probably update the title as that's not silent file corruption either. It's a missing file on a failed upload if I'm understanding you.

[Zvezdin]

The only way I understand that it fails is by seeing the log output of the mount process (https://termbin.com/g2o30). Chrome does not give out any errors and the file is perfectly readable and accessible in the mount directory, until it is remounted and disappears as it was never uploaded in the first place. What I tried to explain may not be "silent corruption". However it is still quite dangerous as the user does something very normal (download a file from the internet), the mount behaves as if the operation as successful (lists the file in the directory, allows the user to successfully read it), and eventually it turns out that the operation was unsuccessful. I don't know if/how Chrome handles IO errors when downloading files. However I suspect that there were no IO write errors given as the file wouldn't be placed in the mount in the first place.

[Animosity022]

Without seeing a debug log, it's really a guessing game.

When you fail an upload, it gives an IO error on a mount as that's an easy test on a mount in Linux terminal.

Your issue is a duplicate of this one:

#2382

I'd surmise Chrome is hiding the IO error and losing files is always a bad thing.

I'd be more curious on fixing when you have some many upload failures? That in itself seems strange.

[Zvezdin]

The observed behaviour really seems identical to #2382. However in the latter's description it is stated that this happens when "the VFS cache will begin deleting any non uploaded files when they reach their retries amount." What I observe here is that the operation is cancelled even before reaching the stated retries amount and the delay between retries. It may still be the same issue triggered by a different stimulus however.

I double checked the log I sent to @ncw and I think that it's safe to post here too, so here it is: https://termbin.com/93kb

I think think that rclone gets confused when chrome first creates an empty file, this empty file is uploaded to the backend, rclone comes back to check if the sizes are the same and by that time chrome has already filled up that local file with content, hence the uploaded file is rejected.
What is weird here is why rclone does not retry the same upload operation as given by the flags --retries 99 --retries-sleep 10s

[ncw]

Here is an edited annotated log of what happened

# Download finishes, Firefox closes the file, rclone finishes the upload
2020/05/31 14:01:52 DEBUG : Unconfirmed 499231.crdownload: transferred to remote
# Firefox opens the destination file and clears it to empty
2020/05/31 14:01:52 DEBUG : somefile.pdf: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2020/05/31 14:01:52 DEBUG : somefile.pdf(0xc000a08380): Opening cached copy with flags=O_WRONLY|O_CREATE|O_TRUNC
2020/05/31 14:01:52 DEBUG : somefile.pdf(0xc000a08380): close:
# Firefox renames the .crdownload to somefile.pdf
2020/05/31 14:01:52 DEBUG : /: Rename: oldName="Unconfirmed 499231.crdownload", newName="somefile.pdf", newDir=/
# rclone decides that the (now empty) somefile.pdf needs to be transferred
2020/05/31 14:01:52 DEBUG : somefile.pdf: Need to transfer - File not found at Destination
# rclone renames the file in the cache
2020/05/31 14:01:52 INFO  : Unconfirmed 499231.crdownload: Renamed in cache
# rclone starts the somefile.pdf upload
2020/05/31 14:01:52 DEBUG : somefile.pdf: Starting singlepart upload
# rclone attempts to rename in onedrive but there is a file there already - the 0 sized somefile.pdf
2020/05/31 14:01:53 ERROR : Unconfirmed 499231.crdownload: Couldn't move: nameAlreadyExists: Name already exists
2020/05/31 14:01:53 ERROR : somefile.pdf: File.Rename error: nameAlreadyExists: Name already exists
2020/05/31 14:01:53 ERROR : Unconfirmed 499231.crdownload: Dir.Rename error: nameAlreadyExists: Name already exists
2020/05/31 14:01:53 DEBUG : /: >Rename: err=nameAlreadyExists: Name already exists

The error in question is this one

2020/05/31 14:01:53 ERROR : somefile.pdf: File.Rename error: nameAlreadyExists: Name already exists

That is onedrive complaining that you are about to rename a file on top of an existing file.

Renaming a file on top of another file isn't part of the integration tests which means that rclone backends are differ in their implementations. The local backend will overwrite an existing file whereas the onedrive backend throws an error.

If the onedrive backend had allowed the rename in this case then it would have worked.

This would also have been fixed by the delayed writeback I have implemented in the vfs branch.

[gservat]

I just ran into this issue but using Google Drive. @ncw will the fix you put together also fix it for other backends like Google Drive?

[ncw]

I hope this should be fixed in the latest beta if someone wants to try it.

[gservat]

@ncw not sure if you want me to keep updating the forum post and this issue, but anyway I did try the latest beta and it didn't seem to improve things. Still unable to save files from the browser straight onto the Google Drive mounted path. It feels like a regression actually as --vfs-cache-mode writes doesn't work around the issue anymore.

[ncw]

Ok let's move the discussion here:

I tried with v1.52.2-230-gd2efb4b2-beta (without --vfs-cache-mode writes ) and I'm still getting a Failed - Download error in Chrome.

I can replicate that.

Interestingly, even with --vfs-cache-mode writes , it now fails.

When I try it with --vfs-cache-mode writes it works perfectly for me - can you post a log of that failing for you?

I had a go at fixing the problem without --vfs-cache-mode - can you have a go with this?

v1.52.2-233-g10dea1ca-fix-vfs-write-beta on branch fix-vfs-write (uploaded in 15-30 mins)

[ncw]

I've just realised that the original poster on the forum was using Google drive - this should be fixed with and without --vfs-cache-mode writes

With testing with onedrive, I see it working too, but without --vfs-cache-mode writes I see these errors which chrome somehow fixes up.

2020/07/22 11:05:47 ERROR : testdl/Unconfirmed 915379.crdownload: Couldn't move: nameAlreadyExists: An item with the same name already exists under the parent
2020/07/22 11:05:47 ERROR : testdl/rclone-v1.49.5-windows-amd64.zip: File.Rename error: nameAlreadyExists: An item with the same name already exists under the parent
2020/07/22 11:05:47 ERROR : testdl/Unconfirmed 915379.crdownload: Dir.Rename error: nameAlreadyExists: An item with the same name already exists under the parent

[ncw]

I a go at fixing up the rename issue - can you try this? It contains the previous fix too

v1.52.2-234-g8f36afac-fix-4293-vfs-write-beta on branch fix-4293-vfs-write (uploaded in 15-30 mins)

[gservat]

That's great @ncw! Thank you! 🙇

Seems to work fine without any errors (not using --vfs-cache-mode writes). Only thing I've noticed is that when I download a file into the google drive mounted dir, it works fine, so I delete the file but the file doesn't get removed in Google Drive. Not sure if it's a totally different bug or some sort of regression.

[ncw]

Thanks for testing :-)

Seems to work fine without any errors (not using --vfs-cache-mode writes).

Great! Can you try with --vfs-cache-mode writes too?

Only thing I've noticed is that when I download a file into the google drive mounted dir, it works fine, so I delete the file but the file doesn't get removed in Google Drive. Not sure if it's a totally different bug or some sort of regression.

I noticed the code previously was making duplicates so it is possible you had a duplicate. Can you try this again with a fresh file?

[gservat]

Thanks for testing :-)

Seems to work fine without any errors (not using --vfs-cache-mode writes).

Great! Can you try with --vfs-cache-mode writes too?

Yep! that works too. Should I be using with or without?

I noticed the code previously was making duplicates so it is possible you had a duplicate. Can you try this again with a fresh file?

Just tried and after removing the file locally, it still doesn't seem to disappear when I go through drive.google.com.

[ncw]

Yep! that works too. Should I be using with or without?

Thanks for testing. Without will save using up local disk space so if it works like that then I'd use it without.

Just tried and after removing the file locally, it still doesn't seem to disappear when I go through drive.google.com.

OK let's work on this now! Can you make a sequence of steps for me showing all the commands you use that I can reproduce this?