Can't playback certain files

Hi. I have the following strange issue using rclone cache for a GDrive remote.
I can’t start playback for certain files in plex or in VLC. The programs just endlessly buffering. With the file manager or cp command i can download the file locally just fine. The file is not corrupted and plays just fine when is local. In the logs i see that the file is starting to download but at a much slower rate then when i was using cp…
I observed the issue since 3 days ago. It is happening for some files that were playing just fine a week ago and for some newly uploaded files.
I have at first file a bug report but i was advised to post it here.
Thanks.
Here is some part of the log (the full text is in the bug report):
2018/07/13 15:16:10 DEBUG : Cache remote mdstorage_Media_cache:: list ‘Filme/Aftermath (2017)’
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017): list: warm 1 from cache for: Filme/Aftermath (2017), expiring on: 2018-07-13 21:05:12.778685195 +0300 EEST
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017): list: cached entries: [Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv]
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: >ReadDirAll: item=1, err=
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: Lookup: name=“Aftermath.2017_1080p.x264.RoSubbed.mkv”
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv, err=
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Attr:
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: >Attr: a=valid=1s ino=0 size=3540732610 mode=-rw-r–r--, err=
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: Lookup: name=".hidden"
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: Attr:
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:10 DEBUG : /: Lookup: name=".Trash"
2018/07/13 15:16:10 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:10 DEBUG : /: Lookup: name=".Trash-1000"
2018/07/13 15:16:10 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:10 DEBUG : /: Lookup: name=".hidden"
2018/07/13 15:16:10 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:10 DEBUG : : Statfs:
2018/07/13 15:16:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274119044359 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: Attr:
2018/07/13 15:16:10 DEBUG : Filme/Aftermath (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:12 DEBUG : /: Lookup: name=“Filme”
2018/07/13 15:16:12 DEBUG : /: >Lookup: node=Filme/, err=
2018/07/13 15:16:12 DEBUG : Filme/: Attr:
2018/07/13 15:16:12 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:12 DEBUG : /: Lookup: name=“Filme”
2018/07/13 15:16:12 DEBUG : /: >Lookup: node=Filme/, err=
2018/07/13 15:16:12 DEBUG : Filme/: Attr:
2018/07/13 15:16:12 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:12 DEBUG : Filme/: Lookup: name=“Aftermath (2017)”
2018/07/13 15:16:12 DEBUG : Filme/: >Lookup: node=Filme/Aftermath (2017)/, err=
2018/07/13 15:16:12 DEBUG : Filme/Aftermath (2017)/: Attr:
2018/07/13 15:16:12 DEBUG : Filme/Aftermath (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:15 DEBUG : /: Lookup: name=“Filme”
2018/07/13 15:16:15 DEBUG : /: >Lookup: node=Filme/, err=
2018/07/13 15:16:15 DEBUG : Filme/: Attr:
2018/07/13 15:16:15 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:15 DEBUG : /: Lookup: name=“Filme”
2018/07/13 15:16:15 DEBUG : /: >Lookup: node=Filme/, err=
2018/07/13 15:16:15 DEBUG : Filme/: Attr:
2018/07/13 15:16:15 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:15 DEBUG : Filme/: Lookup: name=“Aftermath (2017)”
2018/07/13 15:16:15 DEBUG : Filme/: >Lookup: node=Filme/Aftermath (2017)/, err=
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Attr:
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=“Aftermath.2017_1080p.x264.RoSubbed.mkv”
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv, err=
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Attr:
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: >Attr: a=valid=1s ino=0 size=3540732610 mode=-rw-r–r--, err=
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=O_RDONLY|0x800
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: >Open: fd=Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®, err=
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: >Open: fh=&{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}, err=
2018/07/13 15:16:15 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: Read: len=16384, offset=0
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.openRange at 0 length -1
2018/07/13 15:16:15 DEBUG : pacer: Rate limited, sleeping for 1.604402762s (1 consecutive low level retries)
2018/07/13 15:16:15 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:15 DEBUG : pacer: Rate limited, sleeping for 2.930228201s (2 consecutive low level retries)
2018/07/13 15:16:15 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:17 DEBUG : pacer: Resetting sleep to minimum 10ms on success
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize -1
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize -1
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize -1
2018/07/13 15:16:21 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: >Read: read=16384, err=
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize -1
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize -1
2018/07/13 15:16:21 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: Flush:
2018/07/13 15:16:21 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: >Flush: err=
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize -1
2018/07/13 15:16:21 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: Release:
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ReadFileHandle.Release closing
2018/07/13 15:16:21 DEBUG : /: Lookup: name=“Filme”
2018/07/13 15:16:21 DEBUG : /: >Lookup: node=Filme/, err=
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize -1
2018/07/13 15:16:21 DEBUG : Filme/: Attr:
2018/07/13 15:16:21 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:16:21 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize -1

2018/07/13 15:17:05 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1241088 length 131072 chunkOffset 1114112 chunkSize -1
2018/07/13 15:17:05 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: Read: len=8192, offset=1155072
2018/07/13 15:17:05 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1372160 length 262144 chunkOffset 1114112 chunkSize -1
2018/07/13 15:17:05 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ReadFileHandle.seek from 1118208 to 1155072 (fs.RangeSeeker)
2018/07/13 15:17:05 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.RangeSeek from 1634304 to 1155072 length -1
2018/07/13 15:17:05 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at -1 length 4096 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:05 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.openRange at 1155072 length -1
2018/07/13 15:17:05 DEBUG : pacer: Rate limited, sleeping for 1.862301909s (1 consecutive low level retries)
2018/07/13 15:17:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/13 15:17:05 DEBUG : pacer: Rate limited, sleeping for 2.954275911s (2 consecutive low level retries)
2018/07/13 15:17:05 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/13 15:17:07 DEBUG : pacer: Resetting sleep to minimum 10ms on success
2018/07/13 15:17:07 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: moving offset set from 0 to 1155072
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: cache reader closed 1634304
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1159168 length 8192 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: >Read: read=8192, err=
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1167360 length 16384 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1183744 length 32768 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1216512 length 65536 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1282048 length 131072 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Attr:
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: >Attr: a=valid=1s ino=0 size=3540732610 mode=-rw-r–r--, err=
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1413120 length 262144 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: Read: len=4096, offset=1200128
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1675264 length 524288 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 2199552 length 1048576 chunkOffset 1155072 chunkSize -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ReadFileHandle.seek from 1163264 to 1200128 (fs.RangeSeeker)
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.RangeSeek from 3248128 to 1200128 length -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at -1 length 4096 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:08 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.openRange at 1200128 length -1
2018/07/13 15:17:10 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: moving offset set from 0 to 1200128
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: cache reader closed 3248128
2018/07/13 15:17:11 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: >Read: read=4096, err=
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1204224 length 8192 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1212416 length 16384 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Attr:
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: >Attr: a=valid=1s ino=0 size=3540732610 mode=-rw-r–r--, err=
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1228800 length 32768 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1261568 length 65536 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1327104 length 131072 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1458176 length 262144 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : : Statfs:
2018/07/13 15:17:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274119044359 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 1720320 length 524288 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : /: Lookup: name=“Filme”
2018/07/13 15:17:11 DEBUG : /: >Lookup: node=Filme/, err=
2018/07/13 15:17:11 DEBUG : Filme/: Attr:
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 2244608 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:17:11 DEBUG : /: Lookup: name=“Filme”
2018/07/13 15:17:11 DEBUG : /: >Lookup: node=Filme/, err=
2018/07/13 15:17:11 DEBUG : Filme/: Attr:
2018/07/13 15:17:11 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 3293184 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/: Lookup: name=“Aftermath (2017)”
2018/07/13 15:17:11 DEBUG : Filme/: >Lookup: node=Filme/Aftermath (2017)/, err=
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Attr:
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 4341760 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 5390336 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: ReadDirAll:
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >ReadDirAll: item=1, err=
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=“Subtitles”
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=“subtitles”
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=“Subs”
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=“subs”
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 6438912 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 7487488 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 8536064 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.Read at 9584640 length 1048576 chunkOffset 1200128 chunkSize -1
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:11 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: Flush:
2018/07/13 15:17:11 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: >Flush: err=
2018/07/13 15:17:11 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: Release:
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ReadFileHandle.Release closing
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:17:11 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:17:12 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: cache reader closed 10633216
2018/07/13 15:17:12 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv ®}: >Release: err=
2018/07/13 15:17:48 DEBUG : Cache remote mdstorage_Media_cache:: starting cleanup
2018/07/13 15:17:52 DEBUG : Google drive root ‘Media’: Checking for changes on remote
2018/07/13 15:17:52 DEBUG : Google drive root ‘Media’: All changes were processed. Waiting for more.

I would kill -SIGHUP on the rclone process which purges the cachedb and rebuilds it as it looks like something is out of sync.

Try to run a mediainfo or ffprobe on the file and see if you can get all the mediainfo. I’ve also had issue where I get bad file or something goofy happens when I upload it (very rare) and it seems like you played the file first so it was working.

You have some entries that the cache thinks is there but doesn’t appear to be:

2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:15 DEBUG : pacer: Rate limited, sleeping for 2.930228201s (2 consecutive low level retries)
2018/07/13 15:16:15 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/13 15:16:15 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=, err=no such file or directory
2018/07/13 15:16:17 DEBUG : pacer: Resetting sleep to minimum 10ms on success

Those to me further point to the cachedb being out of sync. When I was using cache, I would always start it up with --cache-db-purge

Thanks for the reply.
I purged the cache and the db multiple times (i have erased the cache_backend folder). Same thing though :confused:
Using dmMediaConverter (my application btw, ffprobe/ffmpeg based) on the remote file gets the metadata just fine…

Have you changed chunk size at all as that can contribute to things not playing as well.

That’s usually in your /.config/rclone/cache and there is a named directory of the remote along with the namedremote.db (which is the cache.db). You can wipe both and start it back up and test.

In the rclone.conf file the chunk size is blank, so it is using the default size. I never change it.
I have told you i have wiped that files multiple times ( in /mnt/hdd/2TB/Temp/rclone/). This is the command i am using:
rclone mount --allow-other --daemon --cache-db-path /mnt/hdd/2TB/Temp/rclone/ --cache-tmp-upload-path=/mnt/hdd/2TB/Temp/rclone/rclone_upload/ --cache-info-age=24h --log-file /mnt/hdd/2TB/Temp/logs/rclone.log mdstorage_Media_cache: /mnt/remote/md.storage/Media/

So I wouldn’t know if you changed or not if I don’t ask as that is a common problem with playback.

You’ve removed all the stuff in “/mnt/hdd/2TB/Temp/rclone/” and restarted it back up to confirm I reading what you said correctly so your chunk folder would be in there.

What does your rclone.conf look like that you have setup? Can you share that with the keys and passwords blanked out?

of course. Here it is
[gdrive_mdstorage]
type = drive
client_id =
client_secret =
scope = drive
root_folder_id =
service_account_file =
token = {“access_token”:"",“token_type”:“Bearer”,“refresh_token”:“1/bzZasYNLH”,“expiry”:“2018-66+03:00”}

[mdstorage_Media_cache]
type = cache
remote = gdrive_mdstorage:Media
plex_url = http://127.0.0.1:32400/
plex_username = xxxxx
plex_password = 
chunk_size = 
info_age = 
chunk_total_size = 
plex_token =

If you aren’t doing any encryption, are you able to do:

rclone ls -vv mdstorage_Media_cache: “Filme/Aftermath (2017)/”

I believe that is the directory that has the file you are trying to play.

yes, i can even download the whole file locally using cp comand from the terminal. The file is intact.

Can you run the command and share the output along with a rclone copy with -vv as well?

ok First i have copied the file using terminal. I have ended before it could finish because the downloading was progressing well.

mdalacu@mdonline:/mnt/remote/md.storage/Media/Filme/Aftermath (2017)$ cp * /mnt/hdd/2TB/Temp/
^C

This is thefirst log.
Then i have tried a playback in VLC of the same file. The playback never started.
This is thesecond log.

Can you run the rclone ls command and instead of doing the cp, run the rclone copy command so we get the specific debug logs we’re looking for?

The odd thing is you have 403 rate limits when you did the cp, but it did seem to copy afterwards, which leads me to think it isn’t a ban.

On the cache play in VLC, it suddenly errors out looking for a “:”

(2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r), err=<nil>
2018/07/14 21:05:02 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: >Open: fh=&{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}, err=<nil>
2018/07/14 21:05:02 DEBUG : &{Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Read: len=131072, offset=0
2018/07/14 21:05:02 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.openRange at 0 length -1
2018/07/14 21:05:04 DEBUG : pacer: Rate limited, sleeping for 1.473419506s (1 consecutive low level retries)
2018/07/14 21:05:04 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:05:04 DEBUG : pacer: Rate limited, sleeping for 2.747724879s (2 consecutive low level retries)
2018/07/14 21:05:04 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:05:05 DEBUG : pacer: Rate limited, sleeping for 4.12721662s (3 consecutive low level retries)
2018/07/14 21:05:05 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:05:08 DEBUG : pacer: Resetting sleep to minimum 10ms on success

in the 2nd one:

2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: ChunkedReader.openRange at 0 length -1
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=<nil>, err=no such file or directory
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=<nil>, err=no such file or directory
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=<nil>, err=no such file or directory
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: Lookup: name=":"
2018/07/14 21:14:31 DEBUG : Filme/Aftermath (2017)/: >Lookup: node=<nil>, err=no such file or directory

You can also try to mount without the cache at all and use something like:

rclone mount gcrypt: /GD \
   --allow-other \
   --dir-cache-time 48h \
   --vfs-read-chunk-size 16M \
   --vfs-read-chunk-size-limit 1G \
   --buffer-size 100M \
   --log-file /home/someone/some.log \
   --umask 002 \
   --log-level DEBUG

and try to play without using the cache to see if the cache is causing a problem.

Here it is …log 3 withno cache.
It didn’t made any difference. The playback never started. No cache issue.
This is the command i have used:

rclone mount gdrive_mdstorage: /mnt/remote/md.storage/Test/ \
   --allow-other \
   --dir-cache-time 48h \
   --vfs-read-chunk-size 16M \
   --vfs-read-chunk-size-limit 1G \
   --buffer-size 100M \
   --log-file /mnt/hdd/2TB/Temp/logs/rclone_nocache.log \
   --umask 002 \
   --log-level DEBUG

So I personally don’t use VLC and haven’t tried to play anything with it.

You’ve copied a file via the mount and that worked.
We’ve removed the cache to see if that was an issue and no problems there.

Each time you play with VLC, it seems to 403 and rate limit you which is why the file isn’t playing.

When you try to hit play, you can see in the logs it keeps opening and closing the file:

2018/07/14 21:55:13 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:13 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:14 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:14 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:16 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:17 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:13 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:13 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:14 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:14 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:16 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock
2018/07/14 21:55:17 DEBUG : Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv: Open: flags=OpenReadOnly+OpenNonblock

That’s the opens and here is the flushes when it closes out:

018/07/14 21:55:08 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:08 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:55:08 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:08 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:55:13 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:13 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:55:14 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:14 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:55:14 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:14 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:55:16 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:16 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:55:17 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:17 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:55:18 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:55:18 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>
2018/07/14 21:58:06 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: Flush:
2018/07/14 21:58:06 DEBUG : &{Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv (r)}: >Flush: err=<nil>

and you get rate limited since it’s opening/closing or doing something very odd:

2018/07/14 21:56:34 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:56:34 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:56:35 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:56:45 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:56:45 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:56:54 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:56:54 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:05 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:15 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:15 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:24 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:24 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:25 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:35 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:35 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:44 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:44 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:45 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:57:55 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:58:04 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/07/14 21:58:04 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)

Can you try playing via something else as it seems to be related to VLC? I’m not sure if anyone else that uses VLC can chime in.

I have used VLC for this example as it was more conviniant for me. The real problem is Plex which suddenly stopped playing some of my files…files that used to work just fine.

Can you run a rclone copy on Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv and -vv that and see what it says?

Sorry for the late reply…
I have used this command:

rclone copy -vv --log-file /mnt/hdd/2TB/Temp/logs/rclone_copy.log "gdrive_mdstorage:Media/Filme/Aftermath (2017)/Aftermath.2017_1080p.x264.RoSubbed.mkv" /mnt/hdd/2TB/Temp/

The file downloaded very quickly …~ 11MB/s
Here is the log

And can you play the file one more time in Plex with debug? VLC seems to not work and if Plex was your goal, play it in that. I’m curious if you had a temp ban or something with all those 403s.

Yes, you are right. Now it works…wtf! :confused: Sorry for bothering you alll. And thank you Animosity022 for your patience!

Excellent!

So what i think happened is from the logs, you got a ban for something (unsure why) and that’s why when you tried to play things you’d see the open/close/number 403s errors.

The timing was goofy as I think the ban would go away and you’d copy it and it would work which makes it all that much harder. Usually its 24 hours but not sure anyone knows when the clock starts or stop on that 24 hours.