Hello i m testing rclone git master (latest tag is 1.54-stable, sha: 1406b6c3c9e21f59cba027101bfb2e014a21736e). My windows version is 20H2 x64, winfsp - 2020.2
I experience an issue when i can not get status for write operation onto rclone mount -ed virtual wile system.
Digging deeper i found that control to the system was returned after cmd/cmount.Write() exits, then cmd/cmount.Flush() is called and actual remote flushing (in my case backend/webdav.Update()) occurs. So if there is access violation on remote, client will not catch an error.
e.g. echo 1 > w:\test.txt return control before Flush starts...
Maybe it is supposed to be so, to increase write performance? But this look strange enought.
The command you were trying to run:
rclone mount :webdav: w: --webdav-url https://webdav:8800/
im looking that WinFSPy does not return control before cleanup: winfspy\plumbing\file_system_interface.py:_trampolin_fs_Cleanup() is called immediately after _trampolin_fs_Write()
So maybe there is something different in volume setup?
The way FUSE filesystem work is that they will try to return errors on Write and also on Flush but there is no way to return an error from Release - this is called by the kernel some time after the user has finished with the file.
From your description it sounds like some writeback caching is going on.
Can you do a simple example with rclone mount -vv --debug-fuse and post the log here? Then I will be able to see exactly what you mean.
There may well be mount options to control this -o flag or WinFSP options which you can pass through as well.
Ah, I see what is going on. It is rclone doing the caching for small files.
Try setting --streaming-upload-cutoff 0
--streaming-upload-cutoff SizeSuffix Cutoff for switching to chunked upload if file size is unknown. Upload starts after reaching cutoff or when file ends. (default 100k)
ok first we should confirm that issue is really persists, @ncw may i hope that you will check that control was returned before Flush occur? It all sounds that it should not happed this way.
Then i would investigate the difference between cgofuse and WinFSPy mounts.
2021/04/25 14:27:37 DEBUG : webdav root '': Target remote doesn't support streaming uploads, creating temporary local FS to spool file
What that means is the webdav backend doesn't support unknown length uploads so rclone has to spool the file to disk. This means that the file won't be transmitted to the remote end until the Flush is called. However the flush should return any errors at that point.
You could try your test to a different backend (you can use the local disk) and see if you get the same result?
Destination is not writeable but operation succeeds. i also made time breaks (by breakpoints) before Flush started but operation is still succeeds without breakpoints.
Also i can not find place where Write operation return to WinFSP the STATUS_PENDING code. Current behaviour would be because of operation returns STATUS_SUCCESS code for asynchronous write...
Looking at the WinFSP debug it appears WinFSP calls both Flush and Release in one transaction which is reasonable, but crucially it seems to be ignoring the error code of the Flush
__debug_bin[TID=1164]: FFFF800C4D60EC30: >>Close 0000000000000000:000002A8BD34C270
2021/04/26 14:13:34 DEBUG : /test.txt: Flush: fh=0x0
2021/04/26 14:13:34 ERROR : test.txt: WriteFileHandle.New Rcat failed: Access is denied.
2021/04/26 14:13:34 ERROR : test.txt: WriteFileHandle.Flush error: Access is denied.
2021/04/26 14:13:34 ERROR : IO error: Access is denied.
2021/04/26 14:13:34 DEBUG : /test.txt: >Flush: errc=-5 <-------------- an error is returned by rclone here
2021/04/26 14:13:34 DEBUG : /test.txt: Release: fh=0x0
2021/04/26 14:13:34 DEBUG : test.txt: WriteFileHandle.Release nothing to do
2021/04/26 14:13:34 DEBUG : /test.txt: >Release: errc=0
__debug_bin[TID=1164]: FFFF800C4D60EC30: <<Close IoStatus=0[0] <------ but no error appears here?
So I wonder if this is a WinFSP FUSE layer bug?
@billziss-gh what do you think? Where did this error go?
not sure if i correctly explained the issue that i concerned with.
It does not matter if there is an error or not, but now control returned to the system immediately after Write operation finished so as control returned, there is not way to get status or measure time spent on operation. This would be inspected with debugger.
As far as i know, write operation should return 259/0x103 code (STATUS_PENDING) for asynchronous write that definitely rclone do, but i still can not find corresponding place to inspect neither in rclone or cgofuse.
I would guess that this is caused by a mis-match between the FUSE file system layer which was designed for Linux/Unix systems and WinFSP which has to adapt that into a Windows file system.
