--vfs-cache-mode >= writes all of a sudden


#1

I’ve been using this config for the past 4 months without issue. Emby streams fine from it, and I was able to use it to write recorded TV shows to.

/usr/bin/rclone mount --rc --config /root/.config/rclone/rclone.conf --use-mmap --buffer-size=0M --drive-chunk-size=128M --write-back-cache --allow-other --dir-cache-time=24h --cache-chunk-size=32M --cache-chunk-total-size=50G --cache-info-age=48h --umask=002 --cache-workers=8 --attr-timeout=1s --daemon-timeout=10m --cache-tmp-upload-path /home/rclone/rclone_data/rclone_upload --cache-chunk-path /home/rclone/rclone_data/cache_dir/cache-backend --cache-db-path /home/rclone/rclone_data/cache_dir/cache-backend --cache-dir /home/rclone/rclone_data/cache_dir --cache-tmp-wait-time=75m --syslog --log-level INFO gcrypt: /mnt/media

I use emby to DVR shows to a local directory then use a bash shell script to convert to mkv and remove the commercials, then move it to a /Shows folder on my gdrive. This has worked without issue…until March 10th.

I started seeing these in the log - in fact, this is the first occurence:
Mar 10 20:01:20 optiplex rclone[4923]: Shows/The Circus Inside the Wildest Political Show on Earth (2016)/Season 4/The Circus Inside the Wildest Political Show on Earth S04E07 To the Left
.ts: WriteFileHandle.Write: can’t seek in file without --vfs-cache-mode >= writes

server has been up for 14 days and the rclone process has been running that long too. For fun I cleared the cache (stopped rclone, cleared the dir, restarted and did a kill -HUP), and it is still occuring:

Mar 13 21:42:42 optiplex rclone[4865]: Shows/Modern Family (2009)/Season 10/Modern Family S10E17 The Wild.mkv: WriteFileHandle.Write: can’t seek in file without --vfs-cache-mode >= writes

So, uh, any ideas? I’m at a loss.

John


#2

You should run it in DEBUG mode so you can see how the file is opening.

What else changed? Did you upgrade Emby?


#3

No emby upgrade. No OS updates either. I do those at the end of the month.

Here’s the weird thing - earlier this week I was setting up my mount on a Raspberry PI to put it to dedicated Sonarr use. I copied my config exactly as it was on my media server and I got the same VFS write error on PI. I thought maybe it was due to the arch difference and went with a VFS mount on that instead - which, btw now works great with sonarr.

I just swapped the media center over to VFS - I may test later this week with the cache backend and gather some debug logs then.


#4

So, I may have found what is causing the issue, though I haven’t had time to verify. I enabled bbr congestion control on 3/10, which is the day the issues cropped up.

John


#5

I wouldn’t think that would cause it to but who knows.

Can you grab a debug log so you can see what’s opening up the file and the mode?


#6

Working on the debug logs now.

I know what’s opening the file, though - a simple mv command.

John


#7

A ‘mv’ command shouldn’t trigger a seek though so that would be odd.


#8

Here’s part of the debug log. I tried moving an empty 1G file (fallocate -l 1G) to /mnt/media/test/. It failed with an input/output error.

Kernel 4.14.98

2019/03/14 12:02:53 DEBUG : rclone: Version “v1.46” starting with parameters ["/usr/bin/rclone" “mount” “–rc” “–config” “/root/.config/rclone/rclone.conf” “–cache-db-purge” “–use-mmap” “–buffer-size=0M” “–drive-chunk-size=128M” “–write-back-cache” “–allow-other” “–dir-cache-time=24h” “–cache-chunk-size=32M” “–cache-chunk-total-size=50G” “–cache-info-age=48h” “–umask=002” “–cache-workers=8” “–attr-timeout=1s” “–daemon-timeout=10m” “–cache-tmp-upload-path” “/home/rclone/rclone_data/rclone_upload” “–cache-chunk-path” “/home/rclone/rclone_data/cache_dir/cache-backend” “–cache-db-path” “/home/rclone/rclone_data/cache_dir/cache-backend” “–cache-dir” “/home/rclone/rclone_data/cache_dir” “–cache-tmp-wait-time=75m” “–log-file” “/var/log/rclonecache.log” “–log-level” “DEBUG” “gcrypt:” “/mnt/media”]
2019/03/14 12:02:53 NOTICE: Serving remote control on http://127.0.0.1:5572/
2019/03/14 12:02:53 DEBUG : Using config file from “/root/.config/rclone/rclone.conf”
2019/03/14 12:02:53 DEBUG : gdrive: Loaded invalid token from config file - ignoring
2019/03/14 12:02:54 DEBUG : Keeping previous permissions for config file: -rw-r–r--
2019/03/14 12:02:54 DEBUG : gdrive: Saved new token in config file
2019/03/14 12:02:54 DEBUG : gcache: wrapped gdrive:bucket at root
2019/03/14 12:02:54 DEBUG : gcache: Purging the DB
2019/03/14 12:02:54 INFO : gcache: Cache DB path: /home/rclone/rclone_data/cache_dir/cache-backend/gcache.db
2019/03/14 12:02:54 INFO : gcache: Cache chunk path: /home/rclone/rclone_data/cache_dir/cache-backend/gcache
2019/03/14 12:02:54 INFO : gcache: Chunk Memory: true
2019/03/14 12:02:54 INFO : gcache: Chunk Size: 32M
2019/03/14 12:02:54 INFO : gcache: Chunk Total Size: 50G
2019/03/14 12:02:54 INFO : gcache: Chunk Clean Interval: 1m0s
2019/03/14 12:02:54 INFO : gcache: Workers: 8
2019/03/14 12:02:54 INFO : gcache: File Age: 2d
2019/03/14 12:02:54 INFO : gcache: Upload Temp Rest Time: 1h15m0s
2019/03/14 12:02:54 INFO : gcache: Upload Temp FS: /home/rclone/rclone_data/rclone_upload
2019/03/14 12:02:54 DEBUG : Adding path “cache/expire” to remote control registry
2019/03/14 12:02:54 DEBUG : Adding path “cache/stats” to remote control registry
2019/03/14 12:02:54 DEBUG : Adding path “cache/fetch” to remote control registry
2019/03/14 12:02:55 DEBUG : gcache: wrapped gdrive:bucket at root
2019/03/14 12:02:55 DEBUG : gcache: Purging the DB
2019/03/14 12:02:55 INFO : gcache: Cache DB path: /home/rclone/rclone_data/cache_dir/cache-backend/gcache.db
2019/03/14 12:02:55 INFO : gcache: Cache chunk path: /home/rclone/rclone_data/cache_dir/cache-backend/gcache
2019/03/14 12:02:55 INFO : gcache: Chunk Memory: true
2019/03/14 12:02:55 INFO : gcache: Chunk Size: 32M
2019/03/14 12:02:55 INFO : gcache: Chunk Total Size: 50G
2019/03/14 12:02:55 INFO : gcache: Chunk Clean Interval: 1m0s
2019/03/14 12:02:55 INFO : gcache: Workers: 8
2019/03/14 12:02:55 INFO : gcache: File Age: 2d
2019/03/14 12:02:55 INFO : gcache: Upload Temp Rest Time: 1h15m0s
2019/03/14 12:02:55 INFO : gcache: Upload Temp FS: /home/rclone/rclone_data/rclone_upload
2019/03/14 12:02:55 DEBUG : Adding path “cache/expire” to remote control registry
2019/03/14 12:02:55 DEBUG : Adding path “cache/stats” to remote control registry
2019/03/14 12:02:55 DEBUG : Adding path “cache/fetch” to remote control registry
2019/03/14 12:02:55 DEBUG : Encrypted drive ‘gcrypt:’: Mounting on “/mnt/media”
2019/03/14 12:02:55 DEBUG : Cache remote gcache:: subscribing to ChangeNotify
2019/03/14 12:02:55 DEBUG : Adding path “vfs/forget” to remote control registry
2019/03/14 12:02:55 DEBUG : Adding path “vfs/refresh” to remote control registry
2019/03/14 12:02:55 DEBUG : Adding path “vfs/poll-interval” to remote control registry
2019/03/14 12:02:55 DEBUG : : Root:
2019/03/14 12:02:55 DEBUG : : >Root: node=/, err=
2019/03/14 12:02:55 DEBUG : /: Attr:
2019/03/14 12:02:55 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:02:55 DEBUG : : Statfs:
2019/03/14 12:02:56 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:02:57 DEBUG : /: Attr:
2019/03/14 12:02:57 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:02:57 DEBUG : : Statfs:
2019/03/14 12:02:57 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:02:58 DEBUG : /: Attr:
2019/03/14 12:02:58 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:02:58 DEBUG : : Statfs:
2019/03/14 12:02:58 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:02:59 DEBUG : /: Attr:
2019/03/14 12:02:59 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:02:59 DEBUG : : Statfs:
2019/03/14 12:02:59 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:02:59 DEBUG : /: ReadDirAll:
2019/03/14 12:02:59 DEBUG : Cache remote gcache:: list ‘’
2019/03/14 12:02:59 DEBUG : : list: error: missing cached dir:
2019/03/14 12:02:59 DEBUG : : list: read 0 from temp fs
2019/03/14 12:02:59 DEBUG : : list: temp fs entries: []
2019/03/14 12:02:59 DEBUG : : list: read 9 from source
2019/03/14 12:02:59 DEBUG : : list: source entries: [692co93mqltin2sgs2e70kkdr0 eeko3nqojmk66vmp65f0f84p5c 9sjrti36njm5ougcnrcfd4gp60 flgh8c3lm302t8k0km3mg96i3g emgkjk6s5d8bsbpme50a9gh9cc t6l0rahpmneqc2nkcqcvqpjc20 3gc858rf41guumbngn8pedkj0o n0rvm7ha7ik8b02okpb3antir4 5n96rquvtriqlafes8eoj7ifhs]
2019/03/14 12:02:59 DEBUG : : list: cached object: eeko3nqojmk66vmp65f0f84p5c
2019/03/14 12:02:59 DEBUG : : list: cached object: t6l0rahpmneqc2nkcqcvqpjc20
2019/03/14 12:02:59 DEBUG : : Statfs:
2019/03/14 12:02:59 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:02:59 DEBUG : : list: cached directories: 7
2019/03/14 12:02:59 DEBUG : : list: cached dir: ‘’, cache ts: 2019-03-14 12:02:59.782825743 -0400 EDT m=+6.842115283
2019/03/14 12:02:59 DEBUG : /: >ReadDirAll: item=9, err=
2019/03/14 12:03:00 DEBUG : /: Attr:
2019/03/14 12:03:00 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:00 DEBUG : : Statfs:
2019/03/14 12:03:00 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:00 DEBUG : : Statfs:
2019/03/14 12:03:00 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:01 DEBUG : /: Attr:
2019/03/14 12:03:01 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:01 DEBUG : : Statfs:
2019/03/14 12:03:01 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:01 DEBUG : : Statfs:
2019/03/14 12:03:01 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:02 DEBUG : /: Attr:
2019/03/14 12:03:02 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:02 DEBUG : : Statfs:
2019/03/14 12:03:02 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:02 DEBUG : : Statfs:
2019/03/14 12:03:02 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:03 DEBUG : /: Attr:
2019/03/14 12:03:03 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:03 DEBUG : : Statfs:
2019/03/14 12:03:03 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:03 DEBUG : : Statfs:
2019/03/14 12:03:03 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:04 DEBUG : /: Attr:
2019/03/14 12:03:04 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:04 DEBUG : : Statfs:
2019/03/14 12:03:04 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:04 DEBUG : : Statfs:
2019/03/14 12:03:04 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:05 DEBUG : /: Attr:
2019/03/14 12:03:05 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:05 DEBUG : : Statfs:
2019/03/14 12:03:05 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:05 DEBUG : : Statfs:
2019/03/14 12:03:05 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:06 DEBUG : /: Attr:
2019/03/14 12:03:06 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:06 DEBUG : : Statfs:
2019/03/14 12:03:06 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:06 DEBUG : : Statfs:
2019/03/14 12:03:06 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:07 DEBUG : /: Attr:
2019/03/14 12:03:07 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:07 DEBUG : : Statfs:
2019/03/14 12:03:07 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:07 DEBUG : : Statfs:
2019/03/14 12:03:07 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:08 DEBUG : /: Attr:
2019/03/14 12:03:08 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:08 DEBUG : : Statfs:
2019/03/14 12:03:08 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:08 DEBUG : : Statfs:
2019/03/14 12:03:08 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:09 DEBUG : /: Attr:
2019/03/14 12:03:09 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:09 DEBUG : : Statfs:
2019/03/14 12:03:09 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:09 DEBUG : : Statfs:
2019/03/14 12:03:09 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:10 DEBUG : /: Attr:
2019/03/14 12:03:10 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:10 DEBUG : : Statfs:
2019/03/14 12:03:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:10 DEBUG : : Statfs:
2019/03/14 12:03:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:11 DEBUG : : Statfs:
2019/03/14 12:03:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:11 DEBUG : /: Attr:
2019/03/14 12:03:11 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:11 DEBUG : : Statfs:
2019/03/14 12:03:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:12 DEBUG : : Statfs:
2019/03/14 12:03:12 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:12 DEBUG : /: Attr:
2019/03/14 12:03:12 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:12 DEBUG : : Statfs:
2019/03/14 12:03:12 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:13 DEBUG : : Statfs:
2019/03/14 12:03:13 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:13 DEBUG : /: Attr:
2019/03/14 12:03:13 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:13 DEBUG : : Statfs:
2019/03/14 12:03:13 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:14 DEBUG : : Statfs:
2019/03/14 12:03:14 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:14 DEBUG : /: Attr:
2019/03/14 12:03:14 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:14 DEBUG : : Statfs:
2019/03/14 12:03:14 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:15 DEBUG : /: ReadDirAll:
2019/03/14 12:03:15 DEBUG : /: >ReadDirAll: item=9, err=
2019/03/14 12:03:15 DEBUG : /: Lookup: name=“test”
2019/03/14 12:03:15 DEBUG : /: >Lookup: node=test/, err=
2019/03/14 12:03:15 DEBUG : test/: Attr:
2019/03/14 12:03:15 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:15 DEBUG : /: Attr:
2019/03/14 12:03:15 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:15 DEBUG : /: ReadDirAll:
2019/03/14 12:03:15 DEBUG : /: >ReadDirAll: item=9, err=
2019/03/14 12:03:15 DEBUG : /: Attr:
2019/03/14 12:03:15 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:15 DEBUG : : Statfs:
2019/03/14 12:03:15 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:15 DEBUG : : Statfs:
2019/03/14 12:03:15 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:16 DEBUG : : Statfs:
2019/03/14 12:03:16 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:16 DEBUG : /: Attr:
2019/03/14 12:03:16 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:16 DEBUG : : Statfs:
2019/03/14 12:03:16 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:17 DEBUG : /: Lookup: name=“test”
2019/03/14 12:03:17 DEBUG : /: >Lookup: node=test/, err=
2019/03/14 12:03:17 DEBUG : test/: Attr:
2019/03/14 12:03:17 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:17 DEBUG : /: Lookup: name=“test”
2019/03/14 12:03:17 DEBUG : /: >Lookup: node=test/, err=
2019/03/14 12:03:17 DEBUG : test/: Attr:
2019/03/14 12:03:17 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:17 DEBUG : test/: Lookup: name=“test1g.txt”
2019/03/14 12:03:17 DEBUG : Cache remote gcache:: list ‘9sjrti36njm5ougcnrcfd4gp60’
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: empty listing
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: read 0 from temp fs
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: temp fs entries: []
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: read 6 from source
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: source entries: [9sjrti36njm5ougcnrcfd4gp60/rgs7d104upc879cof5sp4scprg 9sjrti36njm5ougcnrcfd4gp60/9nc299vlgqm5nsnabmp3153ibs 9sjrti36njm5ougcnrcfd4gp60/mmb1bggvdi0brinsiev4isui48 9sjrti36njm5ougcnrcfd4gp60/jejtt8dgqk936jt0bqniep67vc 9sjrti36njm5ougcnrcfd4gp60/kt7d3ao7lsbtmueovpn5nf8ng0 9sjrti36njm5ougcnrcfd4gp60/n64il6kn4lm865vq96r4akvl3s]
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/9nc299vlgqm5nsnabmp3153ibs
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/jejtt8dgqk936jt0bqniep67vc
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/kt7d3ao7lsbtmueovpn5nf8ng0
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/mmb1bggvdi0brinsiev4isui48
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/n64il6kn4lm865vq96r4akvl3s
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/rgs7d104upc879cof5sp4scprg
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached directories: 0
2019/03/14 12:03:17 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached dir: ‘9sjrti36njm5ougcnrcfd4gp60’, cache ts: 2019-03-14 12:03:17.66596861 -0400 EDT m=+24.725258202
2019/03/14 12:03:17 DEBUG : test/: >Lookup: node=test/test1g.txt, err=
2019/03/14 12:03:17 DEBUG : test/test1g.txt: Attr:
2019/03/14 12:03:17 DEBUG : test/test1g.txt: >Attr: a=valid=1s ino=0 size=524288 mode=-rw-rw-r–, err=
2019/03/14 12:03:17 DEBUG : test/: Remove: name=“test1g.txt”
2019/03/14 12:03:17 DEBUG : : Statfs:
2019/03/14 12:03:17 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:18 DEBUG : /: Attr:
2019/03/14 12:03:18 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:18 DEBUG : : Statfs:
2019/03/14 12:03:18 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:18 DEBUG : 9sjrti36njm5ougcnrcfd4gp60/rgs7d104upc879cof5sp4scprg: removing object
2019/03/14 12:03:18 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: cache: expired 9sjrti36njm5ougcnrcfd4gp60
2019/03/14 12:03:18 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: cache: expired
2019/03/14 12:03:18 DEBUG : : invalidating directory cache
2019/03/14 12:03:18 DEBUG : test: forgetting directory cache
2019/03/14 12:03:18 DEBUG : test/: >Remove: err=
2019/03/14 12:03:18 DEBUG : /: Lookup: name=“test”
2019/03/14 12:03:18 DEBUG : Cache remote gcache:: list ‘’
2019/03/14 12:03:18 DEBUG : : list: cold listing: 2019-03-12 12:03:18.28857837 -0400 EDT
2019/03/14 12:03:18 DEBUG : : list: read 0 from temp fs
2019/03/14 12:03:18 DEBUG : : list: temp fs entries: []
2019/03/14 12:03:18 DEBUG : : Statfs:
2019/03/14 12:03:18 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:18 DEBUG : : list: read 9 from source
2019/03/14 12:03:18 DEBUG : : list: source entries: [692co93mqltin2sgs2e70kkdr0 eeko3nqojmk66vmp65f0f84p5c 9sjrti36njm5ougcnrcfd4gp60 flgh8c3lm302t8k0km3mg96i3g emgkjk6s5d8bsbpme50a9gh9cc t6l0rahpmneqc2nkcqcvqpjc20 3gc858rf41guumbngn8pedkj0o n0rvm7ha7ik8b02okpb3antir4 5n96rquvtriqlafes8eoj7ifhs]
2019/03/14 12:03:18 DEBUG : : list: cached object: eeko3nqojmk66vmp65f0f84p5c
2019/03/14 12:03:18 DEBUG : : list: cached object: t6l0rahpmneqc2nkcqcvqpjc20
2019/03/14 12:03:18 DEBUG : : list: cached directories: 6
2019/03/14 12:03:18 DEBUG : : list: cached dir: ‘’, cache ts: 2019-03-14 12:03:18.892302451 -0400 EDT m=+25.951592044
2019/03/14 12:03:18 DEBUG : /: >Lookup: node=test/, err=
2019/03/14 12:03:18 DEBUG : test/: Attr:
2019/03/14 12:03:18 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:18 DEBUG : /: Lookup: name=“test”
2019/03/14 12:03:18 DEBUG : /: >Lookup: node=test/, err=
2019/03/14 12:03:18 DEBUG : test/: Attr:
2019/03/14 12:03:18 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:18 DEBUG : test/: Lookup: name=“test1g.txt”
2019/03/14 12:03:18 DEBUG : Cache remote gcache:: list ‘9sjrti36njm5ougcnrcfd4gp60’
2019/03/14 12:03:18 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cold listing: 2019-03-12 12:03:18.28857837 -0400 EDT
2019/03/14 12:03:18 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: read 0 from temp fs
2019/03/14 12:03:18 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: temp fs entries: []
2019/03/14 12:03:19 DEBUG : /: Attr:
2019/03/14 12:03:19 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=
2019/03/14 12:03:19 DEBUG : : Statfs:
2019/03/14 12:03:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:271793821665 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: read 5 from source
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: source entries: [9sjrti36njm5ougcnrcfd4gp60/9nc299vlgqm5nsnabmp3153ibs 9sjrti36njm5ougcnrcfd4gp60/mmb1bggvdi0brinsiev4isui48 9sjrti36njm5ougcnrcfd4gp60/jejtt8dgqk936jt0bqniep67vc 9sjrti36njm5ougcnrcfd4gp60/kt7d3ao7lsbtmueovpn5nf8ng0 9sjrti36njm5ougcnrcfd4gp60/n64il6kn4lm865vq96r4akvl3s]
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/9nc299vlgqm5nsnabmp3153ibs
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/jejtt8dgqk936jt0bqniep67vc
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/kt7d3ao7lsbtmueovpn5nf8ng0
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/mmb1bggvdi0brinsiev4isui48
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached object: 9sjrti36njm5ougcnrcfd4gp60/n64il6kn4lm865vq96r4akvl3s
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached directories: 0
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: list: cached dir: ‘9sjrti36njm5ougcnrcfd4gp60’, cache ts: 2019-03-14 12:03:19.132586816 -0400 EDT m=+26.191876409
2019/03/14 12:03:19 DEBUG : test/: >Lookup: node=, err=no such file or directory
2019/03/14 12:03:19 DEBUG : test/: Create: name=“test1g.txt”
2019/03/14 12:03:19 DEBUG : test/test1g.txt: Open: flags=O_WRONLY|O_CREATE|O_EXCL|0x20000
2019/03/14 12:03:19 DEBUG : test/test1g.txt: >Open: fd=test/test1g.txt (w), err=
2019/03/14 12:03:19 DEBUG : test/: >Create: node=test/test1g.txt, handle=&{test/test1g.txt (w)}, err=
2019/03/14 12:03:19 DEBUG : test/test1g.txt: Attr:
2019/03/14 12:03:19 DEBUG : test/test1g.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r–, err=
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=0
2019/03/14 12:03:19 DEBUG : test/test1g.txt: Setattr: a=Setattr [ID=0x62 Node=0x3 Uid=0 Gid=0 Pid=11989] mtime=2019-03-14 12:03:19.13852628 -0400 EDT handle=0x1
2019/03/14 12:03:19 DEBUG : test/test1g.txt: >Setattr: err=
2019/03/14 12:03:19 DEBUG : test/test1g.txt: Attr:
2019/03/14 12:03:19 DEBUG : test/test1g.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r–, err=
2019/03/14 12:03:19 DEBUG : Cache remote gcache:: put data streaming in ‘9sjrti36njm5ougcnrcfd4gp60/rgs7d104upc879cof5sp4scprg’
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: cache: expired 9sjrti36njm5ougcnrcfd4gp60
2019/03/14 12:03:19 DEBUG : 9sjrti36njm5ougcnrcfd4gp60: cache: expired
2019/03/14 12:03:19 DEBUG : : invalidating directory cache
2019/03/14 12:03:19 DEBUG : test: forgetting directory cache
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: >Write: written=131072, err=
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=393216
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=524288
2019/03/14 12:03:19 ERROR : test/test1g.txt: WriteFileHandle.Write: can’t seek in file without --vfs-cache-mode >= writes
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=262144
2019/03/14 12:03:19 ERROR : test/test1g.txt: WriteFileHandle.Write: can’t seek in file without --vfs-cache-mode >= writes
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: >Write: written=0, err=illegal seek
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=131072
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: >Write: written=0, err=illegal seek
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=786432
2019/03/14 12:03:19 ERROR : test/test1g.txt: WriteFileHandle.Write: can’t seek in file without --vfs-cache-mode >= writes
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: >Write: written=0, err=illegal seek
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=1441792
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=655360
2019/03/14 12:03:19 DEBUG : test/test1g.txt: Setattr: a=Setattr [ID=0x70 Node=0x3 Uid=0 Gid=0 Pid=11989] mtime=2019-03-14 12:03:19.198526121 -0400 EDT handle=0x1
2019/03/14 12:03:19 DEBUG : test/test1g.txt: >Setattr: err=
2019/03/14 12:03:19 DEBUG : test/test1g.txt: Attr:
2019/03/14 12:03:19 DEBUG : test/test1g.txt: >Attr: a=valid=1s ino=0 size=131072 mode=-rw-rw-r–, err=
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: >Write: written=131072, err=
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=1048576
2019/03/14 12:03:19 ERROR : test/test1g.txt: WriteFileHandle.Write: can’t seek in file without --vfs-cache-mode >= writes
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: >Write: written=0, err=illegal seek
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=1179648
2019/03/14 12:03:19 ERROR : test/test1g.txt: WriteFileHandle.Write: can’t seek in file without --vfs-cache-mode >= writes
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: >Write: written=0, err=illegal seek
2019/03/14 12:03:19 DEBUG : &{test/test1g.txt (w)}: Write: len=131072, offset=1310720


#9

What specifically did you run?

mv localfile mountlocation?


#10

mv -v local mountlocation


#11

I wouldn’t use fallocate to treat this. It is trying to seek the file.

Edit: I see…


#12

I saw the same behavior with .mkv files being moved.

I’ll create another empty 1G file and redo the test.

edit: I used fallocate to generate the file and mv to move it.

John


#13

Are you writing directly to the mount or is something in between? The offsets are jumping around which is making it look like a seek.

It should look like an ordered operation:

019/03/14 12:32:33 DEBUG : 1G.file: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2019/03/14 12:32:33 DEBUG : 1G.file: >Open: fd=1G.file (w), err=<nil>
2019/03/14 12:32:33 DEBUG : /: >Create: node=1G.file, handle=&{1G.file (w)}, err=<nil>
2019/03/14 12:32:33 DEBUG : 1G.file: Attr:
2019/03/14 12:32:33 DEBUG : 1G.file: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=0
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : Cache remote gcache:: put data streaming in '1G.file'
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=131072
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=262144
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=393216
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=524288
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=655360
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=786432
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=917504
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=1048576
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=1179648
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: >Write: written=131072, err=<nil>
2019/03/14 12:32:33 DEBUG : &{1G.file (w)}: Write: len=131072, offset=1310720

#14

Nope. I bring up the mount, ls it to verify it’s there and then mv the file from the local directory to the mount directory. There’s no service running that access the mount either. I checked and there’s only one instance of rclone running.

John


#15

Moving a 10G file.
#lsof | grep test
mv 22362 root 3r REG 179,2 10737418240 3615 /root/test10g.txt
mv 22362 root 4w REG 0,34 3832393728 2103861634628529763 /mnt/media/test/test10g.txt

lsof | grep ‘/mnt/media’

mv 22362 root 4w REG 0,34 7299760128 2103861634628529763 /mnt/media/test/test10g.txt
root@vacuum:~#

John


#16

Write-back-cache in your fuse options. Wonder if that’s causing issues.


#17

That did the trick - removing it and the file is able to be copied now.

I tested it on another system. A system with a 3.10 kernel works with the ‘write-back-cache’ flag enabled. Anything I have with a 4.1X kernel (and even 5) does not.

Great catch.

John


#18

https://www.phoronix.com/scan.php?page=news_item&px=MTY1MzQ

If you were to enable vfs writes with write-back-cache I wonder how performance would be… Compared to without and vfs off. I’ll have a play.


#19

I don’t think that fuse option actually works until 3.15 onward.


#20

Well, it doesn’t not not work. At least rclone started fine and didn’t complain when I had it flagged on.

Also, while it doesn’t appear to work with the cache backend on > 3.10, I’m not seeing any issues with it on a vfs backend on > 4.14.

John