Windows vs Linux Rclone Mount Upload Delay

Suspected Bug
1

What is the problem you are having with rclone? Inconsistent behaviour on VFS Cache Upload between Linux and Windows versions

What is your rclone version (output from rclone version) 1.52.2 (Linux) 1.52.3 (Windows)

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Windows 2012 Datacenter and Centos 7 (both 64 bit)

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

Azure Blob

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

Windows

C:\Windows\System32\rclone.exe" mount --config=c:\windows\system32\rclone.conf mount cvodstorage:clients r: --cache-dir d:\rclonecache --allow-other --vfs-cache-mode=writes --fuse-flag --VolumePrefix=\cvodstorage\clients --log-level=DEBUG --cache-db-purge --vfs-cache-max-age=0h5m0s --log-file=c:\logs\rclone\cvodstorage-clients.log --azureblob-disable-checksum --poll-interval=0

Linux

rclone mount --config=/root/.config/rclone/rclone.conf --allow-other --allow-n
on-empty --default-permissions --vfs-cache-mode=writes --dir-cache-time=0m10s --
gid=1001 --uid=1001 --dir-perms=0777 --file-perms=0666 --umask=002 --poll-interv
al=0 --cache-dir=/mnt/rclone-linux-cache --log-level=DEBUG --azureblob-disable-c
hecksum --azureblob-chunk-size=16M --cache-db-purge --vfs-cache-max-age=0h5m0s -
-log-file=/var/log/rclone/cvodstorage-ingest.log cvodstorage:/ingest /mnt/azblob
/cvodstorage/ingest

The rclone config contents with secrets removed.

Windows

[cvodstorage]
type = azureblob
account = cvodstorage
key  ###############################################

Linux

[cvodstorage]
type = azureblob
account = cvodstorage
key = ##############################################

First thing to note is both mounts work fine, upload, download, no problem. The difference is when an "operation" (like a file write or file copy) COMPLETES compared to Cache upload to BLOB. All are using vfs-cache-mode = WRITES (but FULL has same behaviour)

Linux: A write or copy command (like cp) TO the BLOB will indicate finished AFTER the object has been uploaded to the BLOB.
Windows: A write or copy command (like cp) TO the BLOB will finish after the local VFS cache copy has been written but BEFORE the object has been uploaded to the BLOB.

Examples:

 Linux:
         1.  cp command is initiated from a LOCAL drive to a Azure Blob (cache full)
         2.  file writes to the cache file
         3.  cache file is uploaded to the Azure Blob container
         4.  cp command finishes

I have done about 100 tests on this with this consistent behaviour

Windows:
         1.  copy command is initiated from a LOCAL drive to an Azure Blob (cache full)
         2.  file writes to the cache file
         3.  Copy command finishes
         4.  Cache file is uploaded to the Azure Blob container

I have done 2 days worth of testing on this and cannot figure out why the difference.

Here are some snippets from the logs. This shows the log for the "WRITE/COPY" between the time the "write to cache" stops and the "upload starts". Notice the significant differences between Windows and Linux. I am aware the logs show different files but the point of the below is the behaviour. Probably the key difference is when the "RWFileHandle.Release closing" is sent. For Windows -- after Cache writes but before upload. For Linux -- after upload.

Windows: (Windows copy "completed" at 20:08:16. Cache Upload completed at 20:10:22)


2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Getattr: fh=0x0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Getattr: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Utimens: tmsp=[{Sec:1597089918 Nsec:421462900} {Sec:1491836365 Nsec:0}]
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Utimens: SetModTime: 2017-04-10 14:59:25 +0000 GMT
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Utimens: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Getattr: fh=0x0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Getattr: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Flush: fh=0x0
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf: Need to transfer - File not found at Destination
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Getattr: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Getattr: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Open: flags=0x0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf: Open: flags=O_RDONLY
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf: >Open: fd=AXN-STTVOY00702A.mxf (rw), err=<nil>
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >OpenFile: fd=AXN-STTVOY00702A.mxf (rw), err=<nil>
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Open: errc=0, fh=0x1
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Flush: fh=0x1
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Flush: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Release: fh=0x1
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Getattr: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Getattr: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Open: flags=0x0
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf(0xc000090000): RWFileHandle.Release closing
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf(0xc000090000): close: 
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf: Open: flags=O_RDONLY
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf: >Open: fd=AXN-STTVOY00702A.mxf (rw), err=<nil>
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >OpenFile: fd=AXN-STTVOY00702A.mxf (rw), err=<nil>
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Open: errc=0, fh=0x1
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Getattr: fh=0x1
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Getattr: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Flush: fh=0x1
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: >Flush: errc=0
2020/08/10 20:08:16 DEBUG : /AXN-STTVOY00702A.mxf: Release: fh=0x1
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf(0xc0002a8040): RWFileHandle.Release closing
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf(0xc0002a8040): close: 
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf: Multipart upload session started for 4160 parts of size 4M
2020/08/10 20:08:16 DEBUG : AXN-STTVOY00702A.mxf: Uploading part 1/4160 offset 0/16.250G part size 4M
.
.
.
2020/08/10 20:10:21 DEBUG : AXN-STTVOY00702A.mxf: Uploading part 4160/4160 offset 16.246G/16.250G part size 4M
2020/08/10 20:10:22 INFO  : AXN-STTVOY00702A.mxf: Copied (new)
2020/08/10 20:10:22 DEBUG : AXN-STTVOY00702A.mxf: File._applyPendingModTime OK
2020/08/10 20:10:22 DEBUG : AXN-STTVOY00702A.mxf: transferred to remote
2020/08/10 20:10:22 DEBUG : /AXN-STTVOY00702A.mxf: >Flush: errc=0
2020/08/10 20:10:22 DEBUG : /AXN-STTVOY00702A.mxf: Release: fh=0x0
2020/08/10 20:10:22 DEBUG : AXN-STTVOY00702A.mxf(0xc000090040): RWFileHandle.Release closing
2020/08/10 20:10:22 DEBUG : AXN-STTVOY00702A.mxf(0xc000090040): close: 
2020/08/10 20:10:22 DEBUG : AXN-STTVOY00702A.mxf: File.delWriter couldn't find handle
2020/08/10 20:10:22 DEBUG : AXN-STTVOY00702A.mxf: Modification times differ by -29237h10m57.0618476s: 2020-08-10 20:10:22.0618476 +0000 GMT, 2017-04-10 14:59:25 +0000 GMT
2020/08/10 20:10:37 INFO  : Cleaned the cache: objects 2 (was 2), total size 16.250G (was 16.250G)
2020/08/10 20:10:44 DEBUG : /desktop.ini: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/08/10 20:10:44 DEBUG : /desktop.ini: >Getattr: errc=-2

Linux: (Note for the CentOS level -- this job completed at 19:09:26 (after file upload to BLOB container). This behaviour is consistent for larger files as well.

2020/08/10 19:09:21 DEBUG : &{general-test1G-01-20200810190344.img (rw)}: >Write: written=65536, err=<nil>
2020/08/10 19:09:21 DEBUG : &{general-test1G-01-20200810190344.img (rw)}: Write: len=65536, offset=1073676288
2020/08/10 19:09:21 DEBUG : &{general-test1G-01-20200810190344.img (rw)}: >Write: written=65536, err=<nil>
2020/08/10 19:09:21 DEBUG : testFiles/test1G-01.img: Attr:
2020/08/10 19:09:21 DEBUG : testFiles/test1G-01.img: >Attr: a=valid=1s ino=0 size=1073741824 mode=-rw-rw-r--, err=<nil>
2020/08/10 19:09:21 DEBUG : &{testFiles/test1G-01.img (r)}: Read: len=4096, offset=1073741824
2020/08/10 19:09:21 DEBUG : &{testFiles/test1G-01.img (r)}: >Read: read=0, err=<nil>
2020/08/10 19:09:21 DEBUG : &{general-test1G-01-20200810190344.img (rw)}: Flush:
2020/08/10 19:09:21 DEBUG : general-test1G-01-20200810190344.img: Need to transfer - File not found at Destination
2020/08/10 19:09:21 DEBUG : general-test1G-01-20200810190344.img: Multipart upload session started for 64 parts of size 16M
2020/08/10 19:09:21 DEBUG : general-test1G-01-20200810190344.img: Uploading part 1/64 offset 0/1G part size 16M
2020/08/10 19:09:21 DEBUG : general-test1G-01-20200810190344.img: Uploading part 2/64 offset 16M/1G part size 16M.
.
.
.
2020/08/10 19:09:25 DEBUG : general-test1G-01-20200810190344.img: Uploading part 64/64 offset 1008M/1G part size 16M
2020/08/10 19:09:26 INFO  : general-test1G-01-20200810190344.img: Copied (new)
2020/08/10 19:09:26 DEBUG : general-test1G-01-20200810190344.img: transferred to remote
2020/08/10 19:09:26 DEBUG : &{general-test1G-01-20200810190344.img (rw)}: >Flush: err=<nil>
2020/08/10 19:09:26 DEBUG : &{general-test1G-01-20200810190344.img (rw)}: Release:
2020/08/10 19:09:26 DEBUG : &{testFiles/test1G-01.img (r)}: Flush:
2020/08/10 19:09:26 DEBUG : general-test1G-01-20200810190344.img(0xc0006971c0): RWFileHandle.Release closing
2020/08/10 19:09:26 DEBUG : &{testFiles/test1G-01.img (r)}: >Flush: err=<nil
2

If you can post the full log for each, that would be great.

3

The log is thousands of lines long but I can post it.

4

Just post a link to each, one from each system.

5

Corrected Windows Log Link

You can also see in the above log the file actually uploads twice.

6

hello and welcome to the forum,

  • --allow-other does nothing on windows.
  • --cache-db-purge is for cache backend and based on your config, you are not using cache backend.
7

Helpful -- thanks.

8

Linux Log

9

I think the difference is due to the windows filing system which is more asynchronous than Linux.

Can you try this test with the latest beta? This code has been completely rewritten.

This will do delayed writebacks for everything however you can control it with the --vfs-writeback parameter and disable it you want.

10

Hi Nick,

First of all -- thanks for answering. This is a really great product.

I tried the new Beta release (v.1.52.3-297-gaab9aaba-beta) and the results are the same.

I tried setting the --vfs-write-back to 0s (and 0) with no luck (I even tried "off" and "disabled" to try and "disable" the vfs-write-back).

I have attached an "edited" log where a lot of the "cache" writes have been removed for brevity. Note that from a "Windows" perspective, the copy finished at 03;58:39.42.

RcloneWindowsLog-BetaRelease1.52.3-297-gaab9aaba-beta

11

Just to clarify, you don't want rclone to return till the file has finished uploading?

I think ncw meant that you will see the same early return behaviour on Linux (similar to Windows) with the latest beta instead of vice-versa on Windows i.e. wait till file has been uploaded (similar to Linux).

12

That is correct. I want the process (copy/write) to finish and return to the O/S AFTER the file has been uploaded. I know this may seem odd but it has to do with one machine "processing a file/blob" (like a WRITE) but then after the process is done, another machine needs to go get that file/blob "immediately". Long story and history as to why but has to do with some legacy software we are using that is not "blob ready". We CAN use File Shares but would rather use Azure Blob due to cost differential (we process hundreds of TB per month).

13

I have not tried the latest Beta version on Linux (and I don't think I will) :slight_smile:

14

I am not sure if that is even currently possible on Windows, atleast not with the vfs-cache-mode set to writes or full.

You can try setting the mode to off or minimal and see if that works. That may break other things, however.

15

Thanks, but it indeed does break other things. We need to use the cache (writes) for performance (this is transcoding of large hi-resolution video). Using Off or Minimal slows performance down over all by a factor of 10 or more.

16

Ah. So the other process looks at the cloud storage directly is that right?

The problem appears to be that the Release call isn't synchronous to the app so it happens after the app has closed the file (which is the Flush). However rclone can't upload the file on the Flush because the OS might not be finished with it - we just don't know.

If you are using --vfs-cache-mode off it should shorten that time to almost nothing but it may not work with your app.

In general you don't want explorer (for example) waiting for the file to be uploaded as it hang everything. In fact explorer does hang (which is one of the reasons for the new delayed write back code) and I'm not sure why yours doesn't hang, it is probably something to do with exactly how the app works.

It might be possible to make some API which knows when the file is uploaded - would that be useful? So you'd call an rclone RC command to check.

17

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