Rclone mount: Synchonous write transaction?

Help and Support
21

so i still digging...

I realized that cgofuse use compatibility layer (fuse_main) and winfspy use winfsp api
i also inspected that same status is returned by write operations in both (STATUS_SUCCESS), and switching fuse_intf_Write status to STATUS_PENDING causing deadlock.

It definitely is not kernel space issue, otherwise both frameworks will encounter this issue.

I also captured logs from both winfspy.log (3.8 KB) and rclone.log (10.5 KB) and it look like rclone does not actually handle Cleanup but do both Flush and Release on Close. @ncw really sorry for buzzing but would you consider this?

22

but is still may be on WinFSP responsibility as fuse does not provide Cleanup handler, so Flush should be called on Cleanup...

23

There is no Cleanup in FUSE as you've discovered.

I still think that this trace is the cause of the problem WinFSP appears to have ignored the error from the Flush call

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?

It might best to open an issue on the WinFSP github about this as you've reached the limits of my understanding of the Windows file system.

24

Good advice. fuse_main_real: Control is returned before Flush called · Issue #365 · billziss-gh/winfsp · GitHub

25

@ncw recent test discovered that error is not reported even on file creation:

rclone mount :local:f: x: -vv --debug-fuse

>>> f.write('test\n')
5
>>> f.flush()
>>> os.fsync(f.fileno())
>>> f.close()
>>>
>>> f = open('f:\\test.txt', 'w')
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
PermissionError: [Errno 13] Permission denied: 'f:\\test.txt'
>>>

and the rclone-fsync.log (5.3 KB)

I also checked reference winfsp/tst/passthrough-fuse3 at master · billziss-gh/winfsp · GitHub that reported correct error on file creation.

26

missed open:

>>> f = open('x:\\test.txt', 'w')
>>> f.write('test\n')
27

I m not sure if i got Bill correctly, he did not provided scenario for asynchronous write, it maybe rclone's write() is handled by winfsp as synchronous... But i first would like to get clarity about should be :local:f: x: consistent with passthrough filesystem?

28

I have replied on the WinFSP issue.

29

I didn't realized, did you considered creation issue, so i have to dig deeper and may be find root issue?

I had tested passthrough with debug logging and error is correctly reported:

The service passthrough-fuse3-x has been started.
passthrough-fuse3-x[TID=1b18]: FFFFC78C66867CA0: >>QueryVolumeInformation
passthrough-fuse3-x[TID=1b18]: FFFFC78C66867CA0: <<QueryVolumeInformation IoStatus=0[0] VolumeInfo={TotalSize=1b:ceaff000, FreeSize=9:83443000, VolumeLabel=""}
passthrough-fuse3-x[TID=0788]: FFFFC78C65F9B010: >>Create [UT----] "\", FILE_OPEN, CreateOptions=20, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=00000000000001EC[PID=2f88], DesiredAccess=100080, GrantedAccess=0, ShareAccess=7
passthrough-fuse3-x[TID=0788]: FFFFC78C65F9B010: <<Create IoStatus=0[1] UserContext=0000000000000000:0000016A2F86A860, GrantedAccess=100080, FileInfo={FileAttributes=10, ReparseTag=0, AllocationSize=0:2000, FileSize=0:2000, CreationTime=2019-03-19T04:37:21.986Z, LastAccessTime=2021-05-24T14:04:05.361Z, LastWriteTime=2021-05-24T08:40:23.426Z, ChangeTime=2021-05-24T08:40:23.426Z, IndexNumber=0:0}
passthrough-fuse3-x[TID=0788]: FFFFC78C65A098D0: >>Close 0000000000000000:0000016A2F86A860
passthrough-fuse3-x[TID=0788]: FFFFC78C65A098D0: <<Close IoStatus=0[0]
passthrough-fuse3-x[TID=0788]: FFFFC78C65B0D810: >>Create [UT----] "\test.txt", FILE_OVERWRITE_IF, CreateOptions=60, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=00000000000001F8[PID=2784], DesiredAccess=120196, GrantedAccess=0, ShareAccess=3
passthrough-fuse3-x[TID=0788]: FFFFC78C65B0D810: <<Create IoStatus=c0000022[0]
passthrough-fuse3-x[TID=0788]: FFFFC78C65A0DC60: >>Create [KTBR--] "\test.txt", FILE_OPEN, CreateOptions=4140, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=00000000000001F8[PID=2784], DesiredAccess=0, GrantedAccess=100180, ShareAccess=7
passthrough-fuse3-x[TID=0788]: FFFFC78C65A0DC60: <<Create IoStatus=c0000034[0]
passthrough-fuse3-x[TID=0788]: FFFFC78C65B0D810: >>Create [UT----] "\test.txt", FILE_OVERWRITE_IF, CreateOptions=60, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=00000000000001F8[PID=2784], DesiredAccess=120196, GrantedAccess=0, ShareAccess=3
passthrough-fuse3-x[TID=0788]: FFFFC78C65B0D810: <<Create IoStatus=c0000022[0]

rclone does not attempt to call winapi.CreateFile on first open but on close, so i m not sure what a descriptor returned on opening file.

30

I think this is because of the buffering caused by this flag. Set --streaming-upload-cutoff 0 and it should do what you expect on Open.

  --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 100Ki)
31

still no error ((

rclone.log (11.2 KB)

32

Hmm, I wonder if that is a bug in operations.Rcat

Can you see if you can replicate the no error problem with something like this?

echo something | rclone rcat --streaming-upload-cutoff 0 -vv :local:f:\file.txt

(you might have to translate that to Windows - not sure if echo | works on Windows)

33

Error reported in both cases, but with --streaming-cutoff there are two errors:

C:\Users\kalem\Downloads\rclone-v1.55.1-windows-amd64>echo 1 | .\rclone.exe rcat -vv --streaming-upload-cutoff 0 :local:F:\test.txt
2021/05/28 14:37:07 DEBUG : Using config file from "C:\\Users\\kalem\\.config\\rclone\\rclone.conf"
2021/05/28 14:37:07 DEBUG : rclone: Version "v1.55.1" starting with parameters [".\\rclone.exe" "rcat" "-vv" "--streaming-upload-cutoff" "0" ":local:F:\\test.txt"]
2021/05/28 14:37:07 DEBUG : Creating backend with remote ":local:F:/"
2021/05/28 14:37:07 DEBUG : fs cache: renaming cache item ":local:F:/" to be canonical ":local://?/F:/"
2021/05/28 14:37:07 DEBUG : 3 go routines active
2021/05/28 14:37:07 Failed to rcat with 2 errors: last error was: The system cannot find the file specified.

C:\Users\kalem\Downloads\rclone-v1.55.1-windows-amd64>echo 1 | .\rclone.exe rcat -vv :local:F:\test.txt
2021/05/28 14:37:33 DEBUG : Using config file from "C:\\Users\\kalem\\.config\\rclone\\rclone.conf"
2021/05/28 14:37:33 DEBUG : rclone: Version "v1.55.1" starting with parameters [".\\rclone.exe" "rcat" "-vv" ":local:F:\\test.txt"]
2021/05/28 14:37:33 DEBUG : Creating backend with remote ":local:F:/"
2021/05/28 14:37:33 DEBUG : fs cache: renaming cache item ":local:F:/" to be canonical ":local://?/F:/"
2021/05/28 14:37:33 DEBUG : Local file system at //?/F:/: File to upload is small (4 bytes), uploading instead of streaming
2021/05/28 14:37:33 ERROR : test.txt: Failed to copy: The system cannot find the file specified.
2021/05/28 14:37:33 DEBUG : 4 go routines active
2021/05/28 14:37:33 Failed to rcat: The system cannot find the file specified.

C:\Users\kalem\Downloads\rclone-v1.55.1-windows-amd64>echo 1 | .\rclone.exe rcat -vv :local:F:\Temp\test.txt
2021/05/28 14:38:29 DEBUG : Using config file from "C:\\Users\\kalem\\.config\\rclone\\rclone.conf"
2021/05/28 14:38:29 DEBUG : rclone: Version "v1.55.1" starting with parameters [".\\rclone.exe" "rcat" "-vv" ":local:F:\\Temp\\test.txt"]
2021/05/28 14:38:29 DEBUG : Creating backend with remote ":local:F:/Temp/"
2021/05/28 14:38:29 DEBUG : fs cache: renaming cache item ":local:F:/Temp/" to be canonical ":local://?/F:/Temp/"
2021/05/28 14:38:29 DEBUG : Local file system at //?/F:/Temp/: File to upload is small (4 bytes), uploading instead of streaming
2021/05/28 14:38:29 DEBUG : test.txt: MD5 = 9aeb7f1a6545b7f3fc45e2b54f614713 OK
2021/05/28 14:38:29 INFO  : test.txt: Copied (new)
2021/05/28 14:38:29 DEBUG : 4 go routines active
34

@ncw hi, sorry for delay, i want to summarize of what we talk with Bill on GitHub and it look like on windows rclone do async write when system serve sync write, so error could not be raised...

I think it would be solved by doing sync write and report the error (as a platform specifics or as command line parameter).

i attempted to just remove goroutine for Rcat call and it caused deadlock, so it look like i need general guideline to make a PR to solve this.

35

@kalemas can you write up and summarize the problem in a new issue on Github?

You can put a link to this forum post for context.

If you could link discussions with Bill also that would be very useful - thanks :slight_smile:

36

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