Merge pull request #1904 from JustAMan/hls-move-2

Switch ffmpeg to hls muxer (from segment) to fix premature stop on non-patched ffmpeg

(cherry picked from commit a4608141820800a068561796de3fe4e7f20e5423)
Signed-off-by: Joshua Boniface <joshua@boniface.me>

Emby.Server.Implementations/HttpServer/HttpListenerHost.cs

@@ -539,6 +539,11 @@ namespace Emby.Server.Implementations.HttpServer
             }
             finally
             {
+                if (httpRes.StatusCode >= 500)
+                {
+                    _logger.LogDebug("Sending HTTP Response 500 in response to {Url}", urlToLog);
+                }
+
                 stopWatch.Stop();
                 var elapsed = stopWatch.Elapsed;
                 if (elapsed.TotalMilliseconds > 500)

MediaBrowser.Api/Playback/BaseStreamingService.cs

@@ -289,17 +289,22 @@ namespace MediaBrowser.Api.Playback
                 throw;
             }
 
+            Logger.LogDebug("Launched ffmpeg process");
             state.TranscodingJob = transcodingJob;
 
             // Important - don't await the log task or we won't be able to kill ffmpeg when the user stops playback
             _ = new JobLogger(Logger).StartStreamingLog(state, process.StandardError.BaseStream, logStream);
 
             // Wait for the file to exist before proceeeding
-            while (!File.Exists(state.WaitForPath ?? outputPath) && !transcodingJob.HasExited)
+            var ffmpegTargetFile = state.WaitForPath ?? outputPath;
+            Logger.LogDebug("Waiting for the creation of {0}", ffmpegTargetFile);
+            while (!File.Exists(ffmpegTargetFile) && !transcodingJob.HasExited)
             {
                 await Task.Delay(100, cancellationTokenSource.Token).ConfigureAwait(false);
             }
 
+            Logger.LogDebug("File {0} created or transcoding has finished", ffmpegTargetFile);
+
             if (state.IsInputVideo && transcodingJob.Type == TranscodingJobType.Progressive && !transcodingJob.HasExited)
             {
                 await Task.Delay(1000, cancellationTokenSource.Token).ConfigureAwait(false);
@@ -314,6 +319,7 @@ namespace MediaBrowser.Api.Playback
             {
                 StartThrottler(state, transcodingJob);
             }
+            Logger.LogDebug("StartFfMpeg() finished successfully");
 
             return transcodingJob;
         }

MediaBrowser.Api/Playback/Hls/DynamicHlsService.cs

@@ -192,6 +192,7 @@ namespace MediaBrowser.Api.Playback.Hls
             if (File.Exists(segmentPath))
             {
                 job = ApiEntryPoint.Instance.OnTranscodeBeginRequest(playlistPath, TranscodingJobType);
+                Logger.LogDebug("returning {0} [it exists, try 1]", segmentPath);
                 return await GetSegmentResult(state, playlistPath, segmentPath, segmentExtension, requestedIndex, job, cancellationToken).ConfigureAwait(false);
             }
 
@@ -207,6 +208,7 @@ namespace MediaBrowser.Api.Playback.Hls
                     job = ApiEntryPoint.Instance.OnTranscodeBeginRequest(playlistPath, TranscodingJobType);
                     transcodingLock.Release();
                     released = true;
+                    Logger.LogDebug("returning {0} [it exists, try 2]", segmentPath);
                     return await GetSegmentResult(state, playlistPath, segmentPath, segmentExtension, requestedIndex, job, cancellationToken).ConfigureAwait(false);
                 }
                 else
@@ -243,6 +245,7 @@ namespace MediaBrowser.Api.Playback.Hls
 
                             request.StartTimeTicks = GetStartPositionTicks(state, requestedIndex);
 
+                            state.WaitForPath = segmentPath;
                             job = await StartFfMpeg(state, playlistPath, cancellationTokenSource).ConfigureAwait(false);
                         }
                         catch
@@ -277,7 +280,7 @@ namespace MediaBrowser.Api.Playback.Hls
             //    await Task.Delay(50, cancellationToken).ConfigureAwait(false);
             //}
 
-            Logger.LogInformation("returning {0}", segmentPath);
+            Logger.LogDebug("returning {0} [general case]", segmentPath);
             job = job ?? ApiEntryPoint.Instance.OnTranscodeBeginRequest(playlistPath, TranscodingJobType);
             return await GetSegmentResult(state, playlistPath, segmentPath, segmentExtension, requestedIndex, job, cancellationToken).ConfigureAwait(false);
         }
@@ -458,56 +461,68 @@ namespace MediaBrowser.Api.Playback.Hls
             TranscodingJob transcodingJob,
             CancellationToken cancellationToken)
         {
-            var segmentFileExists = File.Exists(segmentPath);
+            var segmentExists = File.Exists(segmentPath);
-
+            if (segmentExists)
-            // If all transcoding has completed, just return immediately
-            if (transcodingJob != null && transcodingJob.HasExited && segmentFileExists)
             {
-                return await GetSegmentResult(state, segmentPath, segmentIndex, transcodingJob).ConfigureAwait(false);
+                if (transcodingJob != null && transcodingJob.HasExited)
-            }
+                {
+                    // Transcoding job is over, so assume all existing files are ready
+                    Logger.LogDebug("serving up {0} as transcode is over", segmentPath);
+                    return await GetSegmentResult(state, segmentPath, segmentIndex, transcodingJob).ConfigureAwait(false);
+                }
 
-            if (segmentFileExists)
-            {
                 var currentTranscodingIndex = GetCurrentTranscodingIndex(playlistPath, segmentExtension);
 
                 // If requested segment is less than transcoding position, we can't transcode backwards, so assume it's ready
                 if (segmentIndex < currentTranscodingIndex)
                 {
+                    Logger.LogDebug("serving up {0} as transcode index {1} is past requested point {2}", segmentPath, currentTranscodingIndex, segmentIndex);
                     return await GetSegmentResult(state, segmentPath, segmentIndex, transcodingJob).ConfigureAwait(false);
                 }
             }
 
-            var segmentFilename = Path.GetFileName(segmentPath);
+            var nextSegmentPath = GetSegmentPath(state, playlistPath, segmentIndex + 1);
-
+            if (transcodingJob != null)
-            while (!cancellationToken.IsCancellationRequested)
             {
-                try
+                while (!cancellationToken.IsCancellationRequested && !transcodingJob.HasExited)
                 {
-                    var text = File.ReadAllText(playlistPath, Encoding.UTF8);
+                    // To be considered ready, the segment file has to exist AND
-
+                    // either the transcoding job should be done or next segment should also exist
-                    // If it appears in the playlist, it's done
+                    if (segmentExists)
-                    if (text.IndexOf(segmentFilename, StringComparison.OrdinalIgnoreCase) != -1)
                     {
-                        if (!segmentFileExists)
+                        if (transcodingJob.HasExited || File.Exists(nextSegmentPath))
-                        {
-                            segmentFileExists = File.Exists(segmentPath);
-                        }
-                        if (segmentFileExists)
                         {
+                            Logger.LogDebug("serving up {0} as it deemed ready", segmentPath);
                             return await GetSegmentResult(state, segmentPath, segmentIndex, transcodingJob).ConfigureAwait(false);
                         }
-                        //break;
                     }
-                }
+                    else
-                catch (IOException)
+                    {
-                {
+                        segmentExists = File.Exists(segmentPath);
-                    // May get an error if the file is locked
+                        if (segmentExists)
+                        {
+                            continue; // avoid unnecessary waiting if segment just became available
+                        }
+                    }
+
+                    await Task.Delay(100, cancellationToken).ConfigureAwait(false);
                 }
 
-                await Task.Delay(100, cancellationToken).ConfigureAwait(false);
+                if (!File.Exists(segmentPath))
+                {
+                    Logger.LogWarning("cannot serve {0} as transcoding quit before we got there", segmentPath);
+                }
+                else
+                {
+                    Logger.LogDebug("serving {0} as it's on disk and transcoding stopped", segmentPath);
+                }
+                cancellationToken.ThrowIfCancellationRequested();
+            }
+            else
+            {
+                Logger.LogWarning("cannot serve {0} as it doesn't exist and no transcode is running", segmentPath);
             }
 
-            cancellationToken.ThrowIfCancellationRequested();
             return await GetSegmentResult(state, segmentPath, segmentIndex, transcodingJob).ConfigureAwait(false);
         }
 
@@ -521,6 +536,7 @@ namespace MediaBrowser.Api.Playback.Hls
                 FileShare = FileShareMode.ReadWrite,
                 OnComplete = () =>
                 {
+                    Logger.LogDebug("finished serving {0}", segmentPath);
                     if (transcodingJob != null)
                     {
                         transcodingJob.DownloadPositionTicks = Math.Max(transcodingJob.DownloadPositionTicks ?? segmentEndingPositionTicks, segmentEndingPositionTicks);
@@ -909,9 +925,23 @@ namespace MediaBrowser.Api.Playback.Hls
             else
             {
                 var keyFrameArg = string.Format(
+                    CultureInfo.InvariantCulture,
                     " -force_key_frames:0 \"expr:gte(t,{0}+n_forced*{1})\"",
                     GetStartNumber(state) * state.SegmentLength,
-                    state.SegmentLength.ToString(CultureInfo.InvariantCulture));
+                    state.SegmentLength);
+                if (state.TargetFramerate.HasValue)
+                {
+                    // This is to make sure keyframe interval is limited to our segment,
+                    // as forcing keyframes is not enough.
+                    // Example: we encoded half of desired length, then codec detected
+                    // scene cut and inserted a keyframe; next forced keyframe would
+                    // be created outside of segment, which breaks seeking.
+                    keyFrameArg += string.Format(
+                        CultureInfo.InvariantCulture,
+                        " -g {0} -keyint_min {0}",
+                        (int)(state.SegmentLength * state.TargetFramerate)
+                    );
+                }
 
                 var hasGraphicalSubs = state.SubtitleStream != null && !state.SubtitleStream.IsTextSubtitleStream && state.SubtitleDeliveryMethod == SubtitleDeliveryMethod.Encode;
 
@@ -955,6 +985,15 @@ namespace MediaBrowser.Api.Playback.Hls
 
             var threads = EncodingHelper.GetNumberOfThreads(state, encodingOptions, videoCodec);
 
+            if (state.BaseRequest.BreakOnNonKeyFrames)
+            {
+                // FIXME: this is actually a workaround, as ideally it really should be the client which decides whether non-keyframe
+                //        breakpoints are supported; but current implementation always uses "ffmpeg input seeking" which is liable
+                //        to produce a missing part of video stream before first keyframe is encountered, which may lead to
+                //        awkward cases like a few starting HLS segments having no video whatsoever, which breaks hls.js
+                Logger.LogInformation("Current HLS implementation doesn't support non-keyframe breaks but one is requested, ignoring that request");
+                state.BaseRequest.BreakOnNonKeyFrames = false;
+            }
             var inputModifier = EncodingHelper.GetInputModifier(state, encodingOptions);
 
             // If isEncoding is true we're actually starting ffmpeg
@@ -965,14 +1004,6 @@ namespace MediaBrowser.Api.Playback.Hls
 
             var outputTsArg = Path.Combine(Path.GetDirectoryName(outputPath), Path.GetFileNameWithoutExtension(outputPath)) + "%d" + GetSegmentFileExtension(state.Request);
 
-            var timeDeltaParam = string.Empty;
-
-            if (isEncoding && state.TargetFramerate > 0)
-            {
-                float startTime = 1 / (state.TargetFramerate.Value * 2);
-                timeDeltaParam = string.Format(CultureInfo.InvariantCulture, "-segment_time_delta {0:F3}", startTime);
-            }
-
             var segmentFormat = GetSegmentFileExtension(state.Request).TrimStart('.');
             if (string.Equals(segmentFormat, "ts", StringComparison.OrdinalIgnoreCase))
             {
@@ -980,7 +1011,7 @@ namespace MediaBrowser.Api.Playback.Hls
             }
 
             return string.Format(
-                "{0} {1} -map_metadata -1 -map_chapters -1 -threads {2} {3} {4} {5} -f segment -max_delay 5000000 -avoid_negative_ts disabled -start_at_zero -segment_time {6} {10} -individual_header_trailer 0 -segment_format {11} -segment_list_type m3u8 -segment_start_number {7} -segment_list \"{8}\" -y \"{9}\"",
+                "{0} {1} -map_metadata -1 -map_chapters -1 -threads {2} {3} {4} {5} -f hls -max_delay 5000000 -avoid_negative_ts disabled -start_at_zero -hls_time {6} -individual_header_trailer 0 -hls_segment_type {7} -start_number {8} -hls_segment_filename \"{9}\" -hls_playlist_type vod -hls_list_size 0 -y \"{10}\"",
                 inputModifier,
                 EncodingHelper.GetInputArgument(state, encodingOptions),
                 threads,
@@ -988,11 +1019,10 @@ namespace MediaBrowser.Api.Playback.Hls
                 GetVideoArguments(state, encodingOptions),
                 GetAudioArguments(state, encodingOptions),
                 state.SegmentLength.ToString(CultureInfo.InvariantCulture),
+                segmentFormat,
                 startNumberParam,
-                outputPath,
                 outputTsArg,
-                timeDeltaParam,
+                outputPath
-                segmentFormat
             ).Trim();
         }
     }

MediaBrowser.Controller/MediaEncoding/EncodingHelper.cs

@@ -2168,7 +2168,8 @@ namespace MediaBrowser.Controller.MediaEncoding
                 // Important: If this is ever re-enabled, make sure not to use it with wtv because it breaks seeking
                 if (!string.Equals(state.InputContainer, "wtv", StringComparison.OrdinalIgnoreCase)
                     && state.TranscodingType != TranscodingJobType.Progressive
-                    && state.EnableBreakOnNonKeyFrames(outputVideoCodec))
+                    && !state.EnableBreakOnNonKeyFrames(outputVideoCodec)
+                    && (state.BaseRequest.StartTimeTicks ?? 0) > 0)
                 {
                     inputModifier += " -noaccurate_seek";
                 }