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