Renaming files after copy often fails until rclone is restarted (VFS, MacOS)

Sami_Pussinen · March 7, 2021, 8:05pm

Hello there,

I'm suspecting a bug in the VFS layer since I have spent a considerable amount of time ruling other things out in my situation. I'm interested if anyone using MacOS has had similar problems as outlined here:

What is the problem you are having with rclone?

I am using rclone mount to mount a Google Cloud Storage bucket. The mounted volume is used for both reading and writing by actual human users. Files are not particularly large and transfers seem quite snappy, especially when VFS is used to "mask" the upload and download. However, when using VFS mode full or writes or even minimal, we have noticed an issue that is driving us quite bonkers: Copying files and then trying to rename some of them doesn't often work at all. We are using Mac Finder to operate the mount and see this happen very often.

Here's an example with pictures:

Step 1: We have mounted the bucket and copy over some files. For illustration purposes here we have 7 PNG images from a.png to g.png.

Notice that three files (e.png, f.png, g.png) don't have the preview? That seems to somehow correlate with the issue, since if we try to rename those files, we get an error like this:

Not very helpful error message, but that's Apple for you. However, we are able to open the file just fine and even see the preview, if we enable the preview panel in Finder. But this thumbnail never loads and you cannot rename the file. You are able to rename the files a to d, since they have the thumbnails like this (renamed file a.png to a2.png)

This problem only occurs when using VFS. Without it everything seems to work, but then the compatibility is pretty bad, especially with MS Office programs.

What I have checked:

The cache directory has both the files (in vfs dir) and meta files (in vfsMeta dir).
The log seems to indicate successful upload, and the files are accessible fine from another machine, so they are uploaded.
Both 4.0.4 and 4.05 versions of MacFuse display similar behaviour. (Haven't tested older ones)
Removing the "local" option has no effect.
Having Apple FileVault enabled or disabled has no effect.
Mac language settings has no effect (tested Finnish and English)
Changing --cache-dir has no effect.
Changing --local-no-check-updated has no effect.
Changing vfs buffer size or read ahead has no effect.
Degrading network performance has no effect (I have 1000Mbit/s download and 100Mbit/s upload)
Disabling Apple Time Machine has no effect (getting desperate here )
Disabling firewall and F-Secure realtime protection has no effect.
Removing all other sync programs like Dropbox has no effect.
Changing from the default --transfers 4 to 1 or 16 has no effect.
File type of transferred files has no effect.
File count has no effect. In the demo above I used multiple files, but it can also be just one file copied over and then you are not able to rename it.
This has been tested with 10+ Mac devices with the same results.
Killing and restarting rclone allows you to rename the file, but this is not a feasible solution. When restarted, also the thumbnails load for all files, so it would really seem like there's some conection.

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

v1.54.0 stable (from releases)

Which OS you are using and how many bits

MacOS Big Sur 64 bit

Which cloud storage system are you using?

Google Cloud Storage

The command you were trying to run

rclone
--gcs-project-number <redacted>
--gcs-service-account-credentials <redacted>
--gcs-bucket-policy-only
--gcs-location europe-north1
mount
--log-level DEBUG
--log-file ~/rclone.log
--vfs-cache-mode full
--vfs-read-ahead 16M
--cache-dir ~/viilu-cache
--dir-cache-time 0m30s
--volname Volume
--local-no-check-updated
--dir-perms 0777
--file-perms 0777
--umask 0000
--buffer-size 16M
--retries 10
--retries-sleep 0m3s
--fast-list
--option local
--option volicon=/public/icons/mac/drive-icon.icns
:gcs:<redacted>/test

The rclone config contents with secrets removed.

no config file since all parameters are in the command.

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

The log with debug level can be found here: https://gist.github.com/SamiPussinen/271e36afb872edc66813082814aba35a

Some state seems to get stuck somewhere and is fixed by restarting rclone. This only happens when using VFS, which we need to use to have the mount behave nicely with other programs, like MS office.

ncw · March 8, 2021, 12:38pm

That is a great summary thank you

Do files get transferred to and from the bucket not through rclone?

Are there multiple rclone mounts pointed at the same bucket?

Can you reproduce this via the command line? So using cp to copy files into the mount and mv to rename them?

A bit of googling indicates that 8072 is a permissions error. I can't get anything more specific that that!

You could try mounting with -o default_permissions to see if that helps.

Can you also try -o hard_remove independently to see if that helps?

Here is an edited log of what happened to g.png - it is complicated!

File opened for creation

2021/03/07 21:11:19 DEBUG : /g.png: CreateEx: flags=0xA02, mode=0100644
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDWR|O_CREATE|O_EXCL
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle: 
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): openPending: 
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: truncate to size=0
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): >openPending: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >CreateEx: errc=0, fh=0x1

Flush and release indicating a 0 length file got written as no data was added

2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): close: 
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: setting modification time to 2021-03-07 21:11:19.01845 +0200 EET m=+6.585567369
2021/03/07 21:11:19 INFO  : g.png: vfs cache: queuing for upload in 5s
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0

Now we open it again for reading, not sure why it is never read

2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle: 
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): close: 
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0

Now we open it for reading again, not sure why it never seems to have data read from it

2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle: 
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): close: 
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0

Now we open it for reading again

2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle: 
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1

Fuse decides to rename it to .fuse_hidden as it is about to be deleted and an app has it open

Really not sure why this is happening nothing seems to delete the file. Maybe the create is confusing it.

2021/03/07 21:11:19 DEBUG : /g.png: Rename: newPath="/.fuse_hidden0000000a00000007"
2021/03/07 21:11:19 INFO  : g.png: vfs cache: renamed in cache to ".fuse_hidden0000000a00000007"
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vDel: "g.png"
2021/03/07 21:11:19 DEBUG : /g.png: >Rename: errc=0

File is opened for Create

2021/03/07 21:11:19 DEBUG : /g.png: CreateEx: flags=0xA02, mode=0100644
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDWR|O_CREATE|O_EXCL
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle: 
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): openPending: 
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: truncate to size=0
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >openPending: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >CreateEx: errc=0, fh=0x2

Data written to the file

2021/03/07 21:11:19 DEBUG : /g.png: Write: ofst=0, fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): _writeAt: size=4096, off=0
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >_writeAt: n=4096, err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Write: n=4096
2021/03/07 21:11:19 DEBUG : /g.png: Write: ofst=4096, fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): _writeAt: size=4096, off=4096
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >_writeAt: n=4096, err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Write: n=4096
[snip]
2021/03/07 21:11:19 DEBUG : /g.png: Write: ofst=172032, fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): _writeAt: size=3625, off=172032
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >_writeAt: n=3625, err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Write: n=3625

Flush and release (close) the file

2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): close: 
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: setting modification time to 2021-03-07 21:11:19.26521 +0200 EET m=+6.832321076
2021/03/07 21:11:19 INFO  : g.png: vfs cache: queuing for upload in 5s
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0

Chmod it and set its time

2021/03/07 21:11:19 DEBUG : /g.png: Chmod: mode=0100644
2021/03/07 21:11:19 DEBUG : /g.png: >Chmod: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Utimens: tmsp=[{Sec:1615144279 Nsec:266180000} {Sec:1614951679 Nsec:515806556}]
2021/03/07 21:11:19 DEBUG : /g.png: Utimens: SetModTime: 2021-03-05 15:41:19.515806556 +0200 EET
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: setting modification time to 2021-03-05 15:41:19.515806556 +0200 EET
2021/03/07 21:11:19 DEBUG : /g.png: >Utimens: errc=0

Open it again for reading but don't do anything

2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle: 
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x2
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): close: 
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0

And again

2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle: 
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): close: 
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0

We still have fh=0x1 open here - or do we? - in the block above it is flushed and released

ncw · March 8, 2021, 2:21pm

Can you also try the latest beta with the latest macfuse 4.0.5?

Sami_Pussinen · March 8, 2021, 4:35pm

I tried this with the latest beta and MacFuse 4.0.5 as well. Unfortunately I got the same result

Here are some answers to your questions.
Files don't get transferred to or from the bucket without rclone.

Multiple mounts could be pointed to the same bucket at the same time (different machines), but the issue happens even when there's only one (me at 3AM trying to figure this one out for example).

I tested moving the "affected files" via Terminal and it seems to work fine! After the wonky file gets renamed by using mv it also starts working fine through Finder.

Neither -o default_permissions or -o hard_remove doesn't seem to affect the issue.

I'm not yet too versed in the art of low level file operations, so the debug logs don't tell too much to me. However, from your "English translation" (thanks!) it seems strange that there are those renames to FUSE hidden files, since the files are not deleted. Shouldn't FUSE do the renaming if the file is open and it's deleted? These log lines are present when just copying files to the mount. And the files aren't open either, except maybe they are opened by the Finder process itself?

There doesn't seem to be a clear pattern in this. When this issue happens, the thumbnail is the default one, you cannot rename the file and you cannot remove it as well, since that throws an error as well. I noticed that by attempting to remove the file we get another error code.

The interesting part is that when you then go back a directory and up again to the original directory (essentially refreshing the Finder view) the thumbnail now is displayed fine and you are able to rename or delete the file! But this is the case only for that one file that first failed to be deleted

I also noticed that all the thumbnails display fine and the files can be renamed and deleted fine if you kill the finder process by doing killall Finder. After killing it the Finder restarts and everything works as it should. This is very curious. It somehow seems like Finder "loses track" of some of the files and starts working fine again after a restart. Any guesses? Thank you so much for the help!

Sami_Pussinen · March 8, 2021, 4:39pm

Even doing a simple touch to an affected file resolves the issue. Maybe a desperate measure is to make an utility that just touches everything after creation

Sami_Pussinen · March 8, 2021, 5:37pm

The issue seems to relate to the fact that according to the logfile the files are added, then removed and then added back. This is happening when just copying files to a directory. Here's an example of a copy:

2021/03/08 19:21:55 INFO  : a.png: vfs cache: queuing for upload in 5s
2021/03/08 19:21:55 INFO  : a.png: vfs cache: removed cache file as file deleted
2021/03/08 19:21:55 INFO  : a.png: vfs cache: queuing for upload in 5s
2021/03/08 19:21:56 INFO  : a.png: vfs cache: queuing for upload in 5s
2021/03/08 19:22:01 INFO  : a.png: Copied (new)
2021/03/08 19:22:01 INFO  : a.png: vfs cache: upload succeeded try #1

In this example the file a.png is copied to the directory and the whole add, delete, add thing is quite fast (happens during the same second). However, not all files are this fast with this loop.

I tried doing a quick proof of concept touch based solution to this. I have a directory watcher watching for changes and doing a touch after a few seconds a new file is added. This alleviates the problem somewhat, but when copying over multiple files it still seems flaky. The upload speed doesn't seem to affect the success of the touch however. It is enough to touch the file after it has been "added again after the delete".

ncw · March 8, 2021, 5:42pm

Thanks

OK that is one thing ruled out

OK that is interesting. So this is rclone confusing finder somehow...

I really don't understand why we are getting those funny renames.

I was hoping error -43 might be OS error but this doesn't look right

  43 EPROTONOSUPPORT Protocol not supported.  The protocol has not been
         configured into the system or no implementation for it exists.

Both of these are indicative that somehow finder is confused.

Hmm...

Can you try with -o hard_remove and just check that you don't get the .fuse_hidden files?

Assuming that is the case, can you make a log with -vv -o hard_remove --debug-fuse of the problem? There should be less stuff going on in the log which should hopefully make it easier to follow.

Yes the finder seems to make a 0 length file first, then delete it while open (which causes the .fuse_hidden files) then creates it again it with a full length file.

I'd be interested in a log of touch fixing the problem too if you have one.

ncw · March 9, 2021, 9:47am

I had an idea about this while I was out walking the dog this morning...

It would be really helpful if we could work out which error the finder is getting.

What we could do to find that out is to strace/dtruss the finder binary to show what system calls it is calling and what the results are.

This stack overflow page gives some useful hints

What I'd like to know is what system calls the finder calls on g.png and what errors it got back.

Sami_Pussinen · March 16, 2021, 8:38am

Hi Nick,

I'm dropping by just to give a situation report. Unfortunately I haven't managed to try out your suggestions yet. I've been quite overworked and then got sick on top of that. However, I can tell you that the situation is 'stable' at least momentarily with a hack I did that watches the mount files and touches them after they stabilize (it waits for the file to not change for a couple of seconds, which solves the 0 byte file thing). This is incredibly hacky, but seems to help my users so that they can at least work with the thing.

I'll try to look into this more over the weekend. Thanks for the suggestions and sorry for the long silence.

ncw · March 16, 2021, 1:44pm

Sorry you've been ill

I've merged a lot of little VFS and mount fixes over the last few days so it would be worth trying the latest beta again too.

system · May 16, 2021, 9:45am

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.