Dave,
I found the problem. In this case, the SRT file is invalid (copied from Windows -> Linux?).
y 28, 2019 14:14:56.403 [0x7f43d140d700] DEBUG - BPQ: [Processing] -> [Idle]
May 28, 2019 14:14:56.405 [0x7f43c3a23700] DEBUG - Request: [::ffff:127.0.0.1:57154 (Loopback)] GET /library/streams/1207600 (16 live) GZIP Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:56.403 [0x7f43c1c2c700] DEBUG - HTTP requesting POST https://plex.tv/devices/29EE48AA-D89C-4B32-B5B3-C2B11A2F7CA8/notifications?Notification[collapseKey]=syncItemProcessing&Notification[data]=action%3DsyncJobProcessing%26syncItemID%3D36031924%26syncListID%3D6725693&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
May 28, 2019 14:14:56.429 [0x7f43c3a23700] DEBUG - Calculated media file path for path [media://6/b23f29dad64aa70bc817e39c46958532fa039fd.bundle/Contents/Subtitles/en/com.plexapp.agents.opensubtitles_2a75983ed9cfca5534c5a8c08664846b9f965407.srt]: ["/volume1/Plex/Library/Application Support/Plex Media Server/Media/localhost/6/b23f29dad64aa70bc817e39c46958532fa039fd.bundle/Contents/Subtitles/en/com.plexapp.agents.opensubtitles_2a75983ed9cfca5534c5a8c08664846b9f965407.srt"]
May 28, 2019 14:14:56.429 [0x7f43c3a23700] ERROR - Couldn't find the file to stream: /volume1/Plex/Library/Application Support/Plex Media Server/Media/localhost/6/b23f29dad64aa70bc817e39c46958532fa039fd.bundle/Contents/Subtitles/en/com.plexapp.agents.opensubtitles_2a75983ed9cfca5534c5a8c08664846b9f965407.srt
May 28, 2019 14:14:56.430 [0x7f43d0855700] DEBUG - HTTP 404 response from GET http://127.0.0.1:32400/library/streams/1207600?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
May 28, 2019 14:14:56.430 [0x7f444576d700] DEBUG - Completed: [::ffff:127.0.0.1:57154] 404 GET /library/streams/1207600 (16 live) GZIP 25ms 331 bytes
May 28, 2019 14:14:56.431 [0x7f43d0855700] DEBUG - Downloaded stream from [http://127.0.0.1:32400/library/streams/1207600?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx] (codec: srt) to temporary file [/volume1/Plex/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-68eb1ff4-eb20-4078-9dc2-bab5deb97782-819e723c-bfd5-4be6-ae20-ca0670be8398/temp-0.srt]
May 28, 2019 14:14:56.431 [0x7f43d0855700] DEBUG - TPU: hardware transcoding: zero-copy support present
May 28, 2019 14:14:56.431 [0x7f43d0855700] DEBUG - TPU: hardware transcoding: using zero-copy transcoding
May 28, 2019 14:14:56.431 [0x7f43d0855700] DEBUG - TPU: hardware transcoding: final decoder: vaapi, final encoder: vaapi
May 28, 2019 14:14:56.432 [0x7f43d0855700] DEBUG - Job running: EAE_ROOT='/volume1/Plex/tmp_transcoding/pms-5f991066-2eef-40fa-8e67-3664a5f3acd2/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/volume1/Plex/Library/Application\ Support/Plex\ Media\ Server/Codecs/392df4f-2233-linux-x86_64/' XDG_CACHE_HOME='/volume1/Plex/Library/Application Support/Plex Media Server/Cache' XDG_DATA_HOME='/volume1/@appstore/Plex Media Server/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/volume1/@appstore/Plex Media Server/Plex Transcoder' '-codec:#0x01' 'h264' '-hwaccel:#0x01' 'vaapi' '-hwaccel_fallback_threshold:#0x01' '10' '-hwaccel_output_format:#0x01' 'vaapi' '-analyzeduration' '20000000' '-probesize' '20000000' '-i' '/volume1/DS-Movies/Converted Movies/Family Movies/2018/Second.Act.2018/Second.Act.2018.mp4' '-analyzeduration' '20000000' '-probesize' '20000000' '-i' '/volume1/Plex/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-68eb1ff4-eb20-4078-9dc2-bab5deb97782-819e723c-bfd5-4be6-ae20-ca0670be8398/temp-0.srt' '-filter_complex' '[0:#0x01]hwupload[0];[0]scale_vaapi=w=1280:h=540:format=nv12[1];[1]hwupload[2]' '-map' '[2]' '-codec:0' 'h264_vaapi' '-b:0' '1250k' '-maxrate:0' '1667k' '-bufsize:0' '3334k' '-r:0' '23.975999999999999' '-map' '0:#0x02' '-metadata:s:1' 'language=eng' '-codec:1' 'copy' '-copypriorss:1' '0' '-map' '1:s:0' '-metadata:s:2' 'language=eng' '-codec:2' 'mov_text' '-f' 'mp4' '-map_metadata' '-1' '-map_chapters' '-1' '-movflags' '+faststart' '/volume1/Plex/Library/Application Support/Plex Media Server/Cache/Transcode/Sync+/6725693/63/153675.mp4.temp' '-y' '-vaapi_device' '/dev/dri/renderD128' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress'
May 28, 2019 14:14:56.433 [0x7f43d0855700] DEBUG - Jobs: Starting child process with pid 1732
May 28, 2019 14:14:56.666 [0x7f442e88f700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=startup (17 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:56.669 [0x7f4445a5b700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 204 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=startup (17 live) 2ms 203 bytes (pipelined: 1) (range: bytes=0-)
May 28, 2019 14:14:56.670 [0x7f442dcd7700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=opening (17 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:56.672 [0x7f4445a5b700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 204 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=opening (17 live) 2ms 203 bytes (pipelined: 2) (range: bytes=0-)
May 28, 2019 14:14:56.778 [0x7f442e5a1700] DEBUG - HTTP 200 response from GET https://plex.tv/servers/b9680a2940d730f68bbb17dd1f08d25ae765d17a/sync_lists?auth_token=xxxxxxxxxxxxxxxxxxxx
May 28, 2019 14:14:56.792 [0x7f442e5a1700] DEBUG - Sync: downloaded 3 sync lists, analyzing now...
May 28, 2019 14:14:56.792 [0x7f442e5a1700] DEBUG - Sync: sync list 18850826: user 1 (DaveTheNerd), device Dave-iPad-Pro-10.5, profile iOS, id C12F3793-AFD5-41BA-99BA-9D585BF38FE5, sync item(s): 20857172,20857177,20857198,20857201,22606807,22606831,22606836,23008251,23013747,23025617,23081135,23108309,24280933,24280942,24280951,24280962,24280965,24280970,24280971,24280978,24280982,24280985,24404691,24929928,24929931,24929935,24929942,24929946,25468306,25468321,27631052,27631055,27631062,27634955,27733144,28433073,28433089,28433113,28448932,28449604,30850702,31265957,31265960,32621542,32621549,32621572,32621579,32621599,32621614,32621616,32621627,32621632,32621634,32621640,33739535,33739548,33739566,33739576,33859717,33859740,33859746,33859751,35139611,35139614,35139635,35139646,35139657,36017910
May 28, 2019 14:14:56.792 [0x7f442e5a1700] DEBUG - Sync: sync list 32248471: user 14009285 (Skylar), device Skye's iPad 11, profile iOS, id 82C4DA66-5017-4672-85E2-F2A45E2BA035, sync item(s): 33987827,33987854,33987868,33987964,33992903,33993264,33993326,33993343,33993434
May 28, 2019 14:14:56.792 [0x7f442e5a1700] DEBUG - Sync: sync list 6725693: user 1 (DaveTheNerd), device Dave-iPhone XR, profile iOS, id 29EE48AA-D89C-4B32-B5B3-C2B11A2F7CA8, sync item(s): 10462971,36031924
May 28, 2019 14:14:56.792 [0x7f442e5a1700] DEBUG - Sync: synchronizing 3 sync lists to generators
May 28, 2019 14:14:56.827 [0x7f442e5a1700] DEBUG - Sync: synchronized 3 sync list(s) to 79 generators
May 28, 2019 14:14:56.828 [0x7f442e5a1700] INFO - Sync: downloaded 3 sync list(s) with 79 sync items(s): 0 new, 0 updated, 0 deleted
May 28, 2019 14:14:56.829 [0x7f4445a5b700] DEBUG - Completed: [::ffff:192.168.42.179:58120] 200 PUT /sync/refreshContent (17 live) TLS GZIP 1209ms 195 bytes (pipelined: 21)
May 28, 2019 14:14:56.829 [0x7f43d140d700] DEBUG - BPQ: garbageCollect - sync - forced - 10
May 28, 2019 14:14:56.829 [0x7f43d140d700] DEBUG - Sync: starting Sync garbage collection: 10, forced
May 28, 2019 14:14:56.829 [0x7f43d140d700] DEBUG - Sync: garbage collecting filesystem
May 28, 2019 14:14:56.830 [0x7f43d140d700] DEBUG - Sync: garbage collected filesystem
May 28, 2019 14:14:56.830 [0x7f43d140d700] DEBUG - Sync: scanning for items to reprocess in sync list 18850826
May 28, 2019 14:14:56.831 [0x7f43d140d700] DEBUG - Sync: scanned for items to reprocess in sync list 18850826
May 28, 2019 14:14:56.831 [0x7f43d140d700] DEBUG - Sync: scanning for items to reprocess in sync list 32248471
May 28, 2019 14:14:56.831 [0x7f43d140d700] DEBUG - Sync: scanned for items to reprocess in sync list 32248471
May 28, 2019 14:14:56.831 [0x7f43d140d700] DEBUG - Sync: scanning for items to reprocess in sync list 6725693
May 28, 2019 14:14:56.831 [0x7f43d140d700] DEBUG - Sync: scanned for items to reprocess in sync list 6725693
May 28, 2019 14:14:56.832 [0x7f43d140d700] DEBUG - Sync: finished Sync garbage collection: 10
May 28, 2019 14:14:56.955 [0x7f43c3735700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=opened (17 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:56.956 [0x7f4445a5b700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 204 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=opened (16 live) 0ms 203 bytes (pipelined: 3) (range: bytes=0-)
May 28, 2019 14:14:56.960 [0x7f442e88f700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/stream?index=0&id=1&codec=h264&type=video (16 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:56.961 [0x7f444576d700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 206 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/stream?index=0&id=1&codec=h264&type=video (16 live) 0ms 256 bytes (pipelined: 4) (range: bytes=0-)
May 28, 2019 14:14:56.968 [0x7f43c1c2c700] DEBUG - HTTP 200 response from POST https://plex.tv/devices/29EE48AA-D89C-4B32-B5B3-C2B11A2F7CA8/notifications?Notification[collapseKey]=syncItemProcessing&Notification[data]=action%3DsyncJobProcessing%26syncItemID%3D36031924%26syncListID%3D6725693&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
May 28, 2019 14:14:57.013 [0x7f442dcd7700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/stream?index=1&id=2&codec=aac&type=audio&profile=LC (16 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:57.013 [0x7f4445a5b700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 206 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/stream?index=1&id=2&codec=aac&type=audio&profile=LC (16 live) 0ms 256 bytes (pipelined: 5) (range: bytes=0-)
May 28, 2019 14:14:57.056 [0x7f442e5a1700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/streamDetail?index=0&id=1&codec=h264&type=video&bitrate=2495344&profile=High&language=und&width=1920&height=808&interlaced=0&sar=1:1&level=41&frameRate=23.976&disp_default=1 (16 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:57.057 [0x7f4445a5b700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 206 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/streamDetail?index=0&id=1&codec=h264&type=video&bitrate=2495344&profile=High&language=und&width=1920&height=808&interlaced=0&sar=1:1&level=41&frameRate=23.976&disp_default=1 (16 live) 0ms 256 bytes (pipelined: 6) (range: bytes=0-)
May 28, 2019 14:14:57.097 [0x7f43c3735700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/streamDetail?index=1&id=2&codec=aac&type=audio&profile=LC&language=eng&channels=6&layout=5.1&sampleRate=48000&disp_default=1 (16 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:57.098 [0x7f4445a5b700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 206 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress/streamDetail?index=1&id=2&codec=aac&type=audio&profile=LC&language=eng&channels=6&layout=5.1&sampleRate=48000&disp_default=1 (16 live) 0ms 256 bytes (pipelined: 7) (range: bytes=0-)
May 28, 2019 14:14:57.139 [0x7f442e88f700] DEBUG - Request: [::ffff:127.0.0.1:57158 (Loopback)] PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=opening (16 live) Signed-in Token (DaveTheNerd)
May 28, 2019 14:14:57.139 [0x7f4445a5b700] DEBUG - Completed: [::ffff:127.0.0.1:57158] 204 PUT /video/:/transcode/session/68eb1ff4-eb20-4078-9dc2-bab5deb97782/819e723c-bfd5-4be6-ae20-ca0670be8398/progress?status=opening (16 live) 0ms 203 bytes (pipelined: 8) (range: bytes=0-)
May 28, 2019 14:14:57.184 [0x7f43c3a23700] ERROR - [Transcoder] /volume1/Plex/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-68eb1ff4-eb20-4078-9dc2-bab5deb97782-819e723c-bfd5-4be6-ae20-ca0670be8398/temp-0.srt: Invalid data found when processing input
May 28, 2019 14:14:57.237 [0x7f4446037700] DEBUG - Jobs: '/volume1/@appstore/Plex Media Server/Plex Transcoder' exit code for process 1732 is 1 (failure)
May 28, 2019 14:14:57.237 [0x7f442fd11700] DEBUG - Streaming Resource: Terminated session 0x7f43c4586920:68eb1ff4-eb20-4078-9dc2-bab5deb97782 with reason Conversion failed. The transcoder exited due to an error.
May 28, 2019 14:14:57.237 [0x7f43d0855700] DEBUG - Using default transcode duration of 120 minutes
Specifically:
I would first check the permissions on the entire Plex share. I suspect the contents of the tmp_transcoding
directory has junk which isn’t accessible OR the contents of the Caches
directory under Library/Application Support/Plex Media Server
.
In either case, the SRT is the problem. Hardware transcoding itself is working.
As verification, transcode / play something without subtitles.