Playback stops when transcoding is complete/buffer is full

[BMStroh 3]

I've been consistently seeing an issue where all my video playback stops in the web client as soon as transcoding is complete and the browser buffer is full.

 

Playback settings - 1.7x speed due a Chrome plugin; transcode to 480p - 420kbps to reduce bandwidth demands.

 

Tailing logs during playback, it appears that as soon as the ffmpeg-transcode-<guid>.txt log completes with something along this line:

 

[segment @ 0x1d3f5c0] Opening '/var/lib/emby/transcoding-temp/af8679954083af33273fff7eaf08773f.m3u8.tmp' for writing
SegmentComplete=video:0 Index=850 Start=2550.548000 End=2552.841967 Duration=2.293967 offset_pts=0 start_pts=-1744419296 Frames=55 filename=af8679954083af33273fff7eaf08773f850.ts
elapsed=00:00:52.85 frame=13375 fps=253 q=28.0 Lsize=   20319kB time=00:42:32.98 bitrate=  65.2kbits/s throttle=off speed=48.3x
video:12125kB audio:8195kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.000000%
T=71.835s
Local Time: 10:25:14
[libx264 @ 0x1d41e80] frame I:186   Avg QP:18.81  size:  8188
[libx264 @ 0x1d41e80] frame P:4538  Avg QP:22.77  size:  1873
[libx264 @ 0x1d41e80] frame B:8651  Avg QP:25.88  size:   276
[libx264 @ 0x1d41e80] consecutive B-frames: 10.5%  7.6%  6.2% 75.7%
[libx264 @ 0x1d41e80] mb I  I16..4: 19.3%  0.0% 80.7%
[libx264 @ 0x1d41e80] mb P  I16..4:  9.1%  0.0%  0.0%  P16..4: 49.4%  0.0%  0.0%  0.0%  0.0%    skip:41.5%
[libx264 @ 0x1d41e80] mb B  I16..4:  0.5%  0.0%  0.0%  B16..8: 12.8%  0.0%  0.0%  direct: 3.5%  skip:83.2%  L0:31.2% L1:46.0% BI:22.8%
[libx264 @ 0x1d41e80] coded y,uvDC,uvAC intra: 57.2% 48.5% 18.9% inter: 9.2% 4.7% 0.1%
[libx264 @ 0x1d41e80] i16 v,h,dc,p: 47% 21% 16% 16%
[libx264 @ 0x1d41e80] i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 29% 19% 11%  8%  7%  7%  6%  6%  7%
[libx264 @ 0x1d41e80] i8c dc,h,v,p: 44% 18% 29%  9%
[libx264 @ 0x1d41e80] Weighted P-Frames: Y:2.6% UV:1.4%
[libx264 @ 0x1d41e80] kb/s:178.04

 

The server appears to throw a 500 and browser playback stops until I restart playback from the beginning.

 

2019-07-03 10:15:35.052 Info App: ProcessRun 'StreamTranscode cf330f' Process exited with code 0
2019-07-03 10:15:35.052 Info App: FFMpeg exited with code 0
2019-07-03 10:15:35.063 Info App: returning /var/lib/emby/transcoding-temp/ba5c2ba86738126f62a8d9608bd528a8850.ts
2019-07-03 10:15:35.064 Info HttpServer: HTTP Response 200 to 192.168.128.43. Time: 120ms. http://server.local:8096/emby/videos/25222/hls1/main/850.ts?DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTRfNSkgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzczLjAuMzY4My4xMDMgU2FmYXJpLzUzNy4zNnwxNTU0NDkzNDY5ODIz&MediaSourceId=6938aca3b57e2f38427bf9944755bc8d&PlaySessionId=33604afc022c48998022746c8a3edf66&VideoCodec=h264&AudioCodec=mp3,aac&VideoBitrate=303318&AudioBitrate=116682&AudioStreamIndex=1&TranscodingMaxAudioChannels=2&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&TranscodeReasons=ContainerBitrateExceedsLimit
2019-07-03 10:15:35.114 Info HttpServer: HTTP GET http://server.local:8096/emby/videos/25222/hls1/main/851.ts?DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTRfNSkgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzczLjAuMzY4My4xMDMgU2FmYXJpLzUzNy4zNnwxNTU0NDkzNDY5ODIz&MediaSourceId=6938aca3b57e2f38427bf9944755bc8d&PlaySessionId=33604afc022c48998022746c8a3edf66&VideoCodec=h264&AudioCodec=mp3,aac&VideoBitrate=303318&AudioBitrate=116682&AudioStreamIndex=1&TranscodingMaxAudioChannels=2&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&TranscodeReasons=ContainerBitrateExceedsLimit. Host=server.local:8096, Connection=keep-alive, User-Agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.100 Safari/537.36, Accept=*/*, Referer=http://server.local:8096/web/index.html, Accept-Encoding=gzip, deflate, Accept-Language=en-US,en;q=0.9
2019-07-03 10:15:35.121 Info App: ProcessRun 'StreamTranscode 02ffe5' Execute: /opt/emby-server/bin/ffmpeg -ss 00:42:33.000  -f mp4 -i file:"/Brent/TV/iZombie/Season 1/iZombie - 1x13 - Blaine's World.mp4" -threads 1 -map 0:0 -map 0:1 -map -0:s -c:v:0 libx264 -filter_complex "[0:0]scale=trunc(min(max(iw\,ih*dar)\,426)/2)*2:trunc(ow/dar/2)*2" -pix_fmt yuv420p  -maxrate 303318 -bufsize 606636 -preset veryfast -profile:v:0 high -level:v:0 4.1 -crf 23 -x264opts:0 subme=0:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none -g:v:0 72 -keyint_min:v:0 72 -sc_threshold:v:0 0  -copyts -vsync -1 -codec:a:0 copy -disposition:a:0 default -f segment -max_delay 5000000 -avoid_negative_ts disabled -map_metadata -1 -map_chapters -1 -start_at_zero -segment_time 3  -individual_header_trailer 0 -segment_format mpegts -segment_write_temp 1 -segment_list_type m3u8 -segment_start_number 851 -segment_list "/var/lib/emby/transcoding-temp/ba5c2ba86738126f62a8d9608bd528a8.m3u8" -y "/var/lib/emby/transcoding-temp/ba5c2ba86738126f62a8d9608bd528a8%d.ts"
2019-07-03 10:15:35.160 Info App: ProcessRun 'StreamTranscode 02ffe5' Started.
2019-07-03 10:15:35.515 Info App: ProcessRun 'StreamTranscode 02ffe5' Process exited with code 0
2019-07-03 10:15:35.528 Error HttpServer: Error processing request
        *** Error Report ***
        Version: 4.1.1.0
        Command line: /opt/emby-server/system/EmbyServer.dll -programdata /var/lib/emby -ffdetect /opt/emby-server/bin/ffdetect -ffmpeg /opt/emby-server/bin/ffmpeg -ffprobe /opt/emby-server/bin/ffprobe -restartexitcode 3 -updatepackage emby-server-deb_{version}_amd64.deb
        Operating system: Unix 4.15.0.54
        64-Bit OS: True
        64-Bit Process: True
        User Interactive: True
        Runtime: file:///opt/emby-server/system/System.Private.CoreLib.dll
        Processor count: 2
        Program data path: /var/lib/emby
        Application directory: /opt/emby-server/system
        System.Exception: System.Exception: Error starting ffmpeg
           at Emby.Server.MediaEncoding.Api.BaseStreamingService.StartFfMpeg(StreamState state, String outputPath, EncodingOptions encodingOptions, EncodingDiagnosticOptions encodingDiagnosticOptions, CancellationTokenSource cancellationTokenSource, Boolean acquireResources)
           at Emby.Server.MediaEncoding.Api.Hls.DynamicHlsService.GetDynamicSegment(StreamRequest request, String playlistId, String segmentId, Int32 subtitleStreamIndex)
           at Emby.Server.Implementations.Services.ServiceExecGeneral.GetTaskResult(Task task)
           at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost appHost, IRequest httpReq, IResponse httpRes, ILogger logger, String operationName, CancellationToken cancellationToken)
           at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IRequest httpReq, String urlString, String host, String localPath, CancellationToken cancellationToken)
        Source: Emby.Server.MediaEncoding
        TargetSite: Void MoveNext()

2019-07-03 10:15:35.528 Info HttpServer: HTTP Response 500 to 192.168.128.43. Time: 414ms. http://server.local:8096/emby/videos/25222/hls1/main/851.ts?DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTRfNSkgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzczLjAuMzY4My4xMDMgU2FmYXJpLzUzNy4zNnwxNTU0NDkzNDY5ODIz&MediaSourceId=6938aca3b57e2f38427bf9944755bc8d&PlaySessionId=33604afc022c48998022746c8a3edf66&VideoCodec=h264&AudioCodec=mp3,aac&VideoBitrate=303318&AudioBitrate=116682&AudioStreamIndex=1&TranscodingMaxAudioChannels=2&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&TranscodeReasons=ContainerBitrateExceedsLimit

I've reset the web client to Auto - Direct and playback has worked consistently/normally.

embyserver.txt

ffmpeg-transcode-a4feca19-a9d2-46c4-8de1-2b04cb89214f_1.txt

Edited July 3, 2019 by BMStroh

[Luke 37020]

Hi there, can you please attach the complete emby server and ffmpeg logs? thanks.

[BMStroh 3]

Full logs attached.

[BMStroh 3]

Any sort of workaround available here?  If I kick the bitrate high enough that the buffer stays roughly in sync with the playback, I don't get the errors/aborts, but that also chews through a ton of data pretty quickly when I'm streaming remotely, so it's not a long term solution, unfortunately.

 

Thanks for any suggestions.

[Luke 37020]

Hi, if you remove the Chrome plugin, how does that compare?

[BMStroh 3]

Only one video file of test results so far, but I've actually made it to the end of a show without a hang/error after turning on transcode throttling on the server side.  I assume that the throttling prevents the buffer from filling up on the client well before the end of playback.

 

If I start seeing hangs again, even with throttling turned on, I'll reduce playback speed and report back.

 

Thanks for the quick followup and the extra direction.

[Luke 37020]

Thanks for the feedback.

[BMStroh 3]

Limited testing so far, but it appears to be speed related - I got hangs at every speed from 1.7x down to 1.2x; I did just complete an episode at 1.1x.  Normal speed seems to be okay as well.

 

Any additional info I can capture in logs to help narrow down where the 500 error is coming from, server side?  The logged URLs don't appear to be useful to test with since the authorization has expired, so I can't get much that way.  I haven't found any way to log SQL in SQLite either, so I'm not sure what else I can get that would be useful to you.

[Luke 37020]

Right now we're not testing what you're doing so at this point I don't have answers for you. I can only guess that video player is catching up to the position of the transcoding process and thus you end up having to wait.

[BMStroh 3]

I think it's actually the other way around - as soon as transcoding completes and the web player buffer is filled (grey line extends to the end of the video, is well past the green "current position" dot) playback dies because the server kicks back an HTTP 500 instead of an HTTP 204 like usual.  Transcoding is complete and well ahead of playback, but somehow, the browser request (I assume to update playback position) immediately after the last piece is cached blows up.

[Luke 37020]

There's an issue with some videos ending early that has been resolved for the next release. Sounds like that's what it is.

[BMStroh 3]

Based on your response, did some Googling and some math - does appear to be related to the reported problem with playback aborting when the video hits the "mark watched" percentage.  I've pushed that up from 90% to something a bit higher, so if it hangs, it will be in the credits, not the show, but I'm looking forward to the new release.

 

Thanks!

[BMStroh 3]

Updated to the 4.2.0.34 beta and I can confirm that this appears to be resolved.  

 

Did have to rework some SQL in my status sync scripts due to the new join with UserDataKeys2, but playback has worked without error on several episodes in a row.

[Luke 37020]

Thanks for the feedback.

[BMStroh 3]

This may be back in 4.2.1.0 - I've seen several playback stops with a 500 in the logs.  Going to do a bit more digging and grab the latest beta to see if it changes the behavior.

[Luke 37020]

I've seen several playback stops with a 500 in the logs.

Hi, just be aware that this by itself doesn't indicate any sort of problem. Thanks.