add some temporary debug logging (#925)

ErsatzTV.Application/Streaming/Commands/StartFFmpegSessionHandler.cs

@@ -1,4 +1,5 @@
-using ErsatzTV.Core;
+using System.Diagnostics;
+using ErsatzTV.Core;
 using ErsatzTV.Core.Domain;
 using ErsatzTV.Core.Errors;
 using ErsatzTV.Core.FFmpeg;
@@ -78,26 +79,48 @@ public class StartFFmpegSessionHandler : IRequestHandler<StartFFmpegSession, Eit
         IHlsSessionWorker worker,
         CancellationToken cancellationToken)
     {
-        DateTimeOffset start = DateTimeOffset.Now;
+        var sw = Stopwatch.StartNew();
-        DateTimeOffset finish = start.AddSeconds(8);
+        try
-    
-        while (!File.Exists(playlistFileName))
         {
-            await Task.Delay(TimeSpan.FromMilliseconds(100), cancellationToken);
+            DateTimeOffset start = DateTimeOffset.Now;
-        }
+            DateTimeOffset finish = start.AddSeconds(8);
 
-        var segmentCount = 0;
+            _logger.LogDebug("Waiting for playlist to exist");
-        while (DateTimeOffset.Now < finish && segmentCount < initialSegmentCount)
+            while (!File.Exists(playlistFileName))
-        {
+            {
-            await Task.Delay(TimeSpan.FromMilliseconds(200), cancellationToken);
+                await Task.Delay(TimeSpan.FromMilliseconds(100), cancellationToken);
+            }
 
-            DateTimeOffset now = DateTimeOffset.Now.AddSeconds(-30);
+            _logger.LogDebug("Playlist exists");
-            Option<TrimPlaylistResult> maybeResult = await worker.TrimPlaylist(now, cancellationToken);
+
-            foreach (TrimPlaylistResult result in maybeResult)
+            var segmentCount = 0;
+            var lastSegmentCount = -1;
+            while (DateTimeOffset.Now < finish && segmentCount < initialSegmentCount)
             {
-                segmentCount = result.SegmentCount;
+                if (segmentCount != lastSegmentCount)
+                {
+                    lastSegmentCount = segmentCount;
+                    _logger.LogDebug(
+                        "Segment count {SegmentCount} of {InitialSegmentCount}",
+                        segmentCount,
+                        initialSegmentCount);
+                }
+
+                await Task.Delay(TimeSpan.FromMilliseconds(200), cancellationToken);
+
+                DateTimeOffset now = DateTimeOffset.Now.AddSeconds(-30);
+                Option<TrimPlaylistResult> maybeResult = await worker.TrimPlaylist(now, cancellationToken);
+                foreach (TrimPlaylistResult result in maybeResult)
+                {
+                    segmentCount = result.SegmentCount;
+                }
             }
         }
+        finally
+        {
+            sw.Stop();
+            _logger.LogDebug("WaitForPlaylistSegments took {Duration}", sw.Elapsed);
+        }
     }
 
     private Task<Validation<BaseError, Unit>> Validate(StartFFmpegSession request) =>

ErsatzTV.Application/Streaming/HlsSessionWorker.cs

@@ -1,4 +1,5 @@
-using System.Text;
+using System.Diagnostics;
+using System.Text;
 using System.Timers;
 using Bugsnag;
 using CliWrap;
@@ -64,6 +65,7 @@ public class HlsSessionWorker : IHlsSessionWorker
         DateTimeOffset filterBefore,
         CancellationToken cancellationToken)
     {
+        var sw = Stopwatch.StartNew();
         await Slim.WaitAsync(cancellationToken);
         try
         {
@@ -85,6 +87,8 @@ public class HlsSessionWorker : IHlsSessionWorker
         finally
         {
             Slim.Release();
+            sw.Stop();
+            _logger.LogDebug("TrimPlaylist took {Duration}", sw.Elapsed);
         }
     }
 

ErsatzTV/Controllers/IptvController.cs

@@ -124,16 +124,25 @@ public class IptvController : ControllerBase
     [HttpGet("iptv/session/{channelNumber}/hls.m3u8")]
     public async Task<IActionResult> GetLivePlaylist(string channelNumber, CancellationToken cancellationToken)
     {
+        _logger.LogDebug("Checking for session worker for channel {Channel}", channelNumber);
+        
         if (_ffmpegSegmenterService.SessionWorkers.TryGetValue(channelNumber, out IHlsSessionWorker worker))
         {
+            _logger.LogDebug("Trimming playlist for channel {Channel}", channelNumber);
+
             DateTimeOffset now = DateTimeOffset.Now.AddSeconds(-30);
             Option<TrimPlaylistResult> maybePlaylist = await worker.TrimPlaylist(now, cancellationToken);
             foreach (TrimPlaylistResult result in maybePlaylist)
             {
                 return Content(result.Playlist, "application/vnd.apple.mpegurl");
             }
+
+            // TODO: better error here?
+            _logger.LogWarning("Trim playlist failure; will return not found for channel {Channel}", channelNumber);
+            return NotFound();
         }
 
+        _logger.LogWarning("Unable to locate session worker for channel {Channel}", channelNumber);
         return NotFound();
     }
 
@@ -166,14 +175,24 @@ public class IptvController : ControllerBase
         switch (mode)
         {
             case "segmenter":
+                _logger.LogDebug("Maybe starting ffmpeg session for channel {Channel}", channelNumber);
                 Either<BaseError, Unit> result = await _mediator.Send(new StartFFmpegSession(channelNumber, false));
                 return result.Match<IActionResult>(
-                    _ => Redirect($"/iptv/session/{channelNumber}/hls.m3u8"),
+                    _ =>
+                    {
+                        _logger.LogDebug(
+                            "Session started; redirecting to session for channel {Channel}",
+                            channelNumber);
+                        return Redirect($"/iptv/session/{channelNumber}/hls.m3u8");
+                    },
                     error =>
                     {
                         switch (error)
                         {
                             case ChannelSessionAlreadyActive:
+                                _logger.LogDebug(
+                                    "Session is already active; redirecting to session for channel {Channel}",
+                                    channelNumber);
                                 return RedirectPreserveMethod($"/iptv/session/{channelNumber}/hls.m3u8");
                             default:
                                 _logger.LogWarning(