OSX Sierra/High Sierra - Can only copy large files to Cache Mount if nested

blim5001 · May 11, 2018, 6:20am

The settings that work for me are these:

/usr/local/bin/rclone mount gcache: ~/_mounts/gDrive-rclone-cache \
--allow-other \
--dir-cache-time=8h \
--cache-chunk-size=5M \
--cache-info-age=10h \
--cache-workers=8 \
--buffer-size 0M \
--attr-timeout=1s \
--volname=myDrive \
--rc \
--cache-writes \
--vfs-cache-mode writes \
--cache-tmp-upload-path ~/_mounts/_rclone_upload \
--cache-tmp-wait-time 5m \
--cache-db-path /Users/blim/.cache/rcloneCache \
--cache-chunk-path=/Users/blim/.cache/rcloneChunks \
-vv

(I just tried my settings without the --cache-db-path and --cache-chunk-path options and it still worked, so it might be worth trying my settings first and see if they work for you)

The Settings that generate the Error 36 messages when copying are these:

/usr/local/bin/rclone mount gcache: ~/_mounts/gDrive-rclone-cache \
--allow-other \
--dir-cache-time=160h \
--cache-chunk-size=10M \
--cache-info-age=168h \
--cache-workers=5 \
--buffer-size=500M \
--attr-timeout=1s \
--cache-tmp-upload-path ~/_mounts/_rclone_upload \
--cache-tmp-wait-time 60m \
--umask 002 \
--drive-use-trash=false \
-vv

blim5001 · May 11, 2018, 6:44am

I added

--cache-writes \
--vfs-cache-mode writes \

To the second set of settings above and that seemed to work, so you could try adding those to your mount settings.

ncw · May 11, 2018, 8:09am

If not having this is the problem

then there will almost certainly be a matching ERROR log in the rclone log when the finder throws an error.

jrock · May 11, 2018, 9:59am

Thx both, I will test and review logs when I get home.

jrock · May 12, 2018, 3:40am

I can confirm that adding the --vfs-cache-mode writes flag resolves the issue. Thanks @blim5001!

I have not had time to compare the logs with and without the flag, but will do so and revert back.

ncw · May 12, 2018, 9:01am

I suspect you’ll find an ERROR telling you to enable --vfs-cache-mode writes…

jrock · May 12, 2018, 1:28pm

Sadly there is no obvious mention of a vfs-cache-mode error but I have extracted the log section where the two seem to depart.

Without --vfs-cache-mode writes:

2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x2] Write 131072
2018/05/12 20:19:59 DEBUG : fuse: <- Write [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=36124] 0x2 131072 @58589184 fl=0 lock=0 ffl=OpenWriteOnly
2018/05/12 20:19:59 DEBUG : &{video_file.avi (w)}: Write: len=131072, offset=58589184
2018/05/12 20:19:59 DEBUG : &{video_file.avi (w)}: >Write: written=131072, err=<nil>
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x3] Write 131072
2018/05/12 20:19:59 DEBUG : fuse: <- Getattr [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] 0x0 fl=0
2018/05/12 20:19:59 DEBUG : video_file.avi: Attr: 
2018/05/12 20:19:59 DEBUG : video_file.avi: >Attr: a=valid=1s ino=0 size=58720256 mode=-rw-rw-r--, err=<nil>
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x5] Getattr valid=1s ino=6332299928504708810 size=58720256 mode=-rw-rw-r--
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x2 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x2 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x2 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x2 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x2 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x2 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:19:59 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:19:59 DEBUG : fuse: <- Open [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] dir=false fl=OpenReadOnly
2018/05/12 20:19:59 DEBUG : video_file.avi: Open: flags=OpenReadOnly
2018/05/12 20:19:59 DEBUG : video_file.avi: Open: flags=O_RDONLY
2018/05/12 20:20:02 DEBUG : fuse: <- Getattr [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] 0x0 fl=0
2018/05/12 20:20:02 DEBUG : /: Attr: 
2018/05/12 20:20:02 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Getattr valid=1s ino=1 size=0 mode=drwxrwxr-x
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x5
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Read [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] 0x1 838 @0x0 dir=true fl=0 lock=0 ffl=OpenReadOnly
2018/05/12 20:20:02 DEBUG : /: ReadDirAll: 
2018/05/12 20:20:02 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Read 64
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Getattr [ID=0x2 Node=0x2 Uid=501 Gid=20 Pid=291] 0x0 fl=0
2018/05/12 20:20:02 DEBUG : movies/: Attr: 
2018/05/12 20:20:02 DEBUG : movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Getattr valid=1s ino=8190047143392259497 size=0 mode=drwxrwxr-x
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x2 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x2 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x2 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x2 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Getattr [ID=0x3 Node=0x3 Uid=501 Gid=20 Pid=291] 0x0 fl=0
2018/05/12 20:20:02 DEBUG : tv/: Attr: 
2018/05/12 20:20:02 DEBUG : tv/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Getattr valid=1s ino=5891557997223945266 size=0 mode=drwxrwxr-x
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x3 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x3 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x2 Node=0x3 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x3 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Read [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] 0x1 838 @0x40 dir=true fl=0 lock=0 ffl=OpenReadOnly
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Read 0
2018/05/12 20:20:02 DEBUG : fuse: <- Read [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] 0x1 1676 @0x40 dir=true fl=0 lock=0 ffl=OpenReadOnly
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Read 0
2018/05/12 20:20:02 DEBUG : fuse: <- Read [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] 0x1 3353 @0x40 dir=true fl=0 lock=0 ffl=OpenReadOnly
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Read 0
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x5
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Getattr [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291] 0x0 fl=0
2018/05/12 20:20:02 DEBUG : /: Attr: 
2018/05/12 20:20:02 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Getattr valid=1s ino=1 size=0 mode=drwxrwxr-x
2018/05/12 20:20:02 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:20:02 DEBUG : fuse: <- Statfs [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=291]
2018/05/12 20:20:02 DEBUG : : Statfs: 
2018/05/12 20:20:02 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274041239909 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/05/12 20:20:02 DEBUG : fuse: -> [ID=0x2] Statfs blocks=274877906944/274041239909/274877906944 files=1000000000/1000000000 bsize=4096 frsize=4096 namelen=255
2018/05/12 20:20:04 DEBUG : video_file.avi: >Open: fd=<nil *ReadFileHandle>, err=file does not exist
2018/05/12 20:20:04 DEBUG : video_file.avi: >Open: fh=<nil>, err=no such file or directory
2018/05/12 20:20:04 DEBUG : fuse: -> [ID=0x5] Open error=ENOENT
2018/05/12 20:20:04 DEBUG : fuse: <- Lookup [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=291] "video_file.avi"
2018/05/12 20:20:04 DEBUG : /: Lookup: name="video_file.avi"
2018/05/12 20:20:04 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/05/12 20:20:04 DEBUG : fuse: -> [ID=0x3] Lookup error=ENOENT

With --vfs-cache-mode writes:

2018/05/12 20:22:15 DEBUG : fuse: <- Write [ID=0x4 Node=0x5 Uid=501 Gid=20 Pid=36164] 0x2 131072 @192806912 fl=0 lock=0 ffl=OpenWriteOnly
2018/05/12 20:22:15 DEBUG : &{video_file.avi (rw)}: Write: len=131072, offset=192806912
2018/05/12 20:22:15 DEBUG : &{video_file.avi (rw)}: >Write: written=131072, err=<nil>
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x4] Write 131072
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Getattr [ID=0x6 Node=0x5 Uid=501 Gid=20 Pid=291] 0x0 fl=0
2018/05/12 20:22:15 DEBUG : video_file.avi: Attr: 
2018/05/12 20:22:15 DEBUG : video_file.avi: >Attr: a=valid=1s ino=0 size=192937984 mode=-rw-rw-r--, err=<nil>
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x6] Getattr valid=1s ino=6332299928504708810 size=192937984 mode=-rw-rw-r--
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x4 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x4] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x6 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x2
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x6] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x4 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x1
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x4] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x5] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x6 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x0
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x6] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Access [ID=0x3 Node=0x5 Uid=501 Gid=20 Pid=291] mask=0x4
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x3] Access
2018/05/12 20:22:15 DEBUG : fuse: <- Open [ID=0x4 Node=0x5 Uid=501 Gid=20 Pid=291] dir=false fl=OpenReadOnly
2018/05/12 20:22:15 DEBUG : video_file.avi: Open: flags=OpenReadOnly
2018/05/12 20:22:15 DEBUG : video_file.avi: Open: flags=O_RDONLY
2018/05/12 20:22:15 DEBUG : video_file.avi: >Open: fd=video_file.avi (rw), err=<nil>
2018/05/12 20:22:15 DEBUG : video_file.avi: >Open: fh=&{video_file.avi (rw)}, err=<nil>
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x4] Open 0x3 fl=0
2018/05/12 20:22:15 DEBUG : fuse: <- Flush [ID=0x5 Node=0x5 Uid=501 Gid=20 Pid=291] 0x3 fl=0x0 lk=0x0
2018/05/12 20:22:15 DEBUG : &{video_file.avi (rw)}: Flush: 
2018/05/12 20:22:15 DEBUG : &{video_file.avi (rw)}: >Flush: err=<nil>
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x5] Flush
2018/05/12 20:22:15 DEBUG : fuse: <- Release [ID=0x6 Node=0x5 Uid=501 Gid=20 Pid=291] 0x3 fl=OpenReadOnly rfl=0 owner=0x0
2018/05/12 20:22:15 DEBUG : &{video_file.avi (rw)}: Release: 
2018/05/12 20:22:15 DEBUG : video_file.avi(0xc420352600): RWFileHandle.Release closing
2018/05/12 20:22:15 DEBUG : video_file.avi(0xc420352600): close: 
2018/05/12 20:22:15 DEBUG : video_file.avi(0xc420352600): >close: err=<nil>
2018/05/12 20:22:15 DEBUG : &{video_file.avi (rw)}: >Release: err=<nil>
2018/05/12 20:22:15 DEBUG : fuse: -> [ID=0x6] Release

That help?

ncw · May 12, 2018, 4:32pm

Without --vfs-cache writes we get this

Which is something (the finder I suppose) trying to open the file. However I think the file “video_file.avi” is open at that point so isn’t uploaded to cloud storage yet, so can’t be opened.

Whereas with --vfs-cache-mode writes the file is spooled to disk first, so can be opened at any time.

This is exactly the kind of scenario that --vfs-cache-mode writes is for, so I’d say that is an excellent workaround.

jrock · May 12, 2018, 6:52pm

OK, so my limited understanding of the two cache mechanisms is showing here…be gentle

I am wondering why opening from the vfs file cache folder is any different to opening from the --cache-tmp-upload-path in this situation?

Don’t both just respond to open requests with the local file (until it is uploaded)?

Unfortunately I’ve noticed that using --vfs-cache-mode writes:

Does allow copying a large file without the error code 36 (as found by @blim5001)
However if I copy a group of files then the error is back.

So if I try to copy (say) 25 files of (say) 5gb each, somewhere before halfway the error code is back.

I’ll see if there are any new log entries for this.

blim5001 · May 12, 2018, 10:15pm

Bah, I thought we had found the answer

I copied a bunch of files (about 16GB) on Sierra using my mount settings and that worked.

But sadly my High Sierra VM does not have enough space to try it on that and the way I built it will not allow me to easily expand the disk.
I tried with a smaller amount of files and did get the error 36 message towards the end of the copy, but that could of been down to lack of disk space, as it had just about run out of space at the end of the copy

Tried again with just 4 files, so about 8GB and that seemed to work

So probably a stupid question, but do you have plenty of free disk space?

jrock · May 13, 2018, 5:11am

Thx for testing @blim5001. Yes, over a Tb of free space. I suspect you are seeing the same thing as myself on High Sierra as it usually errors out somewhere between 8Gb and 16Gb for me too.

blim5001 · May 13, 2018, 2:52pm

@jrock, so here’s another thing to try

If you go to osxfuse.github.io, there is a developer preview of 3.8 posted on the 7th May

So I thought I would try that. I built a new bigger VM and installed that (must reboot after installing)

Mounted the drive with my usual settings, created a new folder in the root of my drive and tried copying 19 Files into this directory, average file size was just over 1GB, total size 21.34GB

and wait for it… they copied without error

They are currently sitting waiting for the upload to start as I increased my wait time to 120M, as I am backing up some other stuff.

So I would give that a go and see how you get on…

Just to add, this was using the latest beta, so I suggest grabbing that. (I built the one I am using myself, but that should not matter, as it’s the same one I was using yesterday)

jrock · May 13, 2018, 3:50pm

Thanks @blim5001!

I am travelling for the next week and will eagerly test this when I get back!

ncw · May 14, 2018, 9:44am

The --vfs-cache-mode writes cache is very tightly coupled to the the VFS layer and hence to mount. That means that mount can support more things (like reading and writing to the same file at the same time) which rclone backends can’t normally support.

One day we will integrate the cache backend in the same way with the VFS and you won’t need the --vfs-cache-mode flag, but until then it is just another backend so has the same limitations as the other backends.

jrock · July 8, 2018, 6:56am

Just a note to say thx @blim5001 and @ncw for your last replies on this thread and apologies for my radio silence. I haven’t been able to get back to rclone until now. Will finish testing above some time soon and revert back.