not completing cp until upload completes when using vfs-cache

[thinkyfish]

What is your rclone version (output from rclone version)

rclone v1.50.1

• os/arch: linux/amd64
• go version: go1.13.4

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

on Debian Buster 10.1 64Bit

What is the problem you are having with rclone?

I am using rclone as a local fast cache for Dropbox over Samba.
When I upload or locally cp a large file (500MB or more) it transferres at maximum speed to the cache
but waits at 99% until it actually uploads to Dropbox.
I have also tried using a separate cache remote to no avail.

Is there an option like --success-on-cache-write or something I am missing?
I realize this is somewhere between a bug report and a feature request.
The desired behavior would be to finish right after the file is transferred from the source but before the chunk upload.
I don't really have much experience with go but I can try to look at the code.

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

rclone mount \
--allow-other \
--max-read-ahead 14G \
--checkers 16 \
--stats 0 \
--vfs-cache-mode full \
--cache-dir /tmp/dropbox \
dropbox:/ /dropbox/

Here is a test command that I used.

cp ~/OPN.bz2 /dropbox/Marketing/ && date
Thu 07 Nov 2019 03:27:56 PM EST

Here is the output from rclone -vv

2019/11/07 15:26:19 DEBUG : rclone: Version "v1.50.1" starting with parameters ["rclone" "mount" "--allow-other" "--max-read-ahead" "14G" "--acd-templink-threshold" "0" "--checkers" "16" "--stats" "0" "--vfs-cache-mode" "full" "--cache-dir" "/tmp/dropbox" "-vv" "dropbox:/" "/dropbox/"]
2019/11/07 15:26:19 DEBUG : Using config file from "/home/dropbox/.config/rclone/rclone.conf"
2019/11/07 15:26:20 DEBUG : Dropbox root '': Using root namespace "4..elided...2"
2019/11/07 15:26:20 DEBUG : Dropbox root '': Mounting on "/dropbox/"
2019/11/07 15:26:20 INFO  : Dropbox root '': poll-interval is not supported by this remote
2019/11/07 15:26:20 DEBUG : vfs cache root is "/tmp/dropbox/vfs/dropbox"
2019/11/07 15:26:20 DEBUG : Adding path "vfs/forget" to remote control registry
2019/11/07 15:26:20 DEBUG : Adding path "vfs/refresh" to remote control registry
2019/11/07 15:26:20 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2019/11/07 15:26:20 DEBUG : Marketing/openmediavault_5.0.5-amd64.iso: updateTime: setting atime to 2019-11-07 15:17:11.259656844 -0500 EST
2019/11/07 15:26:20 INFO  : Cleaned the cache: objects 3 (was 0), total size 551M (was 0)
2019/11/07 15:26:20 DEBUG : : Root: 
2019/11/07 15:26:20 DEBUG : : >Root: node=/, err=<nil>
2019/11/07 15:26:22 DEBUG : /: Attr: 
2019/11/07 15:26:22 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2019/11/07 15:26:22 DEBUG : /: ReadDirAll: 
2019/11/07 15:26:23 DEBUG : /: >ReadDirAll: item=22, err=<nil>
2019/11/07 15:26:30 DEBUG : /: Attr: 
2019/11/07 15:26:30 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2019/11/07 15:26:30 DEBUG : /: Lookup: name="Marketing"
2019/11/07 15:26:30 DEBUG : /: >Lookup: node=Marketing/, err=<nil>
2019/11/07 15:26:30 DEBUG : Marketing/: Attr: 
2019/11/07 15:26:30 DEBUG : Marketing/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2019/11/07 15:26:36 DEBUG : Marketing/: Attr: 
2019/11/07 15:26:36 DEBUG : Marketing/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2019/11/07 15:26:36 DEBUG : Marketing/: Lookup: name="OPN.bz2"
2019/11/07 15:26:37 DEBUG : Marketing/: >Lookup: node=<nil>, err=no such file or directory
2019/11/07 15:26:37 DEBUG : Marketing/: Lookup: name="OPN.bz2"
2019/11/07 15:26:37 DEBUG : Marketing/: >Lookup: node=<nil>, err=no such file or directory
2019/11/07 15:26:37 DEBUG : Marketing/: Create: name="OPN.bz2"
2019/11/07 15:26:37 DEBUG : Marketing/OPN.bz2: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2019/11/07 15:26:37 DEBUG : Marketing/OPN.bz2(0xc000656000): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL
2019/11/07 15:26:37 DEBUG : Marketing/OPN.bz2: >Open: fd=Marketing/OPN.bz2 (rw), err=<nil>
2019/11/07 15:26:37 DEBUG : Marketing/: >Create: node=Marketing/OPN.bz2, handle=&{Marketing/OPN.bz2 (rw)}, err=<nil>
2019/11/07 15:26:37 DEBUG : Marketing/OPN.bz2: Attr: 
2019/11/07 15:26:37 DEBUG : Marketing/OPN.bz2: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2019/11/07 15:26:37 DEBUG : &{Marketing/OPN.bz2 (rw)}: Write: len=131072, offset=0
2019/11/07 15:26:37 DEBUG : &{Marketing/OPN.bz2 (rw)}: >Write: written=131072, err=<nil>
... Lots of writes ...
2019/11/07 15:26:39 DEBUG : &{Marketing/OPN.bz2 (rw)}: Write: len=131072, offset=307232768
2019/11/07 15:26:39 DEBUG : &{Marketing/OPN.bz2 (rw)}: >Write: written=131072, err=<nil>
2019/11/07 15:26:39 DEBUG : &{Marketing/OPN.bz2 (rw)}: Write: len=44004, offset=307363840
2019/11/07 15:26:39 DEBUG : &{Marketing/OPN.bz2 (rw)}: >Write: written=44004, err=<nil>
2019/11/07 15:26:39 DEBUG : &{Marketing/OPN.bz2 (rw)}: Flush: 
2019/11/07 15:26:39 DEBUG : Marketing/OPN.bz2: Need to transfer - File not found at Destination
2019/11/07 15:26:39 DEBUG : Marketing/OPN.bz2: Uploading chunk 1/7
2019/11/07 15:26:52 DEBUG : Marketing/OPN.bz2: Uploading chunk 2/7
2019/11/07 15:27:04 DEBUG : Marketing/OPN.bz2: Uploading chunk 3/7
2019/11/07 15:27:17 DEBUG : Marketing/OPN.bz2: Uploading chunk 4/7
2019/11/07 15:27:20 DEBUG : Marketing/OPN.bz2: updateTime: setting atime to 2019-11-07 15:26:39.112641227 -0500 EST
2019/11/07 15:27:20 INFO  : Cleaned the cache: objects 4 (was 4), total size 844.167M (was 551M)
2019/11/07 15:27:29 DEBUG : Marketing/OPN.bz2: Uploading chunk 5/7
2019/11/07 15:27:41 DEBUG : Marketing/OPN.bz2: Uploading chunk 6/7
2019/11/07 15:27:53 DEBUG : Marketing/OPN.bz2: Uploading chunk 7/7
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2: DropboxHash = 9563...elided...a89d OK
2019/11/07 15:27:56 INFO  : Marketing/OPN.bz2: Copied (new)
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2: transferred to remote
2019/11/07 15:27:56 DEBUG : &{Marketing/OPN.bz2 (rw)}: >Flush: err=<nil>
2019/11/07 15:27:56 DEBUG : &{Marketing/OPN.bz2 (rw)}: Release: 
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2(0xc000656000): RWFileHandle.Release closing
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2(0xc000656000): close: 
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2: File.delWriter couldn't find handle
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2: Size and modification time the same (differ by -104.641103ms, within tolerance 1s)
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2: Unchanged skipping
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2: transferred to remote
2019/11/07 15:27:56 DEBUG : Marketing/OPN.bz2(0xc000656000): >close: err=<nil>
2019/11/07 15:27:56 DEBUG : &{Marketing/OPN.bz2 (rw)}: >Release: err=<nil>
2019/11/07 15:27:56 DEBUG : Marketing/: Attr: 
2019/11/07 15:27:56 DEBUG : Marketing/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2019/11/07 15:28:04 DEBUG : cache cleaner exiting

The cp returns at about 15:27:56 rather than at 15:26:39 as expected.

[ncw]

This is actually covered by #3186 I think which I'm hoping to do for 1.51

[Animosity022]

@thinkyfish - is this good to close out as it's going to be covered in the other issue?

[Animosity022]

This should be addressed by the other issue so closing this one out so we can follow the other as the question is answered.