Error on Plex Library Scan using rclone Google Drive Cache Mount

Help and Support
1

Mount Script:

rclone mount gcache: /mnt/gdrive --allow-other --buffer-size 256M --dir-cache-time 72h --drive-chunk-size 32M --log-level INFO --log-file /var/log/rclone/gdrive --timeout 1h --umask 002 --vfs-read-chunk-size 128M --vfs-read-chunk-size-limit off --rc

rclone Config File:

[gdrive]
type = drive
scope = drive
token = {"access_token":"***ACCESS TOEKN***","token_type":"Bearer","refresh_token":"***REFRESH TOKEN***","expiry":"2019-02-10T14:13:50.493048752-05:00"}

[gcache]
type = cache
remote = gdrive:/Media
plex_url = http://my-plex-url:32400
plex_username = ***PLEX USERNAME***
plex_password = ***PLEX PASSWORD***

VPS Specs:

  • CentOS Linux release 7.6.1810 (Core)
  • QEMU Virtual CPU - 5 Cores
  • 4GB RAM
  • 2TB SATA HDD

Error:

2019/02/10 13:10:49 INFO : gcache: Cache DB path: /home/ag/.cache/rclone/cache-backend/gcache.db
2019/02/10 13:10:49 INFO : gcache: Cache chunk path: /home/ag/.cache/rclone/cache-backend/gcache
2019/02/10 13:10:49 INFO : gcache: Chunk Memory: true
2019/02/10 13:10:49 INFO : gcache: Chunk Size: 5M
2019/02/10 13:10:49 INFO : gcache: Chunk Total Size: 10G
2019/02/10 13:10:49 INFO : gcache: Chunk Clean Interval: 1m0s
2019/02/10 13:10:49 INFO : gcache: Workers: 4
2019/02/10 13:10:49 INFO : gcache: File Age: 6h0m0s
2019/02/10 13:11:08 INFO : gcache: Connected to Plex server: http://my-plex-url:32400
2019/02/10 13:12:38 ERROR : Movies/American Assassin (2017).mkv: (4184870912/4184939572) error (chunk not found 4183818240) response
2019/02/10 13:12:38 ERROR : Movies/American Assassin (2017).mkv: ReadFileHandle.Read error: low level retry 1/10: EOF

2

5M chunk size is super small for Plex. I’d make it 32M or 64M.

It looks like you maybe changed the chunk size or where the chunks are stored. You can run with a cache purge or can you kill -HUP the rclone process ID to refresht the cache.

3

I increased chuck size to 128M. I think I’m getting better results but still with errors.

2019/02/10 14:15:01 NOTICE: Serving remote control on http://127.0.0.1:5572/
2019/02/10 14:15:02 INFO : gcache: Cache DB path: /home/ag/.cache/rclone/cache-backend/gcache.db
2019/02/10 14:15:02 INFO : gcache: Cache chunk path: /home/ag/.cache/rclone/cache-backend/gcache
2019/02/10 14:15:02 INFO : gcache: Chunk Memory: true
2019/02/10 14:15:02 INFO : gcache: Chunk Size: 128M
2019/02/10 14:15:02 INFO : gcache: Chunk Total Size: 10G
2019/02/10 14:15:02 INFO : gcache: Chunk Clean Interval: 1m0s
2019/02/10 14:15:02 INFO : gcache: Workers: 4
2019/02/10 14:15:02 INFO : gcache: File Age: 6h0m0s
2019/02/10 14:16:18 INFO : gcache: Connected to Plex server: http://my-plex-url:32400
2019/02/10 14:17:02 INFO : cache-cleanup: chunks 70, est. size: 348.919M
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 1/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 2/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 3/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 4/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 5/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 6/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 7/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 8/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 9/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 10/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 1/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 2/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 3/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 4/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 5/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 6/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 7/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 8/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 9/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: low level retry 10/10: EOF
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: unexpected conditions during reading. current position: 5345280, current chunk position: 0, current chunk size: 5242880, offset: 5345280, chunk size: 128M, file size: 4300479864
2019/02/10 14:19:57 ERROR : Movies/Berlin Syndrome (2017).mp4: ReadFileHandle.Read error: EOF
2019/02/10 14:20:02 INFO : cache-cleanup: chunks 27, est. size: 132.176M

4

You need to either start up your mount with “–cache-db-purge” or kill -HUP the rclone process ID to flush the cache.

5

Plex library scanning completed fine with no errors logged by rclone but no media is playing. The only logs from rclone that I got was the following:

2019/02/10 14:54:38 INFO : Movies/The Burbs (1989).mkv: confirmed reading by external reader
2019/02/10 14:54:44 INFO : Movies/The Burbs (1989).mkv: confirmed reading by external reader
2019/02/10 14:54:44 INFO : Movies/The Burbs (1989).mkv: confirmed reading by external reader
2019/02/10 14:55:04 INFO : Movies/The Burbs (1989).mkv: confirmed reading by external reader
2019/02/10 14:55:25 INFO : Movies/The Burbs (1989).mkv: confirmed reading by external reader
2019/02/10 14:55:56 INFO : Movies/The Burbs (1989).mkv: confirmed reading by external reader
2019/02/10 14:56:11 INFO : Movies/The Burbs (1989).mkv: confirmed reading by external reader

Will providing Plex logs help in anyway?

6

I probably would not use 128M as I would suggest 32M or 64M at most.

I would change that and you’d need to clean the cache again.

7

I was able to play the movie but it took a really long time to play on Google Chrome.
Below logs start once I clicked on play button. Is there any other logs that I can provide that would help?

Feb 10, 2019 15:13:55.608 [0x7fd0a87ff700] DEBUG - Statistics: Flushing 3 expired bandwidth entries, 0 expired media entries.
Feb 10, 2019 15:14:11.809 [0x7fd095ffb700] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Feb 10, 2019 15:14:11.809 [0x7fd095ffb700] DEBUG - Selecting best audio stream for part ID 625 (autoselect: 1 language: en)
Feb 10, 2019 15:14:11.809 [0x7fd095ffb700] DEBUG - We’re going to try to auto-select a subtitle.
Feb 10, 2019 15:14:11.809 [0x7fd095ffb700] DEBUG - Selected a foreign audio track
Feb 10, 2019 15:14:11.809 [0x7fd095ffb700] DEBUG - Audio Stream: 17006, Subtitle Stream: 17007
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - Scaled up video bitrate to 7348Kbps based on 4.500000x fudge factor.
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: Selected protocol dash; container: mp4
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: analyzing media item 625
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): Direct Play is disabled
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): media must be transcoded in order to use the dash protocol
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): selected subtitle cannot be converted to a compatible format, burning into video stream
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): avoiding video remux due to burned subtitle stream
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): no remuxable profile found, so video stream will be transcoded
Feb 10, 2019 15:14:11.815 [0x7fd095ffb700] DEBUG - MDE: Cannot direct stream video stream due to profile or setting limitations
Feb 10, 2019 15:14:11.816 [0x7fd095ffb700] DEBUG - Scaled up video bitrate to 7348Kbps based on 4.500000x fudge factor.
Feb 10, 2019 15:14:11.816 [0x7fd095ffb700] DEBUG - MDE: Cannot direct stream audio stream due to codec dca when profile only allows aac
Feb 10, 2019 15:14:11.816 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): selected media 0 / 625
Feb 10, 2019 15:14:11.816 [0x7fd095ffb700] DEBUG - Streaming Resource: Calculated bandwidth of 2369kbps exceeds bandwidth limit. Changing decision parameters provided by client to fit bandwidth limit of 2000kbps
Feb 10, 2019 15:14:11.816 [0x7fd095ffb700] DEBUG - Streaming Resource: Determining preferred transcode encoders through transcode only decision.
Feb 10, 2019 15:14:11.816 [0x7fd095ffb700] DEBUG - Scaled up video bitrate to 7348Kbps based on 4.500000x fudge factor.
Feb 10, 2019 15:14:11.816 [0x7fd095ffb700] DEBUG - Scaled up video bitrate to 7348Kbps based on 4.500000x fudge factor.
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - Streaming Resource: Reducing playback quality for 1904kbps stream bitrate: video resolution to 720x406, audio channels to 2, quality to 41
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - Scaled up video bitrate to 7348Kbps based on 4.500000x fudge factor.
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - Scaled maximum bitrate for resolution reduction to 1035Kbps.
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: Selected protocol dash; container: mp4
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: analyzing media item 625
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): Direct Play is disabled
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): media must be transcoded in order to use the dash protocol
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): selected subtitle cannot be converted to a compatible format, burning into video stream
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): avoiding video remux due to burned subtitle stream
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): no remuxable profile found, so video stream will be transcoded
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - MDE: Cannot direct stream video stream due to profile or setting limitations
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - Scaled up video bitrate to 7348Kbps based on 4.500000x fudge factor.
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - Scaled maximum bitrate for resolution reduction to 1035Kbps.
Feb 10, 2019 15:14:11.817 [0x7fd095ffb700] DEBUG - 12 Years a Slave - audio.channels limitation applies: 6 > 2
Feb 10, 2019 15:14:11.818 [0x7fd095ffb700] DEBUG - MDE: Cannot direct stream audio stream due to profile or setting limitations
Feb 10, 2019 15:14:11.818 [0x7fd095ffb700] DEBUG - MDE: 12 Years a Slave (2013): selected media 0 / 625
Feb 10, 2019 15:14:11.818 [0x7fd095ffb700] DEBUG - Streaming Resource: Adding session 0x7fd0c680f1a0:p0lhy0ykanqdbbxhqfjhjv04 which is using 1257kbps of WAN bandwidth. Used is now 1257kbps
Feb 10, 2019 15:14:11.818 [0x7fd095ffb700] DEBUG - Streaming Resource: Adding session 0x7fd0c680f1a0:p0lhy0ykanqdbbxhqfjhjv04 which is using transcoder slot. Used slots is now 1
Feb 10, 2019 15:14:11.818 [0x7fd095ffb700] DEBUG - Streaming Resource: Added session 0x7fd0c680f1a0:p0lhy0ykanqdbbxhqfjhjv04
Feb 10, 2019 15:14:11.818 [0x7fd095ffb700] DEBUG - Streaming Resource: Reached Decision id=473 codes=(General=1001,Direct play not available; Conversion OK. Direct Play=3000,App cannot direct play this item. Direct play is disabled. Transcode=1001,Direct play not available; Conversion OK.) media=(id=625 part=(id=625 decision=transcode container=mp4 protocol=dash streams=(Video=(id=17005 decision=transcode bitrate=1035 encoder=libx264 width=720 height=406) Audio=(id=17006 decision=transcode bitrate=162 encoder=aac channels=2 rate=48000) Subtitle=(id=17007 decision=burn languageCode=eng location=embedded))))
Feb 10, 2019 15:14:11.822 [0x7fd0c47fe700] DEBUG - Completed: [MY IP ADDRESS:7085] 200 GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F473&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=wan&maxVideoBitrate=2000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=7q6abtas61t5xd23irx1taz6&subtitles=burn&Accept-Language=en (6 live) TLS GZIP 28297ms 5893 bytes (pipelined: 3)
Feb 10, 2019 15:14:12.249 [0x7fd0c1fff700] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Feb 10, 2019 15:14:12.249 [0x7fd0c1fff700] DEBUG - Selecting best audio stream for part ID 625 (autoselect: 1 language: en)
Feb 10, 2019 15:14:12.249 [0x7fd0c1fff700] DEBUG - We’re going to try to auto-select a subtitle.
Feb 10, 2019 15:14:12.249 [0x7fd0c1fff700] DEBUG - Selected a foreign audio track
Feb 10, 2019 15:14:12.249 [0x7fd0c1fff700] DEBUG - Audio Stream: 17006, Subtitle Stream: 17007
Feb 10, 2019 15:14:12.254 [0x7fd0c1fff700] DEBUG - Found session GUID of 7q6abtas61t5xd23irx1taz6 in session start.
Feb 10, 2019 15:14:12.254 [0x7fd0c1fff700] DEBUG - Cleaning directory for session 7q6abtas61t5xd23irx1taz6 ()
Feb 10, 2019 15:14:12.255 [0x7fd0c1fff700] DEBUG - Starting a transcode session 7q6abtas61t5xd23irx1taz6 at offset -1.0 (state=3)
Feb 10, 2019 15:14:12.258 [0x7fd0c1fff700] DEBUG - [Universal] Using local file path instead of URL: /mnt/gdrive/Movies/12 Years a Slave (2013)/12 Years a Slave (2013) HEVC-1080p DTS-6ch.mkv
Feb 10, 2019 15:14:12.258 [0x7fd0c1fff700] DEBUG - TPU: hardware transcoding: zero-copy support not present
Feb 10, 2019 15:14:12.259 [0x7fd0c1fff700] DEBUG - Job running: EAE_ROOT=’/tmp/pms-cc3dda11-033c-493c-bb13-33e11bea019d/EasyAudioEncoder’ FFMPEG_EXTERNAL_LIBS=’/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/531e313-1328-linux-ubuntu-x86_64/’ XDG_CACHE_HOME=’/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache’ XDG_DATA_HOME=’/usr/lib/plexmediaserver/Resources’ X_PLEX_TOKEN=‘xxxxxxxxxxxxxxxxxxxx’ ‘/usr/lib/plexmediaserver/Plex Transcoder’ ‘-codec:0’ ‘hevc’ ‘-codec:1’ ‘dca’ ‘-probesize’ ‘10000000’ ‘-i’ ‘/mnt/gdrive/Movies/12 Years a Slave (2013)/12 Years a Slave (2013) HEVC-1080p DTS-6ch.mkv’ ‘-filter_complex’ ‘[0:2]scale=1920:1080[0];[0:0][0]overlay[1];[1]scale=w=720:h=406[2];[2]format=pix_fmts=yuv420p|nv12[3]’ ‘-filter_complex’ ‘[0:1] aresample=async=1:ocl=’’‘stereo’’’:osr=48000[4]’ ‘-map’ ‘[3]’ ‘-codec:0’ ‘libx264’ ‘-crf:0’ ‘21’ ‘-maxrate:0’ ‘1035k’ ‘-bufsize:0’ ‘2070k’ ‘-r:0’ ‘23.975999999999999’ ‘-preset:0’ ‘veryfast’ ‘-x264opts:0’ ‘subme=2:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none’ ‘-force_key_frames:0’ ‘expr:gte(t,0+n_forced*8)’ ‘-map’ ‘[4]’ ‘-metadata:s:1’ ‘language=eng’ ‘-codec:1’ ‘aac’ ‘-b:1’ ‘162k’ ‘-f’ ‘dash’ ‘-min_seg_duration’ ‘8000000’ ‘-skip_to_segment’ ‘1’ ‘-time_delta’ ‘0.0625’ ‘-manifest_name’ ‘http://127.0.0.1:32400/video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/manifest’ ‘-avoid_negative_ts’ ‘disabled’ ‘-map_metadata’ ‘-1’ ‘-map_chapters’ ‘-1’ ‘dash’ ‘-start_at_zero’ ‘-copyts’ ‘-vsync’ ‘cfr’ ‘-y’ ‘-nostats’ ‘-loglevel’ ‘quiet’ ‘-loglevel_plex’ ‘error’ ‘-progressurl’ ‘http://127.0.0.1:32400/video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress’
Feb 10, 2019 15:14:12.293 [0x7fd0c1fff700] DEBUG - Jobs: Starting child process with pid 9265
Feb 10, 2019 15:14:12.322 [0x7fd0bcfff700] DEBUG - Request: [127.0.0.1:37284 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?status=startup (6 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:12.323 [0x7fd0c47fe700] DEBUG - Completed: [127.0.0.1:37284] 204 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?status=startup (6 live) 1ms 203 bytes (pipelined: 1) (range: bytes=0-)
Feb 10, 2019 15:14:12.324 [0x7fd095ffb700] DEBUG - Request: [127.0.0.1:37284 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?status=opening (6 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:12.324 [0x7fd0c4fff700] DEBUG - Completed: [127.0.0.1:37284] 204 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?status=opening (6 live) 0ms 203 bytes (pipelined: 2) (range: bytes=0-)
Feb 10, 2019 15:14:17.560 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:17.560 [0x7fd095ffb700] DEBUG - Request: [95.211.75.138:46042 (Subnet)] GET /:/websockets/notifications (7 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:17.560 [0x7fd095ffb700] DEBUG - WebSocket: Performing handshake from origin http://localhost
Feb 10, 2019 15:14:17.560 [0x7fd095ffb700] DEBUG - Beginning read from WebSocket
Feb 10, 2019 15:14:22.294 [0x7fd0c1fff700] DEBUG - Using default transcode duration of 120 minutes
Feb 10, 2019 15:14:22.294 [0x7fd0c1fff700] DEBUG - Started session successfully: 7q6abtas61t5xd23irx1taz6
Feb 10, 2019 15:14:22.297 [0x7fd0c47fe700] DEBUG - Completed: [MY IP ADDRESS:24872] 200 GET /video/:/transcode/universal/start.mpd?hasMDE=1&path=%2Flibrary%2Fmetadata%2F473&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=wan&maxVideoBitrate=2000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=7q6abtas61t5xd23irx1taz6&subtitles=burn&Accept-Language=en (7 live) TLS GZIP 36728ms 1016 bytes (pipelined: 2)
Feb 10, 2019 15:14:22.621 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:22.621 [0x7fd095ffb700] DEBUG - Request: [MY IP ADDRESS:24872 (WAN)] GET /status/sessions (8 live) TLS GZIP Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:22.621 [0x7fd095ffb700] DEBUG - [Now] Adding 0 sessions.
Feb 10, 2019 15:14:22.623 [0x7fd0c4fff700] DEBUG - Completed: [MY IP ADDRESS:24872] 200 GET /status/sessions (8 live) TLS GZIP 1ms 470 bytes (pipelined: 3)
Feb 10, 2019 15:14:22.732 [0x7fd0bcfff700] DEBUG - Request: [MY IP ADDRESS:24975 (WAN)] GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/1/initial.mp4 (8 live) TLS GZIP Signed-in
Feb 10, 2019 15:14:22.865 [0x7fd095ffb700] DEBUG - Request: [MY IP ADDRESS:24978 (WAN)] GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/1/0.m4s (12 live) TLS GZIP Signed-in
Feb 10, 2019 15:14:22.866 [0x7fd095ffb700] DEBUG - Asked for segment 0 from session.
Feb 10, 2019 15:14:22.876 [0x7fd0bdffe700] DEBUG - Request: [MY IP ADDRESS:24872 (WAN)] GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/0/initial.mp4 (12 live) TLS GZIP Signed-in
Feb 10, 2019 15:14:22.883 [0x7fd0c5fff700] DEBUG - Request: [MY IP ADDRESS:24976 (WAN)] GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/0/0.m4s (12 live) TLS GZIP Signed-in
Feb 10, 2019 15:14:22.883 [0x7fd0c5fff700] DEBUG - Asked for segment 0 from session.
Feb 10, 2019 15:14:22.893 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:22.893 [0x7fd0c3ffd700] DEBUG - Request: [MY IP ADDRESS:7101 (WAN)] GET /status/sessions (12 live) TLS GZIP Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:22.893 [0x7fd0c3ffd700] DEBUG - [Now] Adding 0 sessions.
Feb 10, 2019 15:14:22.895 [0x7fd0c4fff700] DEBUG - Completed: [MY IP ADDRESS:7101] 200 GET /status/sessions (12 live) TLS GZIP 2ms 470 bytes (pipelined: 1)
Feb 10, 2019 15:14:25.643 [0x7fd0b07fe700] DEBUG - Statistics: Flushing 3 expired bandwidth entries, 0 expired media entries.
Feb 10, 2019 15:14:39.735 [0x7fd0a87ff700] DEBUG - Auth: Refreshing tokens inside the token-based authentication filter.
Feb 10, 2019 15:14:39.735 [0x7fd0a87ff700] DEBUG - HTTP requesting GET https://plex.tv/servers/96bcceb413c2a9586911f495c3580e5dcddb61f2/access_tokens.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1
Feb 10, 2019 15:14:39.735 [0x7fd0c3ffd700] DEBUG - Request: [127.0.0.1:37292 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?status=opened (12 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:39.736 [0x7fd0c47fe700] DEBUG - Completed: [127.0.0.1:37292] 204 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?status=opened (12 live) 0ms 203 bytes (pipelined: 1) (range: bytes=0-)
Feb 10, 2019 15:14:39.736 [0x7fd0c3ffd700] DEBUG - Request: [127.0.0.1:37292 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/stream?index=0&id=0&codec=hevc&type=video (12 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:39.737 [0x7fd0c47fe700] DEBUG - Completed: [127.0.0.1:37292] 206 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/stream?index=0&id=0&codec=hevc&type=video (12 live) 0ms 256 bytes (pipelined: 2) (range: bytes=0-)
Feb 10, 2019 15:14:39.737 [0x7fd0c3ffd700] DEBUG - Request: [127.0.0.1:37292 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/stream?index=1&id=0&codec=dts&type=audio (12 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:39.737 [0x7fd0c47fe700] DEBUG - Completed: [127.0.0.1:37292] 206 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/stream?index=1&id=0&codec=dts&type=audio (12 live) 0ms 256 bytes (pipelined: 3) (range: bytes=0-)
Feb 10, 2019 15:14:40.191 [0x7fd0c3ffd700] DEBUG - Request: [127.0.0.1:37292 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/streamDetail?index=0&id=0&codec=hevc&type=video&profile=Main&width=1920&height=1080&interlaced=0&level=120&frameRate=23.976&disp_default=1 (12 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:40.191 [0x7fd0c47fe700] DEBUG - Completed: [127.0.0.1:37292] 206 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/streamDetail?index=0&id=0&codec=hevc&type=video&profile=Main&width=1920&height=1080&interlaced=0&level=120&frameRate=23.976&disp_default=1 (12 live) 0ms 256 bytes (pipelined: 4) (range: bytes=0-)
Feb 10, 2019 15:14:40.192 [0x7fd0c1fff700] DEBUG - Request: [127.0.0.1:37292 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/streamDetail?index=1&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24&disp_default=1 (12 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:40.192 [0x7fd0c47fe700] DEBUG - Completed: [127.0.0.1:37292] 206 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/streamDetail?index=1&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24&disp_default=1 (12 live) 0ms 256 bytes (pipelined: 5) (range: bytes=0-)
Feb 10, 2019 15:14:40.193 [0x7fd0c1fff700] DEBUG - Request: [127.0.0.1:37292 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/streamDetail?index=2&id=0&codec=hdmv_pgs_subtitle&type=subtitle&language=eng (12 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:40.193 [0x7fd0c47fe700] DEBUG - Completed: [127.0.0.1:37292] 206 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress/streamDetail?index=2&id=0&codec=hdmv_pgs_subtitle&type=subtitle&language=eng (12 live) 0ms 256 bytes (pipelined: 6) (range: bytes=0-)
Feb 10, 2019 15:14:40.199 [0x7fd0c1fff700] DEBUG - Request: [127.0.0.1:37292 (Loopback)] PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?duration=8050.091000 (12 live) Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:40.200 [0x7fd0c4fff700] DEBUG - Completed: [127.0.0.1:37292] 204 PUT /video/:/transcode/session/7q6abtas61t5xd23irx1taz6/c07aacf4-7690-485e-bf22-820f0f80ac37/progress?duration=8050.091000 (12 live) 0ms 203 bytes (pipelined: 7) (range: bytes=0-)
Feb 10, 2019 15:14:40.846 [0x7fd0c3ffd700] DEBUG - Transcoder: session 7q6abtas61t5xd23irx1taz6 indicated fallback to software decoding
Feb 10, 2019 15:14:43.036 [0x7fd0b3bff700] DEBUG - BPQ: onConsiderProcessing: Idle (true)
Feb 10, 2019 15:14:43.036 [0x7fd0b3bff700] DEBUG - BPQ: [Idle] -> [Processing]
Feb 10, 2019 15:14:43.037 [0x7fd0b3bff700] DEBUG - BPQ: generating queue items from 0 generator(s)
Feb 10, 2019 15:14:43.038 [0x7fd0b3bff700] DEBUG - BPQ: generated 0 item(s) for queue
Feb 10, 2019 15:14:43.038 [0x7fd0b3bff700] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Feb 10, 2019 15:14:43.038 [0x7fd0b3bff700] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Feb 10, 2019 15:14:43.070 [0x7fd0b3bff700] DEBUG - BPQ: [Processing] -> [Idle]
Feb 10, 2019 15:14:47.520 [0x7fd0c1fff700] DEBUG - Transcoder segment range: 0 - 0
Feb 10, 2019 15:14:47.539 [0x7fd0c5fff700] DEBUG - Returning segment 0 from session: “/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/chunk-stream0-00001.m4s”
Feb 10, 2019 15:14:47.539 [0x7fd0c5fff700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/init-stream0.m4s,/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/chunk-stream0-00001.m4s is 334474.
Feb 10, 2019 15:14:47.585 [0x7fd0bcfff700] DEBUG - Exists("/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/init-stream1.m4s") => 1
Feb 10, 2019 15:14:47.585 [0x7fd0bcfff700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/init-stream1.m4s is 740.
Feb 10, 2019 15:14:47.587 [0x7fd0c4fff700] DEBUG - Completed: [MY IP ADDRESS:24975] 200 GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/1/initial.mp4 (11 live) TLS GZIP 24855ms 740 bytes (pipelined: 1)
Feb 10, 2019 15:14:47.608 [0x7fd095ffb700] DEBUG - Returning segment 0 from session: “/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/chunk-stream1-00001.m4s”
Feb 10, 2019 15:14:47.608 [0x7fd095ffb700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/init-stream1.m4s,/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/chunk-stream1-00001.m4s is 65708.
Feb 10, 2019 15:14:47.617 [0x7fd0bdffe700] DEBUG - Exists("/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/init-stream0.m4s") => 1
Feb 10, 2019 15:14:47.617 [0x7fd0bdffe700] DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-7q6abtas61t5xd23irx1taz6-c07aacf4-7690-485e-bf22-820f0f80ac37/init-stream0.m4s is 806.
Feb 10, 2019 15:14:47.618 [0x7fd0c4fff700] DEBUG - Completed: [MY IP ADDRESS:24872] 200 GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/0/initial.mp4 (11 live) TLS GZIP 24742ms 806 bytes (pipelined: 4)
Feb 10, 2019 15:14:47.831 [0x7fd0c47fe700] DEBUG - Completed: [MY IP ADDRESS:24978] 200 GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/1/0.m4s (10 live) TLS GZIP 24965ms 65708 bytes (pipelined: 1)
Feb 10, 2019 15:14:47.898 [0x7fd0c47fe700] DEBUG - Completed: [MY IP ADDRESS:24976] 200 GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/0/0.m4s (10 live) TLS GZIP 25016ms 334474 bytes (pipelined: 1)
Feb 10, 2019 15:14:47.922 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:47.923 [0x7fd0c1fff700] DEBUG - Request: [MY IP ADDRESS:24872 (WAN)] GET /:/timeline?ratingKey=473&key=%2Flibrary%2Fmetadata%2F473&playbackTime=0&playQueueItemID=6&state=playing&hasMDE=1&time=0&duration=7200000 (10 live) TLS GZIP Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:47.925 [0x7fd0c1fff700] DEBUG - Client [p0lhy0ykanqdbbxhqfjhjv04] reporting timeline state playing, progress of 0/7200000ms for guid=, ratingKey=473 url=, key=/library/metadata/473, containerKey=, metadataId=473, source=
Feb 10, 2019 15:14:47.974 [0x7fd0c1fff700] DEBUG - It took 0.000000 ms to retrieve 179 items.
Feb 10, 2019 15:14:48.010 [0x7fd0c1fff700] DEBUG - It took 20.000000 ms to retrieve 179 items.
Feb 10, 2019 15:14:48.019 [0x7fd0c1fff700] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Feb 10, 2019 15:14:48.019 [0x7fd0c1fff700] DEBUG - Selecting best audio stream for part ID 625 (autoselect: 1 language: en)
Feb 10, 2019 15:14:48.019 [0x7fd0c1fff700] DEBUG - We’re going to try to auto-select a subtitle.
Feb 10, 2019 15:14:48.019 [0x7fd0c1fff700] DEBUG - Selected a foreign audio track
Feb 10, 2019 15:14:48.019 [0x7fd0c1fff700] DEBUG - Audio Stream: 17006, Subtitle Stream: 17007
Feb 10, 2019 15:14:48.024 [0x7fd0c1fff700] DEBUG - [Now] User is PLEX USERNAME (ID: 1)
Feb 10, 2019 15:14:48.024 [0x7fd0c1fff700] DEBUG - [Now] Device is Chrome (Chrome).
Feb 10, 2019 15:14:48.024 [0x7fd0c1fff700] DEBUG - [Now] Profile is Web
Feb 10, 2019 15:14:48.024 [0x7fd0c1fff700] DEBUG - [Now] Updated play state for /library/metadata/473.
Feb 10, 2019 15:14:48.025 [0x7fd0c1fff700] DEBUG - HubCache: Expiring ‘1/home.continue/1/hubs/en/count=17&excludeFields=summary&excludePlaylists=1&includeEmpty=1&includeExternalMetadata=1&includeFeaturedTags=1&includeStations=1&onlyTransient=1’ because of event plex.event.play.session.state.update.
Feb 10, 2019 15:14:48.025 [0x7fd0c1fff700] DEBUG - HubCache: Expiring ‘1/home.movies.recent/1/hubs/en/count=17&excludeFields=summary&excludePlaylists=1&includeEmpty=1&includeExternalMetadata=1&includeFeaturedTags=1&includeStations=1&onlyTransient=1’ because event plex.event.play.session.state.update referenced an item the hub contained
Feb 10, 2019 15:14:48.025 [0x7fd0c1fff700] DEBUG - HubCache: Expiring ‘1/home.ondeck/1/hubs/en/count=17&excludeFields=summary&excludePlaylists=1&includeEmpty=1&includeExternalMetadata=1&includeFeaturedTags=1&includeStations=1&onlyTransient=1’ because of event plex.event.play.session.state.update.
Feb 10, 2019 15:14:48.026 [0x7fd0c1fff700] DEBUG - Statistics: (2bqkm99es28mqkzl3hk1yhoa) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 1
Feb 10, 2019 15:14:48.027 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:48.027 [0x7fd0bcfff700] DEBUG - Request: [95.211.75.138:46054 (Subnet)] GET /library/metadata/473 (11 live) GZIP Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:48.030 [0x7fd0c4fff700] DEBUG - Completed: [MY IP ADDRESS:24872] 200 GET /:/timeline?ratingKey=473&key=%2Flibrary%2Fmetadata%2F473&playbackTime=0&playQueueItemID=6&state=playing&hasMDE=1&time=0&duration=7200000 (11 live) TLS GZIP 107ms 820 bytes (pipelined: 5)
Feb 10, 2019 15:14:48.042 [0x7fd0bcfff700] DEBUG - It took 10.000000 ms to retrieve 179 items.
Feb 10, 2019 15:14:48.046 [0x7fd0bcfff700] DEBUG - We’re going to try to auto-select an audio stream for account 1.
Feb 10, 2019 15:14:48.046 [0x7fd0bcfff700] DEBUG - Selecting best audio stream for part ID 625 (autoselect: 1 language: en)
Feb 10, 2019 15:14:48.046 [0x7fd0bcfff700] DEBUG - We’re going to try to auto-select a subtitle.
Feb 10, 2019 15:14:48.046 [0x7fd0bcfff700] DEBUG - Selected a foreign audio track
Feb 10, 2019 15:14:48.046 [0x7fd0bcfff700] DEBUG - Audio Stream: 17006, Subtitle Stream: 17007
Feb 10, 2019 15:14:48.049 [0x7fd0c4fff700] DEBUG - Completed: [95.211.75.138:46054] 200 GET /library/metadata/473 (11 live) GZIP 21ms 5911 bytes (pipelined: 1)
Feb 10, 2019 15:14:48.059 [0x7fd0c5fff700] DEBUG - Request: [MY IP ADDRESS:24978 (WAN)] GET /video/:/transcode/universal/dash/7q6abtas61t5xd23irx1taz6/1/1.m4s (11 live) TLS GZIP Signed-in
Feb 10, 2019 15:14:48.060 [0x7fd0c5fff700] DEBUG - Asked for segment 1 from session.
Feb 10, 2019 15:14:48.139 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:48.140 [0x7fd095ffb700] DEBUG - Request: [MY IP ADDRESS:24975 (WAN)] GET /status/sessions (11 live) TLS GZIP Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:48.140 [0x7fd095ffb700] DEBUG - [Now] Adding 1 sessions.
Feb 10, 2019 15:14:48.145 [0x7fd0c4fff700] DEBUG - Completed: [MY IP ADDRESS:24975] 200 GET /status/sessions (11 live) TLS GZIP 5ms 6341 bytes (pipelined: 2)
Feb 10, 2019 15:14:48.283 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:48.283 [0x7fd0c1fff700] DEBUG - Request: [MY IP ADDRESS:24872 (WAN)] GET /status/sessions (11 live) TLS GZIP Signed-in Token (PLEX USERNAME)
Feb 10, 2019 15:14:48.283 [0x7fd0c1fff700] DEBUG - [Now] Adding 1 sessions.
Feb 10, 2019 15:14:48.288 [0x7fd0c47fe700] DEBUG - Completed: [MY IP ADDRESS:24872] 200 GET /status/sessions (11 live) TLS GZIP 4ms 6342 bytes (pipelined: 6)
Feb 10, 2019 15:14:48.302 [0x7fd0c4fff700] DEBUG - Auth: authenticated user 1 as PLEX USERNAME
Feb 10, 2019 15:14:48.302 [0x7fd0bdffe700] DEBUG - Request: [MY IP ADDRESS:24976 (WAN)] GET /playQueues/7?repeat=0&own=1&includeChapters=1&includeGeolocation=1 (11 live) TLS GZIP Signed-in Token (PLEX USERNAME)

p.s. I had to delete the last part of the logs as I’ve exceeded the number of characters.

8

Is that before or after changing it to 32 or 64?

9

After changing to 64M. I only restarted rclone, would restarting Plex make any difference?

10

One thing as well as the plex integration makes things start slow as it starts with a single worker and will move up.

If you have to use the cache backend, I’d turn off the plex integration and give it a whirl.

11

Still the same, it takes mins for the movie to start playing once I click on play button. Would changing vfs/cache make a difference? Since I’ve read that vfs stores cache in HDD and normal cache uses RAM and since my HDD is SATA.

12

Are you playing directly from the mount or from something else?

13

Direct from the mount. I’ve installed rclone & plex yesterday as I’ve got a new VPS and have a clean installation of CentOS. Am I missing any configurations or tweaks?

14

You should change the buffer size to 0M if you are using the cache backend.

15

Now the movie doesn’t even play.

rclone logs:

2019/02/10 15:37:57 NOTICE: Serving remote control on http://127.0.0.1:5572/
2019/02/10 15:37:57 INFO : gcache: Cache DB path: /home/ag/.cache/rclone/cache-backend/gcache.db
2019/02/10 15:37:57 INFO : gcache: Cache chunk path: /home/ag/.cache/rclone/cache-backend/gcache
2019/02/10 15:37:58 INFO : gcache: Chunk Memory: true
2019/02/10 15:37:58 INFO : gcache: Chunk Size: 64M
2019/02/10 15:37:58 INFO : gcache: Chunk Total Size: 10G
2019/02/10 15:37:58 INFO : gcache: Chunk Clean Interval: 1m0s
2019/02/10 15:37:58 INFO : gcache: Workers: 4
2019/02/10 15:37:58 INFO : gcache: File Age: 6h0m0s
2019/02/10 15:39:23 ERROR : Movies/Ali Wong Hard Knock Wife (2018).mkv: (0/1930410648) error (chunk not found 0) response
2019/02/10 15:39:23 ERROR : Movies/Ali Wong Hard Knock Wife (2018).mkv: ReadFileHandle.Read error: low level retry 1/10: EOF
2019/02/10 15:39:52 ERROR : Movies/Ali Wong Hard Knock Wife (2018).mkv: (0/1930410648) error (chunk not found 0) response
2019/02/10 15:39:52 ERROR : Movies/Ali Wong Hard Knock Wife (2018).mkv: ReadFileHandle.Read error: low level retry 1/10: EOF

Plex error message:
chrome_2019-02-10_23-41-20

I’m really sorry. I’m new to this and I’m not really sure what’s going on.

16

You need to either start up your mount with “–cache-db-purge” or kill -HUP the rclone process ID to flush the cache.

That needs to be done if you change the chunk size.

17

Below is the script I use to mount Google drive.

/usr/bin/rclone mount gcache: /mnt/gdrive --allow-other --buffer-size 0M --dir-cache-time 72h --cache-chunk-size 64M --cache-db-purge --log-level INFO --log-file /var/log/rclone/gdrive --timeout 1h --umask 002 --vfs-read-chunk-size 128M --vfs-read-chunk-size-limit off --rc

adding --cache-db-purge within the script should do the job, right?

Also, I’ve been using /bin/fusermount -uz /mnt/gdrive to unmount before remounting.

18

That should be good.

You can always just stop the mount and remove:

/home/ag/.cache/rclone/cache-backend/gcache.db
/home/ag/.cache/rclone/cache-backend/gcache

and start it back up if that’s easier.

19

Movies play now! But take around 2 to 3 mins to start playing, is this normal? can it be improved?

20

Are you using your own API key?

You can always try without the cache as well so something like

rclone mount GD: /mnt/gdrive --allow-other --dir-cache-time 72h --drive-chunk-size 32M --log-level INFO --log-file /var/log/rclone/gdrive --timeout 1h --umask 002 --vfs-read-chunk-size 128M --vfs-read-chunk-size-limit off --rc

would be a good test.