add playback troubleshooting logs (#2475)

CHANGELOG.md

@@ -65,6 +65,9 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 - Add `Stream Selector` option to playback troubleshooting tool
   - This can be helpful for validating stream selector behavior with specific content
   - Manual subtitle selection will be disabled when using a stream selector
+- Add basic log viewer to playback troubleshooting tool
+  - Streaming log level will be forced to `Debug` during troubleshooting
+  - Streaming log level will be restored to its previous value after troubleshooting completes
 
 ### Fixed
 - Fix green output when libplacebo tonemapping is used with NVIDIA acceleration and 10-bit output in FFmpeg Profile

ErsatzTV.Application/Troubleshooting/Commands/PrepareTroubleshootingPlayback.cs

@@ -5,6 +5,7 @@ using ErsatzTV.Core.Interfaces.FFmpeg;
 namespace ErsatzTV.Application.Troubleshooting;
 
 public record PrepareTroubleshootingPlayback(
+    Guid SessionId,
     StreamingMode StreamingMode,
     int MediaItemId,
     int FFmpegProfileId,

ErsatzTV.Application/Troubleshooting/Commands/PrepareTroubleshootingPlaybackHandler.cs

@@ -18,6 +18,8 @@ using ErsatzTV.Infrastructure.Data;
 using ErsatzTV.Infrastructure.Extensions;
 using Microsoft.EntityFrameworkCore;
 using Microsoft.Extensions.Logging;
+using Serilog.Context;
+using Serilog.Events;
 
 namespace ErsatzTV.Application.Troubleshooting;
 
@@ -32,6 +34,7 @@ public class PrepareTroubleshootingPlaybackHandler(
     IWatermarkSelector watermarkSelector,
     IEntityLocker entityLocker,
     IMediator mediator,
+    LoggingLevelSwitches loggingLevelSwitches,
     ILogger<PrepareTroubleshootingPlaybackHandler> logger)
     : IRequestHandler<PrepareTroubleshootingPlayback, Either<BaseError, PlayoutItemResult>>
 {
@@ -39,8 +42,12 @@ public class PrepareTroubleshootingPlaybackHandler(
         PrepareTroubleshootingPlayback request,
         CancellationToken cancellationToken)
     {
+        var currentStreamingLevel = loggingLevelSwitches.StreamingLevelSwitch.MinimumLevel;
+        loggingLevelSwitches.StreamingLevelSwitch.MinimumLevel = LogEventLevel.Debug;
+
         try
         {
+            using var logContext = LogContext.PushProperty(InMemoryLogService.CorrelationIdKey, request.SessionId);
             await using TvContext dbContext = await dbContextFactory.CreateDbContextAsync(cancellationToken);
             Validation<BaseError, Tuple<MediaItem, string, string, FFmpegProfile>> validation = await Validate(
                 dbContext,
@@ -64,6 +71,10 @@ public class PrepareTroubleshootingPlaybackHandler(
             logger.LogError(ex, "Error while preparing troubleshooting playback");
             return BaseError.New(ex.Message);
         }
+        finally
+        {
+            loggingLevelSwitches.StreamingLevelSwitch.MinimumLevel = currentStreamingLevel;
+        }
     }
 
     private async Task<Either<BaseError, PlayoutItemResult>> GetProcess(

ErsatzTV.Application/Troubleshooting/Commands/StartTroubleshootingPlaybackHandler.cs

@@ -11,6 +11,8 @@ using ErsatzTV.Core.Interfaces.Troubleshooting;
 using ErsatzTV.Core.Notifications;
 using ErsatzTV.FFmpeg.Runtime;
 using Microsoft.Extensions.Logging;
+using Serilog.Context;
+using Serilog.Events;
 
 namespace ErsatzTV.Application.Troubleshooting;
 
@@ -20,6 +22,8 @@ public class StartTroubleshootingPlaybackHandler(
     IEntityLocker entityLocker,
     IRuntimeInfo runtimeInfo,
     IGraphicsEngine graphicsEngine,
+    InMemoryLogService logService,
+    LoggingLevelSwitches loggingLevelSwitches,
     ILogger<StartTroubleshootingPlaybackHandler> logger)
     : IRequestHandler<StartTroubleshootingPlayback>
 {
@@ -32,8 +36,13 @@ public class StartTroubleshootingPlaybackHandler(
 
     public async Task Handle(StartTroubleshootingPlayback request, CancellationToken cancellationToken)
     {
+        var currentStreamingLevel = loggingLevelSwitches.StreamingLevelSwitch.MinimumLevel;
+        loggingLevelSwitches.StreamingLevelSwitch.MinimumLevel = LogEventLevel.Debug;
+
         try
         {
+            using var logContext = LogContext.PushProperty(InMemoryLogService.CorrelationIdKey, request.SessionId);
+
             // write media info without title
             string infoJson = JsonSerializer.Serialize(request.MediaItemInfo with { Title = null }, Options);
             await File.WriteAllTextAsync(
@@ -129,6 +138,20 @@ public class StartTroubleshootingPlaybackHandler(
                     .WithValidation(CommandResultValidation.None)
                     .ExecuteAsync(linkedCts.Token);
 
+                try
+                {
+                    IEnumerable<string> logs = logService.Sink.GetLogs(request.SessionId);
+                    await File.WriteAllLinesAsync(
+                        Path.Combine(FileSystemLayout.TranscodeTroubleshootingFolder, "logs.txt"),
+                        logs,
+                        linkedCts.Token);
+                    logService.Sink.ClearLogs(request.SessionId);
+                }
+                catch (Exception)
+                {
+                    // do nothing
+                }
+
                 await mediator.Publish(
                     new PlaybackTroubleshootingCompletedNotification(commandResult.ExitCode),
                     linkedCts.Token);
@@ -160,6 +183,7 @@ public class StartTroubleshootingPlaybackHandler(
         finally
         {
             entityLocker.UnlockTroubleshootingPlayback();
+            loggingLevelSwitches.StreamingLevelSwitch.MinimumLevel = currentStreamingLevel;
         }
     }
 }

ErsatzTV.Core/InMemoryLogService.cs

@@ -0,0 +1,46 @@
+using Serilog.Core;
+using Serilog.Events;
+using System.Collections.Concurrent;
+using System.Globalization;
+
+namespace ErsatzTV.Core;
+
+public class InMemorySink : ILogEventSink
+{
+    private readonly ConcurrentDictionary<Guid, ConcurrentQueue<string>> _logs = new();
+
+    public void Emit(LogEvent logEvent)
+    {
+        if (logEvent.Properties.TryGetValue(InMemoryLogService.CorrelationIdKey, out var correlationIdValue) &&
+            correlationIdValue is ScalarValue { Value: Guid correlationId })
+        {
+            ConcurrentQueue<string> logQueue = _logs.GetOrAdd(correlationId, _ => new ConcurrentQueue<string>());
+
+            string message = logEvent.RenderMessage(CultureInfo.CurrentCulture);
+            logQueue.Enqueue($"[{logEvent.Timestamp:HH:mm:ss} {logEvent.Level}] {message}");
+
+            while (logQueue.Count > 100)
+            {
+                logQueue.TryDequeue(out _);
+            }
+        }
+    }
+
+    public IEnumerable<string> GetLogs(Guid correlationId)
+    {
+        _logs.TryGetValue(correlationId, out ConcurrentQueue<string> logs);
+        return logs ?? Enumerable.Empty<string>();
+    }
+
+    public void ClearLogs(Guid correlationId)
+    {
+        _logs.TryRemove(correlationId, out _);
+    }
+}
+
+public class InMemoryLogService
+{
+    public InMemorySink Sink { get; } = new();
+
+    public static readonly string CorrelationIdKey = "CorrelationId";
+}

ErsatzTV/Controllers/Api/TroubleshootController.cs

@@ -10,6 +10,7 @@ using ErsatzTV.Core.Interfaces.Metadata;
 using ErsatzTV.Core.Interfaces.Troubleshooting;
 using MediatR;
 using Microsoft.AspNetCore.Mvc;
+using Serilog.Context;
 
 namespace ErsatzTV.Controllers.Api;
 
@@ -41,12 +42,16 @@ public class TroubleshootController(
         int seekSeconds,
         CancellationToken cancellationToken)
     {
+        var sessionId = Guid.NewGuid();
+        using var logContext = LogContext.PushProperty(InMemoryLogService.CorrelationIdKey, sessionId);
+
         try
         {
             Option<int> ss = seekSeconds > 0 ? seekSeconds : Option<int>.None;
 
             Either<BaseError, PlayoutItemResult> result = await mediator.Send(
                 new PrepareTroubleshootingPlayback(
+                    sessionId,
                     streamingMode,
                     mediaItem,
                     ffmpegProfile,
@@ -68,8 +73,6 @@ public class TroubleshootController(
                     await mediator.Send(new GetMediaItemInfo(mediaItem), cancellationToken);
                 foreach (MediaItemInfo mediaInfo in maybeMediaInfo.RightToSeq())
                 {
-                    var sessionId = Guid.NewGuid();
-
                     try
                     {
                         TroubleshootingInfo troubleshootingInfo = await mediator.Send(

ErsatzTV/Pages/PlaybackTroubleshooting.razor

@@ -6,6 +6,7 @@
 @using ErsatzTV.Application.Troubleshooting
 @using ErsatzTV.Application.Troubleshooting.Queries
 @using ErsatzTV.Application.Watermarks
+@using ErsatzTV.Core.Interfaces.Metadata
 @using ErsatzTV.Core.Notifications
 @using MediatR.Courier
 @using Microsoft.AspNetCore.WebUtilities
@@ -16,6 +17,7 @@
 @inject IEntityLocker Locker
 @inject ICourier Courier;
 @inject ISnackbar Snackbar;
+@inject ILocalFileSystem LocalFileSystem;
 
 <MudForm Style="max-height: 100%">
     <MudPaper Square="true" Style="display: flex; height: 64px; min-height: 64px; width: 100%; z-index: 100; align-items: center">
@@ -46,6 +48,15 @@
             </MudStack>
             <MudText Typo="Typo.h5" Class="mt-10 mb-2">Playback Settings</MudText>
             <MudDivider Class="mb-6"/>
+            <MudStack Row="true" Breakpoint="Breakpoint.SmAndDown" Class="form-field-stack gap-md-8 mb-5">
+                <div class="d-flex">
+                    <MudText>Streaming Mode</MudText>
+                </div>
+                <MudSelect @bind-Value="_streamingMode" For="@(() => _streamingMode)">
+                    <MudSelectItem Value="@(StreamingMode.HttpLiveStreamingSegmenter)">HLS Segmenter</MudSelectItem>
+                    <MudSelectItem Value="@(StreamingMode.HttpLiveStreamingSegmenterFmp4)">HLS Segmenter (fmp4)</MudSelectItem>
+                </MudSelect>
+            </MudStack>
             <MudStack Row="true" Breakpoint="Breakpoint.SmAndDown" Class="form-field-stack gap-md-8 mb-5">
                 <div class="d-flex">
                     <MudText>FFmpeg Profile</MudText>
@@ -68,15 +79,6 @@
                     }
                 </MudSelect>
             </MudStack>
-            <MudStack Row="true" Breakpoint="Breakpoint.SmAndDown" Class="form-field-stack gap-md-8 mb-5">
-                <div class="d-flex">
-                    <MudText>Streaming Mode</MudText>
-                </div>
-                <MudSelect @bind-Value="_streamingMode" For="@(() => _streamingMode)">
-                    <MudSelectItem Value="@(StreamingMode.HttpLiveStreamingSegmenter)">HLS Segmenter</MudSelectItem>
-                    <MudSelectItem Value="@(StreamingMode.HttpLiveStreamingSegmenterFmp4)">HLS Segmenter (fmp4)</MudSelectItem>
-                </MudSelect>
-            </MudStack>
             <MudStack Row="true" Breakpoint="Breakpoint.SmAndDown" Class="form-field-stack gap-md-8 mb-5">
                 <div class="d-flex">
                     <MudText>Subtitle</MudText>
@@ -150,6 +152,11 @@
                 </media-controller>
                 <div class="d-none d-md-flex" style="width: 400px"></div>
             </div>
+            <MudText Typo="Typo.h5" Class="mt-10 mb-2">Logs</MudText>
+            <MudDivider Class="mb-6"/>
+            <MudStack Row="true" Breakpoint="Breakpoint.SmAndDown" Class="gap-md-8 mb-5">
+                <MudTextField @bind-Value="_logs" ReadOnly="true" Lines="20" Variant="Variant.Outlined" />
+            </MudStack>
             <div class="mb-6">
                 <br/>
                 <br/>
@@ -176,6 +183,7 @@
     private int? _subtitleId;
     private int _seekSeconds;
     private bool _hasPlayed;
+    private string _logs;
 
     [SupplyParameterFromQuery(Name = "mediaItem")]
     public int? MediaItemId { get; set; }
@@ -240,6 +248,8 @@
 
     private async Task PreviewChannel()
     {
+        _logs = null;
+
         var baseUri = NavigationManager.ToAbsoluteUri(NavigationManager.Uri).ToString();
         string apiUri = baseUri.Replace("/system/troubleshooting/playback", "/api/troubleshoot/playback.m3u8");
         var queryString = new Dictionary<string, string>
@@ -312,7 +322,6 @@
 
     private async Task DownloadResults()
     {
-        string apiUri = "api/troubleshoot/playback/archive";
         var queryString = new Dictionary<string, string>
         {
             ["mediaItem"] = (MediaItemId ?? 0).ToString(),
@@ -337,12 +346,14 @@
             }
         }
 
-        string uriWithQuery = QueryHelpers.AddQueryString(apiUri, queryString);
+        string uriWithQuery = QueryHelpers.AddQueryString("api/troubleshoot/playback/archive", queryString);
         await JsRuntime.InvokeVoidAsync("window.open", uriWithQuery);
     }
 
     private void HandleTroubleshootingCompleted(PlaybackTroubleshootingCompletedNotification result)
     {
+        _logs = null;
+
         if (result.ExitCode == 0)
         {
             Snackbar.Add("FFmpeg troubleshooting process exited successfully", Severity.Success);
@@ -351,6 +362,13 @@
         {
             Snackbar.Add($"FFmpeg troubleshooting process exited with code {result.ExitCode}", Severity.Warning);
         }
+
+        string logFileName = Path.Combine(FileSystemLayout.TranscodeTroubleshootingFolder, "logs.txt");
+        if (LocalFileSystem.FileExists(logFileName))
+        {
+            _logs = File.ReadAllText(logFileName);
+            InvokeAsync(StateHasChanged);
+        }
     }
 
 }

ErsatzTV/Program.cs

@@ -35,12 +35,15 @@ public class Program
             .Build();
 
         LoggingLevelSwitches = new LoggingLevelSwitches();
+        InMemoryLogService = new InMemoryLogService();
     }
 
     private static IConfiguration Configuration { get; }
 
     private static LoggingLevelSwitches LoggingLevelSwitches { get; }
 
+    internal static InMemoryLogService InMemoryLogService { get; }
+
     public static async Task<int> Main(string[] args)
     {
         using var _ = new Mutex(
@@ -94,6 +97,7 @@ public class Program
             .MinimumLevel.Override("Serilog.AspNetCore.RequestLoggingMiddleware", LoggingLevelSwitches.HttpLevelSwitch)
             .Destructure.UsingAttributes()
             .Enrich.FromLogContext()
+            .WriteTo.Sink(InMemoryLogService.Sink)
             .WriteTo.File(
                 FileSystemLayout.LogFilePath,
                 rollingInterval: RollingInterval.Day,

ErsatzTV/Startup.cs

@@ -683,6 +683,7 @@ public class Startup
         services.AddSingleton<ITroubleshootingNotifier, TroubleshootingNotifier>();
         services.AddSingleton<CustomFontMapper>();
         services.AddSingleton<GraphicsEngineFonts>();
+        services.AddSingleton(Program.InMemoryLogService);
 
         if (SearchHelper.IsElasticSearchEnabled)
         {