Server Version#: 1.21.3.4014
Player Version#: Plex Web 4.51.1
So I found that some movies don’t play direct, only manually switching to transcoding will make them work. On the server itself as well as on completely different Computers (e.g. my Windows Laptop). At first glance there’s nothing unusual, x264 at a normal bitrate. This is the Media Info output:
General
UniqueID/String : 245078123632902188402499397034336578471 (0xB860546757BAAE2F93C2A4EC10CFE017)
CompleteName : A:\Movies\dwqdqwddw\dqdqdqddqdwq.mkv
Format/String : Matroska
Format_Version : Version 2
FileSize/String : 11.1 GiB
Duration/String : 2 h 21 min
OverallBitRate_Mode/String : Variable
OverallBitRate/String : 11.3 Mb/s
Encoded_Date : UTC 2015-09-02 10:27:16
Encoded_Application/String : mkvmerge v3.4.0 (‘Rapunzel’) built on May 15 2010 09:38:20
Encoded_Library/String : libebml v0.8.0 + libmatroska v0.9.0
Audio #1
ID/String : 2
Format/String : DTS
Format/Info : Digital Theater Systems
CodecID : A_DTS
Duration/String : 2 h 21 min
BitRate_Mode/String : Constant
BitRate/String : 1 509 kb/s
Channel(s)/String : 6 channels
ChannelLayout : C L R Ls Rs LFE
SamplingRate/String : 48.0 kHz
FrameRate/String : 93.750 FPS (512 SPF)
BitDepth/String : 24 bits
Compression_Mode/String : Lossy
StreamSize/String : 1.49 GiB (13%)
Language/String : German
Default/String : Yes
Forced/String : No
Audio #2
ID/String : 3
Format/String : DTS
Format/Info : Digital Theater Systems
CodecID : A_DTS
Duration/String : 2 h 21 min
BitRate_Mode/String : Constant
BitRate/String : 1 509 kb/s
Channel(s)/String : 6 channels
ChannelLayout : C L R Ls Rs LFE
SamplingRate/String : 48.0 kHz
FrameRate/String : 93.750 FPS (512 SPF)
BitDepth/String : 24 bits
Compression_Mode/String : Lossy
StreamSize/String : 1.49 GiB (13%)
Language/String : English
Default/String : No
Forced/String : No
Text #1
ID/String : 4
Format/String : VobSub
MuxingMode : zlib
CodecID : S_VOBSUB
CodecID/Info : Picture based subtitle format used on DVDs
Language/String : German
Default/String : No
Forced/String : No
Text #2
ID/String : 5
Format/String : VobSub
MuxingMode : zlib
CodecID : S_VOBSUB
CodecID/Info : Picture based subtitle format used on DVDs
Language/String : English
Default/String : No
Forced/String : No
Inspect the Plex Media Server.log file.
Navigate to the time stamps which match the time when you pressed Play.
The most relevant lines have MDE: in them.
I’m certainly not an expert, but I doubt Plex Web has ever or will ever direct play DTS audio. (that is the section you’ve posted in). So a transcode of at least the audio is required, even if you are not using the subs.
The subs are picture based (VobSub), so that also will require a transcode on most apps, and for sure the Plex Web app.
If I activate the subtitles, Plex switches to transcoding and playback works.
Nope, just using it to play in the browser on that same device.
All local, even on the server itself it acts the same
Default bitrate 8mpbs. The recommended settings are checked: All compatible videos will play at original quality. Incompatible videos will be converted at maximum quality.
The problem isn’t that Plex decides to transcode. The problem is that playback doesn’t even start unless I switch to transcoding myself, either by selecting subtitles or a different bitrate. I’ll check if the log reveals anything helpful, though.
13:40:39.879 DEBUG - Request: [192.168.178.31:57360 (Subnet)] POST /playQueues?type=video&uri=server%3A%2F%2F5e4d68b09709560b3d52f902a79fce635ec3e7a4%2Fcom.plexapp.plugins.library%2Flibrary%2Fmetadata%2F2762&repeat=0&own=1&includeChapters=1&includeMarkers=1&includeGeolocation=1&includeExternalMedia=1 (11 live) TLS GZIP Signed-in Token (amorpheus)
13:40:39.880 DEBUG - PlayQueue: Converted 'server://5e4d68b09709560b3d52f902a79fce635ec3e7a4/com.plexapp.plugins.library/library/metadata/2762' to 'library://x/item/%2Flibrary%2Fmetadata%2F2762'
13:40:39.880 DEBUG - PlayQueue: 0 generated IDs compressed down to a 20 byte blob.
13:40:39.882 DEBUG - PlayQueue: Start index: 0 End index: 0 Count: 1
13:40:39.882 DEBUG - PlayQueue: 1 generated IDs compressed down to a 24 byte blob.
13:40:39.885 DEBUG - PlayQueue: Added 1 items in 0.0 sec.
13:40:39.891 DEBUG - It took 10.000000 ms to retrieve 138 items.
13:40:39.892 DEBUG - Audio Stream: 85848, Subtitle Stream: 0
13:40:39.894 DEBUG - Completed: [192.168.178.31:57360] 200 POST /playQueues?type=video&uri=server%3A%2F%2F5e4d68b09709560b3d52f902a79fce635ec3e7a4%2Fcom.plexapp.plugins.library%2Flibrary%2Fmetadata%2F2762&repeat=0&own=1&includeChapters=1&includeMarkers=1&includeGeolocation=1&includeExternalMedia=1 (11 live) TLS GZIP 14ms 5952 bytes (pipelined: 8)
13:40:39.971 DEBUG - Auth: authenticated user 1 as amorpheus
13:40:39.971 DEBUG - Request: [192.168.178.31:57360 (Subnet)] GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F2762&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=700&location=lan&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=9ioe0d0gbw20lh35ktpgq8v3&subtitles=burn&Accept-Language=en (11 live) TLS GZIP Signed-in Token (amorpheus)
13:40:39.971 DEBUG - [Transcode] Found session GUID of 9ioe0d0gbw20lh35ktpgq8v3 in session start.
13:40:39.971 DEBUG - [Transcode] TranscodeUniversalRequest: using augmented profile Web
13:40:39.971 DEBUG - [Transcode] Downloading document http://127.0.0.1:32400/library/metadata/2762?includeBandwidths=1&offset=-1&X-Plex-Incomplete-Segments=1&X-Plex-Session-Identifier=ydt5omjf755ze38pwgh7b5t4
13:40:39.971 DEBUG - [Transcode] Auth: authenticated user 1 as amorpheus
13:40:39.979 DEBUG - [Transcode] It took 10.000000 ms to retrieve 138 items.
13:40:39.981 DEBUG - [Transcode] Audio Stream: 85848, Subtitle Stream: 0
13:40:39.983 DEBUG - [Transcode] MDE: Selected protocol dash; container: mp4
13:40:39.983 DEBUG - [Transcode] MDE: analyzing media item 2816
13:40:39.983 DEBUG - [Transcode] MDE: Movie: Direct Play is disabled
13:40:39.983 DEBUG - [Transcode] MDE: Movie: media must be transcoded in order to use the dash protocol
13:40:39.983 DEBUG - [Transcode] MDE: Movie: selected audio stream is not the first audio stream and direct play stream selection is not enabled
13:40:39.983 DEBUG - [Transcode] MDE: Movie: no direct play video profile exists for http/mkv/h264
13:40:39.983 DEBUG - [Transcode] MDE: Movie: no direct play video profile exists for http/mkv/h264/dca
13:40:39.983 DEBUG - [Transcode] MDE: Movie: no direct play video profile exists for http/mkv/h264/dca
13:40:39.983 DEBUG - [Transcode] MDE: Cannot direct stream audio stream due to codec dca when profile only allows aac
13:40:39.983 DEBUG - [Transcode] MDE: Movie: selected media 0 / 2816
13:40:39.983 DEBUG - [Transcode] Streaming Resource: Added session 0x7f770c063d20:ydt5omjf755ze38pwgh7b5t4
13:40:39.983 DEBUG - [Transcode] Streaming Resource: Reached Decision id=2762 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=2816 part=(id=2817 decision=transcode container=mp4 protocol=dash streams=(Video=(id=85846 decision=copy width=1920 height=804) Audio=(id=85848 decision=transcode bitrate=256 encoder=aac channels=2 rate=48000))))
13:40:39.985 DEBUG - Completed: [192.168.178.31:57360] 200 GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F2762&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=700&location=lan&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=9ioe0d0gbw20lh35ktpgq8v3&subtitles=burn&Accept-Language=en (11 live) TLS GZIP 14ms 5486 bytes (pipelined: 9)
13:40:40.043 DEBUG - Auth: authenticated user 1 as amorpheus
13:40:40.044 DEBUG - Request: [192.168.178.31:57360 (Subnet)] GET /video/:/transcode/universal/start.mpd?hasMDE=1&path=%2Flibrary%2Fmetadata%2F2762&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=700&location=lan&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=9ioe0d0gbw20lh35ktpgq8v3&subtitles=burn&Accept-Language=en (11 live) TLS GZIP Signed-in Token (amorpheus)
13:40:40.044 DEBUG - [Transcode] Found session GUID of 9ioe0d0gbw20lh35ktpgq8v3 in session start.
13:40:40.044 DEBUG - [Transcode] TranscodeUniversalRequest: using augmented profile Web
13:40:40.044 DEBUG - [Transcode] Downloading document http://127.0.0.1:32400/library/metadata/2762?checkFiles=1&includeBandwidths=1&offset=-1&X-Plex-Incomplete-Segments=1&X-Plex-Session-Identifier=ydt5omjf755ze38pwgh7b5t4
13:40:40.044 DEBUG - [Transcode] Auth: authenticated user 1 as amorpheus
13:40:40.052 DEBUG - [Transcode] It took 10.000000 ms to retrieve 138 items.
13:40:40.111 DEBUG - [Transcode] Audio Stream: 85848, Subtitle Stream: 0
13:40:40.112 DEBUG - [Transcode] Found session GUID of 9ioe0d0gbw20lh35ktpgq8v3 in session start.
13:40:40.112 DEBUG - [Transcode] Cleaning directory for session 9ioe0d0gbw20lh35ktpgq8v3 ()
13:40:40.112 DEBUG - [Transcode] Starting a transcode session 9ioe0d0gbw20lh35ktpgq8v3 at offset -1.0 (state=3)
13:40:40.113 DEBUG - [Transcode] [Universal] Using local file path instead of URL: /mnt/Pool/Movies/Movie/movie.mkv
13:40:40.113 DEBUG - [Transcode] Job running: FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/367b3d4-3673-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxxP' '/usr/lib/plexmediaserver/Plex Transcoder' '-codec:0' 'h264' '-codec:2' 'dca' '-ss' '0' '-noaccurate_seek' '-analyzeduration' '20000000' '-probesize' '20000000' '-i' '/mnt/Pool/Movies/Movie/movie.mkv' '-map' '0:0' '-metadata:s:0' 'language=ger' '-codec:0' 'copy' '-filter_complex' '[0:2] aresample=async=1:ocl='\''stereo'\'':rematrix_maxval=60.000000dB:osr=48000[0]' '-map' '[0]' '-metadata:s:1' 'language=eng' '-codec:1' 'aac' '-b:1' '256k' '-f' 'dash' '-seg_duration' '5' '-init_seg_name' 'init-stream$RepresentationID$.m4s' '-media_seg_name' 'chunk-stream$RepresentationID$-$Number%05d$.m4s' '-window_size' '5' '-delete_removed' 'false' '-skip_to_segment' '1' '-time_delta' '0.0625' '-manifest_name' 'http://127.0.0.1:32400/video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/manifest?X-Plex-Http-Pipeline=infinite' '-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/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress'
13:40:40.113 DEBUG - [Transcode] Jobs: Starting child process with pid 2631329
13:40:40.116 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=startup (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.116 DEBUG - Completed: [127.0.0.1:39352] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=startup (12 live) 0ms 203 bytes (pipelined: 1) (range: bytes=0-)
13:40:40.122 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=startup (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.123 DEBUG - Completed: [127.0.0.1:39352] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=startup (12 live) 0ms 203 bytes (pipelined: 2) (range: bytes=0-)
13:40:40.123 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=opening (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.123 DEBUG - Completed: [127.0.0.1:39352] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=opening (12 live) 0ms 203 bytes (pipelined: 3) (range: bytes=0-)
13:40:40.127 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=opened (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.127 DEBUG - Completed: [127.0.0.1:39352] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?status=opened (12 live) 0ms 203 bytes (pipelined: 4) (range: bytes=0-)
13:40:40.128 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/stream?index=0&id=0&codec=h264&type=video (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.128 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/stream?index=0&id=0&codec=h264&type=video (12 live) 0ms 195 bytes (pipelined: 5) (range: bytes=0-)
13:40:40.128 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/stream?index=1&id=0&codec=dts&type=audio (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.128 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/stream?index=1&id=0&codec=dts&type=audio (12 live) 0ms 195 bytes (pipelined: 6) (range: bytes=0-)
13:40:40.128 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/stream?index=2&id=0&codec=dts&type=audio (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.129 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/stream?index=2&id=0&codec=dts&type=audio (12 live) 0ms 195 bytes (pipelined: 7) (range: bytes=0-)
13:40:40.148 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&language=ger&width=1920&height=804&interlaced=0&sar=1:1&level=41&frameRate=23.976&disp_default=1&disp_forced=1 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.148 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&language=ger&width=1920&height=804&interlaced=0&sar=1:1&level=41&frameRate=23.976&disp_default=1&disp_forced=1 (12 live) 0ms 195 bytes (pipelined: 8) (range: bytes=0-)
13:40:40.149 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=1&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=ger&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24&disp_default=1 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.149 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=1&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=ger&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24&disp_default=1 (12 live) 0ms 195 bytes (pipelined: 9) (range: bytes=0-)
13:40:40.149 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=2&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.149 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=2&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24 (12 live) 0ms 195 bytes (pipelined: 10) (range: bytes=0-)
13:40:40.150 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=3&id=0&codec=dvd_subtitle&type=subtitle&language=ger (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.150 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=3&id=0&codec=dvd_subtitle&type=subtitle&language=ger (12 live) 0ms 195 bytes (pipelined: 11) (range: bytes=0-)
13:40:40.150 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=4&id=0&codec=dvd_subtitle&type=subtitle&language=eng (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.150 DEBUG - Completed: [127.0.0.1:39352] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress/streamDetail?index=4&id=0&codec=dvd_subtitle&type=subtitle&language=eng (12 live) 0ms 195 bytes (pipelined: 12) (range: bytes=0-)
13:40:40.159 DEBUG - Request: [127.0.0.1:39352 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?duration=8478.763000 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.159 DEBUG - [Transcode] Started session successfully: 9ioe0d0gbw20lh35ktpgq8v3
13:40:40.159 DEBUG - Completed: [127.0.0.1:39352] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/2bc65697-4352-4183-9038-6469db7fb222/progress?duration=8478.763000 (12 live) 0ms 203 bytes (pipelined: 13) (range: bytes=0-)
13:40:40.159 DEBUG - Completed: [192.168.178.31:57360] 200 GET /video/:/transcode/universal/start.mpd?hasMDE=1&path=%2Flibrary%2Fmetadata%2F2762&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=700&location=lan&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=9ioe0d0gbw20lh35ktpgq8v3&subtitles=burn&Accept-Language=en (12 live) TLS GZIP 115ms 1029 bytes (pipelined: 10)
13:40:40.169 DEBUG - Auth: authenticated user 1 as amorpheus
13:40:40.169 DEBUG - Request: [192.168.178.31:57360 (Subnet)] GET /status/sessions (12 live) TLS GZIP Signed-in Token (amorpheus)
13:40:40.169 DEBUG - [Now] Adding 0 sessions.
13:40:40.169 DEBUG - Completed: [192.168.178.31:57360] 200 GET /status/sessions (12 live) TLS GZIP 0ms 429 bytes (pipelined: 11)
13:40:40.235 DEBUG - Request: [192.168.178.31:57360 (Subnet)] GET /video/:/transcode/universal/dash/9ioe0d0gbw20lh35ktpgq8v3/1/initial.mp4 (12 live) TLS GZIP Signed-in
13:40:40.236 DEBUG - Request: [192.168.178.31:57357 (Subnet)] GET /video/:/transcode/universal/dash/9ioe0d0gbw20lh35ktpgq8v3/1/278.m4s (12 live) TLS GZIP Signed-in
13:40:40.236 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Asked for segment 278 from session.
13:40:40.240 DEBUG - Request: [192.168.178.31:57359 (Subnet)] GET /video/:/transcode/universal/dash/9ioe0d0gbw20lh35ktpgq8v3/0/278.m4s (12 live) TLS GZIP Signed-in
13:40:40.240 DEBUG - Request: [192.168.178.31:57356 (Subnet)] GET /video/:/transcode/universal/dash/9ioe0d0gbw20lh35ktpgq8v3/0/initial.mp4 (12 live) TLS GZIP Signed-in
13:40:40.240 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Asked for segment 278 from session.
13:40:40.275 DEBUG - [Transcode] Transcoder segment range: 0 - 0 (0)
13:40:40.335 DEBUG - [Transcode] Exists("/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-9ioe0d0gbw20lh35ktpgq8v3-2bc65697-4352-4183-9038-6469db7fb222/init-stream1.m4s") => 1
13:40:40.335 DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-9ioe0d0gbw20lh35ktpgq8v3-2bc65697-4352-4183-9038-6469db7fb222/init-stream1.m4s is 741 (of total: 741).
13:40:40.336 DEBUG - Completed: [192.168.178.31:57360] 200 GET /video/:/transcode/universal/dash/9ioe0d0gbw20lh35ktpgq8v3/1/initial.mp4 (12 live) TLS GZIP 100ms 741 bytes (pipelined: 12)
13:40:40.340 DEBUG - [Transcode] Exists("/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-9ioe0d0gbw20lh35ktpgq8v3-2bc65697-4352-4183-9038-6469db7fb222/init-stream0.m4s") => 1
13:40:40.340 DEBUG - Content-Length of /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-9ioe0d0gbw20lh35ktpgq8v3-2bc65697-4352-4183-9038-6469db7fb222/init-stream0.m4s is 823 (of total: 823).
13:40:40.340 DEBUG - Completed: [192.168.178.31:57356] 200 GET /video/:/transcode/universal/dash/9ioe0d0gbw20lh35ktpgq8v3/0/initial.mp4 (12 live) TLS GZIP 100ms 823 bytes (pipelined: 5)
13:40:40.368 DEBUG - [Transcode] Transcoder segment range: 0 - 1 (1)
13:40:40.436 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] We're in a seek: asked for 278, min/max available was 0/1
13:40:40.436 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Segment #278 WON.
13:40:40.436 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Killing job.
13:40:40.436 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Signalling job ID 2631329 with 9
13:40:40.436 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Job was already killed, not killing again.
13:40:40.436 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Stopping transcode session 9ioe0d0gbw20lh35ktpgq8v3
13:40:40.437 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Starting a transcode session 9ioe0d0gbw20lh35ktpgq8v3 at offset 1390.0 (state=3)
13:40:40.437 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] [Universal] Using local file path instead of URL: /mnt/Pool/Movies/Movie/movie.mkv
13:40:40.438 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Job running: FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/367b3d4-3673-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxxP' '/usr/lib/plexmediaserver/Plex Transcoder' '-codec:0' 'h264' '-codec:2' 'dca' '-ss' '1390' '-noaccurate_seek' '-analyzeduration' '20000000' '-probesize' '20000000' '-i' '/mnt/Pool/Movies/Movie/movie.mkv' '-map' '0:0' '-metadata:s:0' 'language=ger' '-codec:0' 'copy' '-filter_complex' '[0:2] aresample=async=1:ocl='\''stereo'\'':rematrix_maxval=60.000000dB:osr=48000[0]' '-map' '[0]' '-metadata:s:1' 'language=eng' '-codec:1' 'aac' '-b:1' '256k' '-f' 'dash' '-seg_duration' '5' '-init_seg_name' 'init-stream$RepresentationID$.m4s' '-media_seg_name' 'chunk-stream$RepresentationID$-$Number%05d$.m4s' '-window_size' '5' '-delete_removed' 'false' '-skip_to_segment' '279' '-time_delta' '0.0625' '-manifest_name' 'http://127.0.0.1:32400/video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/manifest?X-Plex-Http-Pipeline=infinite' '-avoid_negative_ts' 'disabled' '-map_metadata' '-1' '-map_chapters' '-1' 'dash' '-start_at_zero' '-copyts' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress'
13:40:40.438 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Jobs: Starting child process with pid 2631344
13:40:40.438 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Started session successfully: 9ioe0d0gbw20lh35ktpgq8v3
13:40:40.438 DEBUG - [Transcode/9ioe0d0gbw20lh35ktpgq8v3] Streaming Resource: Resetting play progress due to seek
13:40:40.440 DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 2631329 is -9 (signal: Killed)
13:40:40.441 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=startup (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.441 DEBUG - Completed: [127.0.0.1:39358] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=startup (12 live) 0ms 203 bytes (pipelined: 1) (range: bytes=0-)
13:40:40.442 DEBUG - Auth: authenticated user 1 as amorpheus
13:40:40.442 DEBUG - Request: [192.168.178.31:57356 (Subnet)] GET /status/sessions (12 live) TLS GZIP Signed-in Token (amorpheus)
13:40:40.442 DEBUG - [Now] Adding 0 sessions.
13:40:40.442 DEBUG - Completed: [192.168.178.31:57356] 200 GET /status/sessions (12 live) TLS GZIP 0ms 429 bytes (pipelined: 6)
13:40:40.445 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=startup (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.445 DEBUG - Completed: [127.0.0.1:39358] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=startup (12 live) 0ms 203 bytes (pipelined: 2) (range: bytes=0-)
13:40:40.445 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=opening (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.446 DEBUG - Completed: [127.0.0.1:39358] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=opening (12 live) 0ms 203 bytes (pipelined: 3) (range: bytes=0-)
13:40:40.451 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=opened (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.451 DEBUG - Completed: [127.0.0.1:39358] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?status=opened (12 live) 0ms 203 bytes (pipelined: 4) (range: bytes=0-)
13:40:40.451 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/stream?index=0&id=0&codec=h264&type=video (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.451 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/stream?index=0&id=0&codec=h264&type=video (12 live) 0ms 195 bytes (pipelined: 5) (range: bytes=0-)
13:40:40.452 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/stream?index=1&id=0&codec=dts&type=audio (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.452 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/stream?index=1&id=0&codec=dts&type=audio (12 live) 0ms 195 bytes (pipelined: 6) (range: bytes=0-)
13:40:40.452 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/stream?index=2&id=0&codec=dts&type=audio (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.452 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/stream?index=2&id=0&codec=dts&type=audio (12 live) 0ms 195 bytes (pipelined: 7) (range: bytes=0-)
13:40:40.473 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&language=ger&width=1920&height=804&interlaced=0&sar=1:1&level=41&frameRate=23.976&disp_default=1&disp_forced=1 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.474 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&language=ger&width=1920&height=804&interlaced=0&sar=1:1&level=41&frameRate=23.976&disp_default=1&disp_forced=1 (12 live) 0ms 195 bytes (pipelined: 8) (range: bytes=0-)
13:40:40.474 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=1&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=ger&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24&disp_default=1 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.474 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=1&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=ger&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24&disp_default=1 (12 live) 0ms 195 bytes (pipelined: 9) (range: bytes=0-)
13:40:40.474 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=2&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.475 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=2&id=0&codec=dts&type=audio&bitrate=1536000&profile=DTS&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&bitDepth=24 (12 live) 0ms 195 bytes (pipelined: 10) (range: bytes=0-)
13:40:40.475 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=3&id=0&codec=dvd_subtitle&type=subtitle&language=ger (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.475 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=3&id=0&codec=dvd_subtitle&type=subtitle&language=ger (12 live) 0ms 195 bytes (pipelined: 11) (range: bytes=0-)
13:40:40.475 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=4&id=0&codec=dvd_subtitle&type=subtitle&language=eng (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.475 DEBUG - Completed: [127.0.0.1:39358] 200 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress/streamDetail?index=4&id=0&codec=dvd_subtitle&type=subtitle&language=eng (12 live) 0ms 195 bytes (pipelined: 12) (range: bytes=0-)
13:40:40.480 DEBUG - Request: [127.0.0.1:39358 (Loopback)] PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?duration=8478.763000 (12 live) Signed-in Token (amorpheus) (range: bytes=0-)
13:40:40.481 DEBUG - Completed: [127.0.0.1:39358] 204 PUT /video/:/transcode/session/9ioe0d0gbw20lh35ktpgq8v3/4203c04e-cba6-48f4-a26d-35ae5f3076a9/progress?duration=8478.763000 (12 live) 0ms 203 bytes (pipelined: 13) (range: bytes=0-)
13:40:40.513 DEBUG - Auth: authenticated user 1 as amorpheus
13:40:40.513 DEBUG - Request: [192.168.178.31:57356 (Subnet)] GET /status/sessions (12 live) TLS GZIP Signed-in Token (amorpheus)
13:40:40.513 DEBUG - [Now] Adding 0 sessions.
13:40:40.513 DEBUG - Completed: [192.168.178.31:57356] 200 GET /status/sessions (12 live) TLS GZIP 0ms 429 bytes (pipelined: 7)
13:40:40.585 DEBUG - [Transcode] Transcoder segment range: 274 - 274 (274)
13:40:40.671 DEBUG - [Transcode] Transcoder segment range: 274 - 276 (276)
13:40:40.768 DEBUG - [Transcode] Transcoder segment range: 274 - 278 (278)
To me it looks like it is trying to start transcoding? Later it says something about throttling:
13:40:42.482 DEBUG - [Transcode] Session 9ioe0d0gbw20lh35ktpgq8v3 (4) is throttling
13:40:42.482 DEBUG - [Transcoder] Throttle - Going into sloth mode.
The seeking is because I’ve tried to skip to later in the file, but the behavior is the same as before.
Edit: one thing to note is that the selector in the UI keeps showing Original and doesn’t indicate any transcoding.
Could you please activate the debug log of the web app as well
(Settings - Plex Web - ‘Show Advanced’ - Debug - “Debug Level”=“enabled”)
then recreate the issue
then fetch the log both from the web app and the server (so one can see both sides).?
@amorpheus it’s curious for sure. The PlexWeb logs show direct stream playback starting then remaining in a buffering state for several minutes until being stopped. PMS logs agree. No errors on either side. The H.264 stream characteristics look pretty tame. Level 4.1, < 1080p, tame bitrate.
The only hypothesis I have is that the video stream decoding is hitting a an error. The error is either silent or not logged in a way that our log collection is expecting. It’s really unclear what is truly happening.
There’s a couple things that could be tried depending on how in the weeds you want to venture. The path of least resistance is likely to replace the file or use the Plex for Windows app.
First, the MKV can be remuxed into an MP4. The MP4 created below will play via direct stream because of the DTS audio track. The MP4 should have the same bad behavior as the MKV:
Okay, so the direct copy version still acts exactly the same. For the AAC one I’m actually getting Error code: s3015 (Media) and it throws the error right away instead of playing. I took the liberty of shortening the samples to ten seconds, let me know if that’s a problem.
I’ll try that later. Quick question, could verbose logging on the server side shed light on this?
Verbose logging on the server shouldn’t uncover anything new.
For the AAC one I’m actually getting Error code: s3015 (Media) and it throws the error right away instead of playing.
Same here, nice find! The s3015 issue was an unrelated bug. Thanks for sharing your sample files.
During playback PMS is transcoding the 6ch DTS in plex-issue-dts.mp4 file to 2ch AAC. While the 6ch AAC is being copied instead of transcoded. Chrome will direct play 6ch AAC but it won’t direct stream 6ch AAC which results in the s3015. Fixes have been submitted for review.
If you’re curious, this ffmpeg command will transcode the AAC audio stream to stereo (w/o any nice downsampling) instead of copying it. It will direct play and direct stream correctly. Apologies for forgetting the -ac 2 before.
I took the liberty of shortening the samples to ten seconds, let me know if that’s a problem.
For me the above 2ch AAC video file direct plays start to finish okay. But once direct play is disabled then all of the files are having a problem. I’m seeing a behavior where the file plays okay for 5s then video freezes for the remainder of the playback. This could be a red herring, short files sometimes play incorrectly using direct stream. But, maybe it’s not the case as the audio is continuing.
Will you please cut one addition 60s sample then see if it reproduces the infinite buffering problem? Copying the DTS audio or transcoding to AAC 2ch will get around the s3015. I’m hoping a longer clip will help our direct stream estimations.
I’m that the 60s sample repros the infinite buffering for you.
Looking back, I’m unsure precisely what caused the S3015. I was able to prevent the error by transcoding the audio to stereo. But, this is the odd part, other multichannel audio streams in movies played correctly when using direct stream.
It does, exactly how you described. Video plays for 5 seconds and then gets stuck, audio continues for the rest of the clip. As a sanity check I played the file with both VLC and the Dropbox web player, worked fine in both.
60 seconds, AAC transcoded to two channels: Dropbox - plex-issue-aac2ch.mp4 - Simplify your life
You’re welcome, as a fellow developer I’m happy to dig in to get to the bottom of this, and curious to hear more about Plex’s inner workings along the way. Also glad to be finding other bugs and helping you guys make things more robust!
Hey, anything new here? Let me know if I can help any further, or if a future PMS release should address it and I might as well close this topic for now.
that the 60s sample repros the infinite buffering for you.
