Extracting to ACD mount possible?

[B4dM4n (Fabian Möller)]

I probably found the cause for this data loss and created a new issue on Github to track the progress.

Issue: rclone mount: race condition with multiple RWFileHandle's

[neik]

Thanks guys for putting such an effort in fixing bugs and improving rclone!

I am pretty sure a lot of people - including me - really appreciate it!

€dit:

A simpler approach could be to use the JD integrated extractor and move the extracted files to a rclone mount afterwards.

With this approach I do not get empty files anymore. The upload seems to be slower though.

[B4dM4n (Fabian Möller)]

With this approach I do not get empty files anymore. The upload seems to be slower though.

That’s good to hear.

The fix should also be released soon. It’s finished but needs to be reviewed, because it’s a large change to the mount system.

[neik]

The fix should also be released soon. It’s finished but needs to be reviewed, because it’s a large change to the mount system.

Yeah, I saw that on github, will be glad to test it.
Thanks for the effort you put in it, really appreciate it!

[neik]

@B4dM4n, just saw on github that your fix was merged. Gave it a try and the issue apparently is fixed.
However, I noticed something else. The time between upload and cache cleaning is about one hour.
Is this intended?

[B4dM4n (Fabian Möller)]

Good to hear that it’s working now.

The delay between upload and cleaning should be determined by the --vfs-cache-poll-interval flag. Unless the file is used shortly after the upload. When the file is still in the cache and opened again, the cache file is reused.

I did not see this behavior until now, but I will observe it.

Do you have a log when the delay happens?

[neik]

Thanks! Will have a look at that flag tomorrow.

No, unfortunately I do not have a log. Will try to create one and post it over here.

Thanks mate!

€dit: @B4dM4n, here is the log. I uploaded three files (big, medium, small).

2018/02/20 11:41:11 DEBUG : Using config file from “/root/.config/rclone/rclone.conf”
2018/02/20 11:41:11 DEBUG : rclone: Version “v1.39-155-g62e72801β” starting with parameters [“rclone_beta” “mount” “–log-level” “DEBUG” “–log-file” “/tmp/log.txt” “–allow-non-empty” “–allow-other” “–buffer-size” “32M” “–dir-cache-time” “300h” “–poll-interval” “8h” “–vfs-cache-mode” “writes” “–vfs-cache-max-age” “10m” “upload:” “/media/cry”]
2018/02/20 11:41:11 INFO : Encrypted drive ‘upload:’: Modify window is 1ms
2018/02/20 11:41:11 DEBUG : Encrypted drive ‘upload:’: Mounting on “/media/cry”
2018/02/20 11:41:11 DEBUG : vfs cache root is “/root/.cache/rclone/vfs/upload”
2018/02/20 11:41:11 DEBUG : : Root:
2018/02/20 11:41:11 DEBUG : : >Root: node=/, err=
2018/02/20 11:41:12 DEBUG : Google drive root ‘’: Checking for changes on remote
2018/02/20 11:41:12 DEBUG : Google drive root ‘’: All changes were processed. Waiting for more.

Upload starts

2018/02/20 12:12:10 DEBUG : /: Lookup: name=“upload”
2018/02/20 12:12:10 DEBUG : /: >Lookup: node=upload/, err=
2018/02/20 12:12:10 DEBUG : upload/: Attr:
2018/02/20 12:12:10 DEBUG : upload/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/02/20 12:12:10 DEBUG : /: Lookup: name=“upload”
2018/02/20 12:12:10 DEBUG : /: >Lookup: node=upload/, err=
2018/02/20 12:12:10 DEBUG : upload/: Attr:
2018/02/20 12:12:10 DEBUG : upload/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/02/20 12:12:10 DEBUG : /: Attr:
2018/02/20 12:12:10 DEBUG : /: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/02/20 12:12:10 DEBUG : : Statfs:
2018/02/20 12:12:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Lookup: name=“test”
2018/02/20 12:12:10 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:10 DEBUG : upload/: Mkdir: name=“test”
2018/02/20 12:12:11 DEBUG : upload/: >Mkdir: node=upload/test/, err=
2018/02/20 12:12:11 DEBUG : upload/test/: Attr:
2018/02/20 12:12:11 DEBUG : upload/test/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/02/20 12:12:11 DEBUG : upload/test/: Lookup: name=“a”
2018/02/20 12:12:11 DEBUG : upload/test/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:11 DEBUG : upload/test/: Mkdir: name=“a”
2018/02/20 12:12:12 DEBUG : upload/test/: >Mkdir: node=upload/test/a/, err=
2018/02/20 12:12:12 DEBUG : upload/test/a/: Attr:
2018/02/20 12:12:12 DEBUG : upload/test/a/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/02/20 12:12:12 DEBUG : upload/test/a/: Lookup: name=“test.pdf”
2018/02/20 12:12:12 DEBUG : upload/test/a/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:12 DEBUG : upload/test/a/: Create: name=“test.pdf”
2018/02/20 12:12:12 DEBUG : upload/test/a/test.pdf: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/02/20 12:12:12 DEBUG : upload/test/a/test.pdf(0xc420124380): Opening cached copy with flags=O_RDWR|O_CREATE|O_EXCL
2018/02/20 12:12:12 DEBUG : upload/test/a/test.pdf: >Open: fd=upload/test/a/test.pdf (rw), err=
2018/02/20 12:12:12 DEBUG : upload/test/a/: >Create: node=upload/test/a/test.pdf, handle=&{upload/test/a/test.pdf (rw)}, err=
2018/02/20 12:12:12 DEBUG : upload/test/a/test.pdf: Attr:
2018/02/20 12:12:12 DEBUG : upload/test/a/test.pdf: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-r–r--, err=
2018/02/20 12:12:12 DEBUG : &{upload/test/a/test.pdf (rw)}: Flush:
2018/02/20 12:12:12 DEBUG : upload/test/a/test.pdf(0xc420124380): close:
2018/02/20 12:12:12 DEBUG : upload/test/a/test.pdf: Couldn’t find file - need to transfer
2018/02/20 12:12:13 INFO : upload/test/a/test.pdf: Copied (new)
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf: transferred to remote
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf(0xc420124380): >close: err=
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: >Flush: err=
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: Release:
2018/02/20 12:12:14 DEBUG : upload/test/a/: Remove: name=“test.pdf”
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf(0xc420124380): RWFileHandle.Release nothing to do
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: >Release: err=
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf: Removed from cache
2018/02/20 12:12:14 DEBUG : upload/test/a/: >Remove: err=
2018/02/20 12:12:14 DEBUG : upload/test/a/: Lookup: name=“test.pdf”
2018/02/20 12:12:14 DEBUG : upload/test/a/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:14 DEBUG : upload/test/a/: Create: name=“test.pdf”
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf: Open: flags=O_RDWR|O_CREATE
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf(0xc4212bc540): Opening cached copy with flags=O_RDWR|O_CREATE
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf: >Open: fd=upload/test/a/test.pdf (rw), err=
2018/02/20 12:12:14 DEBUG : upload/test/a/: >Create: node=upload/test/a/test.pdf, handle=&{upload/test/a/test.pdf (rw)}, err=
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf: Attr:
2018/02/20 12:12:14 DEBUG : upload/test/a/test.pdf: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-r–r--, err=
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: Write: len=131072, offset=0
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: Write: len=131072, offset=131072
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: Write: len=131072, offset=262144
2018/02/20 12:12:14 DEBUG : &{upload/test/a/test.pdf (rw)}: >Write: written=131072, err=

…many writes…

2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: Write: len=131072, offset=39976960
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: Write: len=131072, offset=40108032
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: Write: len=131072, offset=40239104
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: Write: len=28603, offset=40370176
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: >Write: written=28603, err=
2018/02/20 12:12:15 DEBUG : upload/test/a/test.pdf: Fsync:
2018/02/20 12:12:15 DEBUG : upload/test/a/test.pdf: >Fsync: err=
2018/02/20 12:12:15 DEBUG : &{upload/test/a/test.pdf (rw)}: Flush:
2018/02/20 12:12:15 DEBUG : upload/test/a/test.pdf(0xc4212bc540): close:
2018/02/20 12:12:15 DEBUG : upload/test/a/test.pdf: Couldn’t find file - need to transfer
2018/02/20 12:12:15 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/19gfhndp002pnu9m03klro0pb4/qfrtaf0stj3ehv9dqs6pj23j3ud9vg439k24klq45c85d9rme367o1qanoo355gr5f0vb4tgoen5pup2nius7sbr1jpgt7hlhalcmupj1qgbt8r7i58k1mpjrnunsh7h: Sending chunk 0 length 8388608
2018/02/20 12:12:16 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/19gfhndp002pnu9m03klro0pb4/qfrtaf0stj3ehv9dqs6pj23j3ud9vg439k24klq45c85d9rme367o1qanoo355gr5f0vb4tgoen5pup2nius7sbr1jpgt7hlhalcmupj1qgbt8r7i58k1mpjrnunsh7h: Sending chunk 8388608 length 8388608
2018/02/20 12:12:16 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/19gfhndp002pnu9m03klro0pb4/qfrtaf0stj3ehv9dqs6pj23j3ud9vg439k24klq45c85d9rme367o1qanoo355gr5f0vb4tgoen5pup2nius7sbr1jpgt7hlhalcmupj1qgbt8r7i58k1mpjrnunsh7h: Sending chunk 16777216 length 8388608
2018/02/20 12:12:17 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/19gfhndp002pnu9m03klro0pb4/qfrtaf0stj3ehv9dqs6pj23j3ud9vg439k24klq45c85d9rme367o1qanoo355gr5f0vb4tgoen5pup2nius7sbr1jpgt7hlhalcmupj1qgbt8r7i58k1mpjrnunsh7h: Sending chunk 25165824 length 8388608
2018/02/20 12:12:17 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/19gfhndp002pnu9m03klro0pb4/qfrtaf0stj3ehv9dqs6pj23j3ud9vg439k24klq45c85d9rme367o1qanoo355gr5f0vb4tgoen5pup2nius7sbr1jpgt7hlhalcmupj1qgbt8r7i58k1mpjrnunsh7h: Sending chunk 33554432 length 6854251
2018/02/20 12:12:18 INFO : upload/test/a/test.pdf: Copied (new)
2018/02/20 12:12:18 DEBUG : upload/test/a/test.pdf: transferred to remote
2018/02/20 12:12:18 DEBUG : upload/test/a/test.pdf(0xc4212bc540): >close: err=
2018/02/20 12:12:18 DEBUG : &{upload/test/a/test.pdf (rw)}: >Flush: err=
2018/02/20 12:12:18 DEBUG : &{upload/test/a/test.pdf (rw)}: Release:
2018/02/20 12:12:18 DEBUG : upload/test/a/test.pdf(0xc4212bc540): RWFileHandle.Release nothing to do
2018/02/20 12:12:18 DEBUG : &{upload/test/a/test.pdf (rw)}: >Release: err=
2018/02/20 12:12:18 DEBUG : upload/test/a/test.pdf: Attr:
2018/02/20 12:12:18 DEBUG : upload/test/a/test.pdf: >Attr: a=valid=1m0s ino=0 size=40398779 mode=-rw-r–r--, err=
2018/02/20 12:12:18 DEBUG : upload/test/a/test.pdf: Setattr: a=Setattr [ID=0x1703f Node=0x6 Uid=0 Gid=0 Pid=21985] atime=2018-02-20 12:12:15 +0100 CET mtime=2018-02-20 07:13:54.591 +0100 CET handle=INVALID-0x0
2018/02/20 12:12:19 DEBUG : upload/test/a/test.pdf: File.applyPendingModTime OK
2018/02/20 12:12:19 DEBUG : upload/test/a/test.pdf: >Setattr: err=
2018/02/20 12:12:19 DEBUG : upload/test/a/test.pdf: Attr:
2018/02/20 12:12:19 DEBUG : upload/test/a/test.pdf: >Attr: a=valid=1m0s ino=0 size=40398779 mode=-rw-r–r--, err=
2018/02/20 12:12:19 DEBUG : upload/test/: Lookup: name=“test1.pdf”
2018/02/20 12:12:19 DEBUG : upload/test/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:19 DEBUG : upload/test/: Attr:
2018/02/20 12:12:19 DEBUG : upload/test/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/02/20 12:12:19 DEBUG : upload/test/: Lookup: name=“test1.pdf”
2018/02/20 12:12:19 DEBUG : upload/test/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:19 DEBUG : upload/test/: Create: name=“test1.pdf”
2018/02/20 12:12:19 DEBUG : upload/test/test1.pdf: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/02/20 12:12:19 DEBUG : upload/test/test1.pdf(0xc4202261c0): Opening cached copy with flags=O_RDWR|O_CREATE|O_EXCL
2018/02/20 12:12:19 DEBUG : upload/test/test1.pdf: >Open: fd=upload/test/test1.pdf (rw), err=
2018/02/20 12:12:19 DEBUG : upload/test/: >Create: node=upload/test/test1.pdf, handle=&{upload/test/test1.pdf (rw)}, err=
2018/02/20 12:12:19 DEBUG : upload/test/test1.pdf: Attr:
2018/02/20 12:12:19 DEBUG : upload/test/test1.pdf: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-r–r--, err=
2018/02/20 12:12:19 DEBUG : &{upload/test/test1.pdf (rw)}: Flush:
2018/02/20 12:12:19 DEBUG : upload/test/test1.pdf(0xc4202261c0): close:
2018/02/20 12:12:19 DEBUG : upload/test/test1.pdf: Couldn’t find file - need to transfer
2018/02/20 12:12:20 INFO : upload/test/test1.pdf: Copied (new)
2018/02/20 12:12:20 DEBUG : upload/test/test1.pdf: transferred to remote
2018/02/20 12:12:20 DEBUG : upload/test/test1.pdf(0xc4202261c0): >close: err=
2018/02/20 12:12:20 DEBUG : &{upload/test/test1.pdf (rw)}: >Flush: err=
2018/02/20 12:12:20 DEBUG : &{upload/test/test1.pdf (rw)}: Release:
2018/02/20 12:12:20 DEBUG : upload/test/test1.pdf(0xc4202261c0): RWFileHandle.Release nothing to do
2018/02/20 12:12:20 DEBUG : &{upload/test/test1.pdf (rw)}: >Release: err=
2018/02/20 12:12:20 DEBUG : upload/test/: Remove: name=“test1.pdf”
2018/02/20 12:12:21 DEBUG : upload/test/test1.pdf: Removed from cache
2018/02/20 12:12:21 DEBUG : upload/test/: >Remove: err=
2018/02/20 12:12:21 DEBUG : upload/test/: Lookup: name=“test1.pdf”
2018/02/20 12:12:21 DEBUG : upload/test/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:21 DEBUG : upload/test/: Create: name=“test1.pdf”
2018/02/20 12:12:21 DEBUG : upload/test/test1.pdf: Open: flags=O_RDWR|O_CREATE
2018/02/20 12:12:21 DEBUG : upload/test/test1.pdf(0xc4201241c0): Opening cached copy with flags=O_RDWR|O_CREATE
2018/02/20 12:12:21 DEBUG : upload/test/test1.pdf: >Open: fd=upload/test/test1.pdf (rw), err=
2018/02/20 12:12:21 DEBUG : upload/test/: >Create: node=upload/test/test1.pdf, handle=&{upload/test/test1.pdf (rw)}, err=
2018/02/20 12:12:21 DEBUG : upload/test/test1.pdf: Attr:
2018/02/20 12:12:21 DEBUG : upload/test/test1.pdf: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-r–r--, err=
2018/02/20 12:12:21 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=131072, offset=0
2018/02/20 12:12:21 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:21 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=131072, offset=131072
2018/02/20 12:12:21 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:21 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=131072, offset=262144
2018/02/20 12:12:21 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=131072, err=

…many writes; here the chunk size starts to vary. This already happened before your fix. Don’t know if it is relevant anyway…

2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=131072, offset=109707264
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=131072, offset=109838336
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=24618, offset=109969408
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=24618, err=
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=131030, offset=109994026
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=131030, err=
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=42, offset=110125056
2018/02/20 12:12:23 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=42, err=

…many writes…

2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=434, offset=427425792
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=434, err=
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=130638, offset=427426226
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=130638, err=
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=131072, offset=427556864
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=131072, err=
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: Write: len=104411, offset=427687936
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: >Write: written=104411, err=
2018/02/20 12:12:28 DEBUG : upload/test/test1.pdf: Fsync:
2018/02/20 12:12:28 DEBUG : upload/test/test1.pdf: >Fsync: err=
2018/02/20 12:12:28 DEBUG : &{upload/test/test1.pdf (rw)}: Flush:
2018/02/20 12:12:28 DEBUG : upload/test/test1.pdf(0xc4201241c0): close:
2018/02/20 12:12:29 DEBUG : upload/test/test1.pdf: Couldn’t find file - need to transfer
2018/02/20 12:12:29 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 0 length 8388608
2018/02/20 12:12:29 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 8388608 length 8388608
2018/02/20 12:12:30 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 16777216 length 8388608
2018/02/20 12:12:30 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 25165824 length 8388608
2018/02/20 12:12:30 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 33554432 length 8388608
2018/02/20 12:12:31 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 41943040 length 8388608
2018/02/20 12:12:31 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 50331648 length 8388608

…many sending…

2018/02/20 12:12:45 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 402653184 length 8388608
2018/02/20 12:12:45 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 411041792 length 8388608
2018/02/20 12:12:45 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 419430400 length 8388608
2018/02/20 12:12:46 DEBUG : kk20jpvdcq51cmjdih2ov07qsg/56jdmvav4dbddv0jflid6nmf1j977n6jfr2vorqa8hubion2nfskla0680di63sf0mvl8n9u202tn6d5t9hh90hsdk732bmdnbiruqo/ek78ls1nqbi50qcpk7k6edqai2o0s3ter4mvvr1l3th3dee3odh945dbja0op4qgefli849um8ldkgaqrc94fbaoce39314gc8d5ad8: Sending chunk 427819008 length 77819
2018/02/20 12:12:47 INFO : upload/test/test1.pdf: Copied (new)
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: transferred to remote
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf(0xc4201241c0): >close: err=
2018/02/20 12:12:47 DEBUG : &{upload/test/test1.pdf (rw)}: >Flush: err=
2018/02/20 12:12:47 DEBUG : &{upload/test/test1.pdf (rw)}: Release:
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf(0xc4201241c0): RWFileHandle.Release nothing to do
2018/02/20 12:12:47 DEBUG : &{upload/test/test1.pdf (rw)}: >Release: err=
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: Attr:
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: >Attr: a=valid=1m0s ino=0 size=427792347 mode=-rw-r–r--, err=
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: Setattr: a=Setattr [ID=0x18828 Node=0xe Uid=0 Gid=0 Pid=21985] atime=2018-02-20 12:12:28 +0100 CET mtime=2018-02-19 21:30:29.074 +0100 CET handle=INVALID-0x0
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: File.applyPendingModTime OK
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: >Setattr: err=
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: Attr:
2018/02/20 12:12:47 DEBUG : upload/test/test1.pdf: >Attr: a=valid=1m0s ino=0 size=427792347 mode=-rw-r–r--, err=
2018/02/20 12:12:47 DEBUG : upload/test/: Lookup: name=“test2.pdf”
2018/02/20 12:12:47 DEBUG : upload/test/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:47 DEBUG : upload/test/: Attr:
2018/02/20 12:12:47 DEBUG : upload/test/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/02/20 12:12:47 DEBUG : upload/test/: Lookup: name=“test2.pdf”
2018/02/20 12:12:47 DEBUG : upload/test/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:47 DEBUG : upload/test/: Create: name=“test2.pdf”
2018/02/20 12:12:47 DEBUG : upload/test/test2.pdf: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/02/20 12:12:47 DEBUG : upload/test/test2.pdf(0xc4201c63f0): Opening cached copy with flags=O_RDWR|O_CREATE|O_EXCL
2018/02/20 12:12:47 DEBUG : upload/test/test2.pdf: >Open: fd=upload/test/test2.pdf (rw), err=
2018/02/20 12:12:47 DEBUG : upload/test/: >Create: node=upload/test/test2.pdf, handle=&{upload/test/test2.pdf (rw)}, err=
2018/02/20 12:12:47 DEBUG : upload/test/test2.pdf: Attr:
2018/02/20 12:12:47 DEBUG : upload/test/test2.pdf: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-r–r--, err=
2018/02/20 12:12:47 DEBUG : &{upload/test/test2.pdf (rw)}: Flush:
2018/02/20 12:12:47 DEBUG : upload/test/test2.pdf(0xc4201c63f0): close:
2018/02/20 12:12:48 DEBUG : upload/test/test2.pdf: Couldn’t find file - need to transfer
2018/02/20 12:12:49 INFO : upload/test/test2.pdf: Copied (new)
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: transferred to remote
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf(0xc4201c63f0): >close: err=
2018/02/20 12:12:49 DEBUG : &{upload/test/test2.pdf (rw)}: >Flush: err=
2018/02/20 12:12:49 DEBUG : &{upload/test/test2.pdf (rw)}: Release:
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf(0xc4201c63f0): RWFileHandle.Release nothing to do
2018/02/20 12:12:49 DEBUG : &{upload/test/test2.pdf (rw)}: >Release: err=
2018/02/20 12:12:49 DEBUG : upload/test/: Remove: name=“test2.pdf”
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: Removed from cache
2018/02/20 12:12:49 DEBUG : upload/test/: >Remove: err=
2018/02/20 12:12:49 DEBUG : upload/test/: Lookup: name=“test2.pdf”
2018/02/20 12:12:49 DEBUG : upload/test/: >Lookup: node=, err=no such file or directory
2018/02/20 12:12:49 DEBUG : upload/test/: Create: name=“test2.pdf”
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: Open: flags=O_RDWR|O_CREATE
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf(0xc4201907e0): Opening cached copy with flags=O_RDWR|O_CREATE
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: >Open: fd=upload/test/test2.pdf (rw), err=
2018/02/20 12:12:49 DEBUG : upload/test/: >Create: node=upload/test/test2.pdf, handle=&{upload/test/test2.pdf (rw)}, err=
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: Attr:
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-r–r--, err=
2018/02/20 12:12:49 DEBUG : &{upload/test/test2.pdf (rw)}: Write: len=4345, offset=0
2018/02/20 12:12:49 DEBUG : &{upload/test/test2.pdf (rw)}: >Write: written=4345, err=
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: Fsync:
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf: >Fsync: err=
2018/02/20 12:12:49 DEBUG : &{upload/test/test2.pdf (rw)}: Flush:
2018/02/20 12:12:49 DEBUG : upload/test/test2.pdf(0xc4201907e0): close:
2018/02/20 12:12:50 DEBUG : upload/test/test2.pdf: Couldn’t find file - need to transfer
2018/02/20 12:12:51 INFO : upload/test/test2.pdf: Copied (new)
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: transferred to remote
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf(0xc4201907e0): >close: err=
2018/02/20 12:12:51 DEBUG : &{upload/test/test2.pdf (rw)}: >Flush: err=
2018/02/20 12:12:51 DEBUG : &{upload/test/test2.pdf (rw)}: Release:
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf(0xc4201907e0): RWFileHandle.Release nothing to do
2018/02/20 12:12:51 DEBUG : &{upload/test/test2.pdf (rw)}: >Release: err=
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: Attr:
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: >Attr: a=valid=1m0s ino=0 size=4345 mode=-rw-r–r--, err=
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: Setattr: a=Setattr [ID=0x18839 Node=0xf Uid=0 Gid=0 Pid=21985] atime=2018-02-20 12:12:49 +0100 CET mtime=2018-02-20 07:13:53.71 +0100 CET handle=INVALID-0x0
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: File.applyPendingModTime OK
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: >Setattr: err=
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: Attr:
2018/02/20 12:12:51 DEBUG : upload/test/test2.pdf: >Attr: a=valid=1m0s ino=0 size=4345 mode=-rw-r–r--, err=
2018/02/20 12:13:11 DEBUG : Cleaning the cache
2018/02/20 12:14:11 DEBUG : Cleaning the cache
2018/02/20 12:15:11 DEBUG : Cleaning the cache
2018/02/20 12:16:11 DEBUG : Cleaning the cache
2018/02/20 12:17:11 DEBUG : Cleaning the cache
2018/02/20 12:18:11 DEBUG : Cleaning the cache

these cache cleaning seem to be the poll-interval of the vfs (default 1min)

2018/02/20 12:19:11 DEBUG : Cleaning the cache
2018/02/20 12:20:11 DEBUG : Cleaning the cache
2018/02/20 12:21:11 DEBUG : Cleaning the cache
2018/02/20 12:22:11 DEBUG : Cleaning the cache
2018/02/20 12:23:11 DEBUG : Cleaning the cache
2018/02/20 12:23:11 DEBUG : upload/test/test2.pdf: Removed from cache
2018/02/20 12:23:11 DEBUG : upload/test/a/test.pdf: Removed from cache
2018/02/20 12:23:11 DEBUG : upload/test/test1.pdf: Removed from cache
2018/02/20 12:23:11 DEBUG : upload/test/a: Removed empty directory
2018/02/20 12:23:11 DEBUG : upload/test: Removed empty directory
2018/02/20 12:23:11 DEBUG : upload: Removed empty directory
2018/02/20 12:23:11 DEBUG : : Removed empty directory

After this log I actually think it is the --vfs-cache-max flag that is doing this. Yesterday with the default value the files were deleted after one hour. Now I set the flag to 10min and the files are being deleted after 10min.
It seems to work correctly. Can it be set to 0min so that it won’t cache the file after the upload?

€dit: FYI… Setting --vfs-cache-max to 0min the files will be deleted immediately after the upload.
Once again: Big thanks for the fix!

[Dual-O (Oli)]

my default mount is

rclone mount GD: /mount --allow-non-empty --allow-other --buffer-size 256M --cache-db-purge --cache-info-age=6h --cache-workers=10 --cache-chunk-size=8M --cache-total-chunk-size=10G

but when I unrar to this crypt/cache mount I got 0 byte Files.
can you help me to find the solution?

rclone v1.39 (no beta)

[ncw (Nick Craig-Wood)]

can you help me to find the solution?

Try the latest beta and if it doesn’t work then please open a new topic - thanks!

[Dual-O (Oli)]

do I need https://rclone.org/cache/#cache-writes?

[ncw (Nick Craig-Wood)]

do I need https://rclone.org/cache/#cache-writes?

You probably need --vfs-cache-mode writes I’d say…

[neik]

The latest stable (1.39) doesn’t have the fix yet, it was implemented after that release.

From my experience you can actually either use --cache-writes or --vfs-cache-mode writes. Both worked for me.

[Dual-O (Oli)]

my cache mount:
rclone mount GD1_mount: /mount --allow-non-empty --allow-other --buffer-size 256M --cache-db-purge --cache-info-age=6h --cache-workers=10 --cache-chunk-size=8M --cache-total-chunk-size=10G --cache-writes

is not working.
any suggestions?

[neik]

And you are using the latest beta?
What is the output of rclone version?

[Dual-O (Oli)]

rclone v1.39-246-g078d705dβ

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

[neik]

Well, I am running…

rclone v1.39-155-g62e72801β

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

…and haven’t had any issue since it has been fixed.
You might want to try this one.

€dit: While trying the latest 1.40 I gave cache another try and ended up with the same problem like @Dual-O.
@B4dM4n, do have any hint? Can we iron that out?