Cannot copy files to mounted azure storage (WIndows)

hami89 · April 6, 2022, 3:26pm

What is the problem you are having with rclone?

I am trying to mount an Azure blob storage account (hierarchical namespaces enabled) as a drive on an Azure VM.
The actual mount is successful, files can be read, renamed and deleted from all containers within the storage account.

When I try to copy files to any folder, an error is thrown, that the file already exists (and rclone creates a 0 byte blob), and then it is not possible to overwrite the created zero byte file. But I can rename or delete it.

I tried to do the mount to a folder instead of a drive, I tried to mount only one container instead of the full storage and I also tried it from my laptop (Win 11) with the same setup, but I have the same result.

The interesting part is that I can create files directly on the mounted storage. Eg: selecting 100 local files and compressing them to a zip file directly to the storage works. Compressing the files locally and copy the zip file doesn't.

Originally I did the mounting with nssm using SYSTEM user, but for debug I switched over to console, same result.

Run the command 'rclone version' and share the full output of the command.

rclone v1.58.0
- os/version: Microsoft Windows Server 2022 Datacenter Azure Edition 21H2 (64 bit)
- os/kernel: 10.0.20348.587 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.17.8
- go/linking: dynamic
- go/tags: cmount

WinFsp version: 1.10.22006.0

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

Azure Storage (General purpose account with hierarchical namespaces enambled)

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

rclone mount xydatablob: C:\xy --volname "XY Data" --config C:\Secrets\rclone.conf --vfs-cache-mode full
rclone mount xydatablob: C:\xy --volname "XY Data" --config C:\Secrets\rclone.conf --vfs-cache-mode full -o GroupName="Authenticated Users" --dir-perms 0777 --file-perms 0777

Note: group names and permissions really did not change anything, I was just experimenting with them.

The rclone config contents with secrets removed.

[xydatablob]
type = azureblob
account = ...
key = ....

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

I opened a container from the mount "test" and tried to copy a file "testfile" into it, which created a zero byte file, then told me that it already exists, I chose overwrite, then it throw no permission error.
Note: I renamed my real storage name to "XY" in the log.

Full log from mount until copy failure and shutdown.

ncw · April 6, 2022, 3:40pm

The file is sucessfully created here

2022/04/06 15:11:09 DEBUG : test/testfile: Open: flags=O_RDWR|O_CREATE|O_EXCL
2022/04/06 15:11:09 DEBUG : test/testfile: newRWFileHandle:
2022/04/06 15:11:09 DEBUG : test/testfile(0xc00051c380): openPending:
2022/04/06 15:11:09 DEBUG : test/testfile: vfs cache: truncate to size=0
2022/04/06 15:11:09 DEBUG : test: Added virtual directory entry vAddFile: "testfile"
2022/04/06 15:11:09 DEBUG : test/testfile(0xc00051c380): >openPending: err=<nil>
2022/04/06 15:11:09 DEBUG : test/testfile: >newRWFileHandle: err=<nil>
2022/04/06 15:11:09 DEBUG : test: Added virtual directory entry vAddFile: "testfile"
2022/04/06 15:11:09 DEBUG : test/testfile: >Open: fd=test/testfile (rw), err=<nil>
2022/04/06 15:11:09 DEBUG : /test/testfile: >CreateEx: errc=0, fh=0x0

And then a bit later the file is created again

2022/04/06 15:11:09 DEBUG : /test/testfile: CreateEx: flags=0x502, mode=0770
2022/04/06 15:11:09 DEBUG : test/testfile: Open: flags=O_RDWR|O_CREATE|O_EXCL
2022/04/06 15:11:09 DEBUG : test/testfile: newRWFileHandle:
2022/04/06 15:11:09 DEBUG : test/testfile: >newRWFileHandle: err=file already exists
2022/04/06 15:11:09 DEBUG : test/testfile: File.openRW failed: file already exists
2022/04/06 15:11:09 DEBUG : test/testfile: >Open: fd=<nil *RWFileHandle>, err=file already exists
2022/04/06 15:11:09 DEBUG : /test/testfile: >CreateEx: errc=-17, fh=0xFFFFFFFFFFFFFFFF

However this time the creation fails because O_EXCL was passed in which means only create this if it doesn't exist, and it already does.

So this looks at first glance to be application doing the copying doing something strange.

Which application are you copying the file to the mount with?

hami89 · April 6, 2022, 3:49pm

I used total commander originally, but the result was the same from File explorer too (at least from user perspective). I created a log from File explorer for the same test steps:

hami89 · April 6, 2022, 4:52pm

I also tried it from command line, exact same results.

hami89 · April 7, 2022, 9:17pm

I made several further tests, when I use rclone on an Azure Virtual Machine (Win '22 server), it always runs into this behavior, regardless of the mounted storage (I also tried ftp and sftp) and the program used for copying the files.
Can it be some strange behavior of Windows Server '22 or an Azure VM itself?

ncw · April 8, 2022, 1:39pm

It sounds like Windows datacenter 22 is behaving differently somehow.

I suspect this might be an interaction between it an WinFsp. I looked on the WinFsp github page and I couldn't see any relevant issues.

This looks like a regression in Win 2022 but I'm not certain - @billziss-gh do you have a thought about this?

@hami89 it would be worth trying to reproduce this with one of WinFsp's own filing systems such as sshfs-win and if that fails reporting a bug on the WinFsp github. If it doesn't fail it is probably an rclone problem (a misunderstanding of something by me most likely!).

hami89 · April 11, 2022, 3:57pm

I have installed SSHFS-Win 2021.1 Beta2 atop of my pre-existing config.

I ran the following command:

C:\Users\ghamos>net use Z: \\sshfs\xyz@xyz.com
The password is invalid for \\sshfs\xyz@xyz.com.

Enter the user name for 'sshfs': xyz
Enter the password for sshfs:
The command completed successfully.

After this a new Z: network drive appeared, and I could simply copy-paste the same "testfile" successfully to the SFTP site. Because of this, I think it is not a WinFsp issue.

Later today I will try the whole rclone mount process with the current beta release of WinFsp and using rclone to mount as network drive.

ncw · April 11, 2022, 4:36pm

That is great testing thank you.

Cross fingers it is fixed in the WinFSP beta.

If not, can you describe what sort of Azure VM you used and I'll have a go at reproducing it.

hami89 · April 12, 2022, 1:08pm

Unfortunately, I got the same behavior after installing the latest beta version of WinFsp. (I tried it with SFTP and Azure Blob storages attached as drives and folders.) As soon as I put files there, it says that they already exist and I have no permission to overwrite them, and a 0 byte file is created for each.
The picture below was taken after dropping 3 files to an empty test folder. Three 0 byte files appeared immediately and a file exist error was thrown:

After choosing "Replace...":

With sshfs it worked with the same files.

Environment
We have two similar virtual machines hosted in different Azure (West US & North EU), but they behave the same regarding this issue.

Machine parameters:
Size: Standard B8ms (8 vcpus, 32 GiB memory) >> I don't think that this matters.
OS: Windows (Windows Server 2022 Datacenter Azure Edition)

On extra info, but it should not affect this: we are using Azure AD to log into the virtual machine. Regarding my user, I have administratrative privileges on the machine.

ncw · April 12, 2022, 3:02pm

Thanks for trying.

Can you do one more test for me? The original log you generated was very good - can you generate that one for me but with the --debug-fuse flag set. This should have lots more debug in it from cgofuse which hopefully will have a clue in and I can ask the WinFSP author about.

Thank you

hami89 · April 12, 2022, 3:51pm

I made one more test with the following command:
rclone mount xyzdatablob: W: --config C:\Secrets\rclone.conf --vfs-cache-mode full -o GroupName="Authenticated Users" --dir-perms 0777 --file-perms 0777 -vv --debug-fuse

Full command line log is here: rclone azure mount copy error (from explorer with fuse debug) - Pastebin.com

ncw · April 13, 2022, 12:21pm

Looking at this carefully and looking up the values of the constants, the 0x502 passed from Windows does not include O_EXCL which is 0x400 according to the cgofuse constants, so it looks like something has got lost in translation.

Rclone translates that 0x502 from WinFSP/cgofuse which should be O_RDWR|O_CREATE|O_TRUNC into O_RDWR|O_CREATE|O_EXCL as if the TRUNC and EXCL flags are the wrong way round...

I think this might be a bug in cgofuse or WinFSP so I've made an issue report here

github.com/winfsp/cgofuse

Mixup of O_EXCL and O_TRUNC constant values CGO vs non CGO

opened 12:17PM - 13 Apr 22 UTC

ncw

If you compile and run this program ```go package main import ( "fmt" … "github.com/winfsp/cgofuse/fuse" ) func main() { fmt.Printf("fuse.O_APPEND = 0x%04x\n", fuse.O_APPEND) fmt.Printf("fuse.O_CREAT = 0x%04x\n", fuse.O_CREAT) fmt.Printf("fuse.O_EXCL = 0x%04x\n", fuse.O_EXCL) fmt.Printf("fuse.O_TRUNC = 0x%04x\n", fuse.O_TRUNC) } ``` It prints this ``` Z:\go\src\github.com\rclone\rclone\cgofusetest>go run test.go fuse.O_APPEND = 0x0008 fuse.O_CREAT = 0x0100 fuse.O_EXCL = 0x0400 fuse.O_TRUNC = 0x0200 ``` However if you disable CGO and compile it you get a different answer with O_EXCL and O_TRUNC swapped over. ``` Z:\go\src\github.com\rclone\rclone\cgofusetest>set CGO_ENABLED=0 Z:\go\src\github.com\rclone\rclone\cgofusetest>go run test.go fuse.O_APPEND = 0x0008 fuse.O_CREAT = 0x0100 fuse.O_EXCL = 0x0200 fuse.O_TRUNC = 0x0400 ``` I believe the non CGO version is correct, at least that agrees with what I receive from WinFSP. It is defined here https://github.com/winfsp/cgofuse/blob/f0ad03169e0f07409feb7e3db95fba57fab5cfc6/fuse/fsop_nocgo_windows.go#L107-L108 whereas the CGO version is defined here - this also looks correct https://github.com/winfsp/cgofuse/blob/f0ad03169e0f07409feb7e3db95fba57fab5cfc6/fuse/fsop_cgo.go#L249-L250 So something a little wacky is going on! This is compiling on Windows 10 with go1.18.1 and gcc 8.1.0 provided by MinGW using latest released cgofuse v1.5.0 and latest stable WinFSP (2022 installed from `1.10.220006.msi`). This was originally reported in the rclone forum here: https://forum.rclone.org/t/cannot-copy-files-to-mounted-azure-storage-windows/30092 if you want some background. I suspect that the problem might be with the WinFSP include files, but I couldn't figure out where the constants were defined. You said before in https://github.com/winfsp/cgofuse/issues/19#issuecomment-344405666 where we discussed a very similar issue > WinFsp-FUSE supports both the MSVC and Cygwin environments. In MSVC O_CREAT|O_RDWR translates to 0x0102. In Cygwin it translates to 0x0202. Cgofuse uses the MSVC environment, which is the reason you see 0x0102. So I wonder if I'm including the Cygwin version of the fuse header files or something like that? This is the include I use CPATH=C:\Program Files\WinFsp\inc\fuse;C:\Program Files (x86)\WinFsp\inc\fuse Any help gratefully received!

rclone[TID=24b4]: FFFF9E86CC94E060: >>Create [UT---C] "\test\testfile", FILE_CREATE, CreateOptions=44, FileAttributes=20, Security=NULL, AllocationSize=0:1825000, AccessToken=0000000000000298[PID=2350], DesiredAccess=17019f, GrantedAccess=0, ShareAccess=0
2022/04/12 15:46:22 DEBUG : /test: Getattr: fh=0xFFFFFFFFFFFFFFFF
2022/04/12 15:46:22 DEBUG : /test: >Getattr: errc=0
2022/04/12 15:46:22 DEBUG : /test/testfile: CreateEx: flags=0x502, mode=0770
2022/04/12 15:46:22 DEBUG : test/testfile: Open: flags=O_RDWR|O_CREATE|O_EXCL
2022/04/12 15:46:22 DEBUG : test/testfile: newRWFileHandle:
2022/04/12 15:46:22 DEBUG : test/testfile(0xc000c1a080): openPending:
2022/04/12 15:46:22 DEBUG : test/testfile: vfs cache: truncate to size=0
2022/04/12 15:46:22 DEBUG : test: Added virtual directory entry vAddFile: "testfile"
2022/04/12 15:46:22 DEBUG : test/testfile(0xc000c1a080): >openPending: err=<nil>
2022/04/12 15:46:22 DEBUG : test/testfile: >newRWFileHandle: err=<nil>
2022/04/12 15:46:22 DEBUG : test: Added virtual directory entry vAddFile: "testfile"
2022/04/12 15:46:22 DEBUG : test/testfile: >Open: fd=test/testfile (rw), err=<nil>
2022/04/12 15:46:22 DEBUG : /test/testfile: >CreateEx: errc=0, fh=0x0
2022/04/12 15:46:22 DEBUG : /test/testfile: Release: fh=0x0
2022/04/12 15:46:22 DEBUG : test/testfile(0xc000c1a080): RWFileHandle.Release
2022/04/12 15:46:22 DEBUG : test/testfile(0xc000c1a080): close:
2022/04/12 15:46:22 DEBUG : test/testfile: vfs cache: setting modification time to 2022-04-12 15:46:22.8018157 +0000 GMT m=+18.086083401
2022/04/12 15:46:22 INFO  : test/testfile: vfs cache: queuing for upload in 5s
2022/04/12 15:46:22 DEBUG : test/testfile(0xc000c1a080): >close: err=<nil>
2022/04/12 15:46:22 DEBUG : /test/testfile: >Release: errc=0
rclone[TID=24b4]: FFFF9E86CC94E060: <<Create IoStatus=c0000010[0]

ncw · April 15, 2022, 11:16am

That mixup is a bug, but it isn't the bug causing your problem.

After a bit of discussion we think we might be narrowing in on the problem.

Could you do your test with this binary please which has a bit of extra logging in which will confirm or deny the theory!

v1.59.0-beta.6072.c9ae0654f.fix-cmount-copy on branch fix-cmount-copy (uploaded in 15-30 mins)

Thank you

hami89 · April 21, 2022, 12:24pm

Sorry for the late reply. I managed to do the test today with the modified binary you linked.

Here is the log: rclone azure mount copy error (from explorer with extra debug) - Pastebin.com

ncw · April 21, 2022, 3:45pm

Thank you for the log - that confirms what we were thinking. For discussion see Mixup of O_EXCL and O_TRUNC constant values CGO vs non CGO · Issue #66 · winfsp/cgofuse · GitHub

system · May 21, 2022, 3:46pm

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