add slow api logging for jellyfin

CHANGELOG.md

@@ -35,8 +35,10 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 - Add `Target Loudness` (LUFS/LKFS) to ffmpeg profile when loudness normalization is enabled
   - Default value is `-16`; some sources normalize to a quieter value, e.g. `-24`
 - Add environment variables to help troubleshoot performance
-  - `ETV_SLOW_QUERY_MS` - milliseconds threshold for logging slow database queries (at DEBUG level)
+  - `ETV_SLOW_DB_MS` - milliseconds threshold for logging slow database queries (at DEBUG level)
     - e.g. if this is set to `1000`, queries taking longer than 1 second will be logged
+  - `ETV_SLOW_API_MS` - milliseconds threshold for logging slow API calls (at DEBUG level)
+    - This is currently limited to *Jellyfin*
 
 ### Fixed
 - Fix startup on systems unsupported by NvEncSharp

ErsatzTV.Core/SystemEnvironment.cs

@@ -37,10 +37,16 @@ public class SystemEnvironment
 
         MaximumUploadMb = maximumUploadMb;
 
-        string slowQueryMsVariable = Environment.GetEnvironmentVariable("ETV_SLOW_QUERY_MS");
-        if (int.TryParse(slowQueryMsVariable, out int slowQueryMs))
+        string slowDbMsVariable = Environment.GetEnvironmentVariable("ETV_SLOW_DB_MS");
+        if (int.TryParse(slowDbMsVariable, out int slowDbMs))
         {
-            SlowQueryMs = slowQueryMs;
+            SlowDbMs = slowDbMs;
+        }
+
+        string slowApiMsVariable = Environment.GetEnvironmentVariable("ETV_SLOW_API_MS");
+        if (int.TryParse(slowApiMsVariable, out int slowApiMs))
+        {
+            SlowApiMs = slowApiMs;
         }
     }
 
@@ -51,5 +57,6 @@ public class SystemEnvironment
     public static int StreamingPort { get; }
     public static bool AllowSharedPlexServers { get; }
     public static int MaximumUploadMb { get; }
-    public static int? SlowQueryMs { get; }
+    public static int? SlowDbMs { get; }
+    public static int? SlowApiMs { get; }
 }

ErsatzTV.Infrastructure/Jellyfin/JellyfinApiClient.cs

@@ -15,6 +15,7 @@ namespace ErsatzTV.Infrastructure.Jellyfin;
 public class JellyfinApiClient : IJellyfinApiClient
 {
     private readonly IFallbackMetadataProvider _fallbackMetadataProvider;
+    private readonly IHttpClientFactory _httpClientFactory;
     private readonly IJellyfinPathReplacementService _jellyfinPathReplacementService;
     private readonly ILogger<JellyfinApiClient> _logger;
     private readonly IMemoryCache _memoryCache;
@@ -23,11 +24,13 @@ public class JellyfinApiClient : IJellyfinApiClient
         IMemoryCache memoryCache,
         IJellyfinPathReplacementService jellyfinPathReplacementService,
         IFallbackMetadataProvider fallbackMetadataProvider,
+        IHttpClientFactory httpClientFactory,
         ILogger<JellyfinApiClient> logger)
     {
         _memoryCache = memoryCache;
         _jellyfinPathReplacementService = jellyfinPathReplacementService;
         _fallbackMetadataProvider = fallbackMetadataProvider;
+        _httpClientFactory = httpClientFactory;
         _logger = logger;
     }
 
@@ -37,7 +40,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             var cts = new CancellationTokenSource();
             cts.CancelAfter(TimeSpan.FromSeconds(5));
             return await service.GetSystemInformation(apiKey, cts.Token)
@@ -59,7 +62,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             List<JellyfinLibraryResponse> libraries = await service.GetLibraries(apiKey);
             return libraries
                 .Map(Project)
@@ -189,7 +192,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             JellyfinPlaybackInfoResponse playbackInfo = await service.GetPlaybackInfo(apiKey, itemId);
             Option<MediaVersion> maybeVersion = ProjectToMediaVersion(playbackInfo);
             return maybeVersion.ToEither(() => BaseError.New("Unable to locate Jellyfin statistics"));
@@ -209,7 +212,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             JellyfinLibraryItemsResponse itemsResponse = await service.GetShowLibraryItems(
                 apiKey,
                 parentId: library.ItemId,
@@ -240,7 +243,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             JellyfinSearchHintsResponse searchResponse = await service.SearchHints(
                 apiKey,
                 showTitle,
@@ -281,7 +284,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         }
     }
 
-    private static async IAsyncEnumerable<Tuple<TItem, int>> GetPagedLibraryItems<TItem>(
+    private async IAsyncEnumerable<Tuple<TItem, int>> GetPagedLibraryItems<TItem>(
         string address,
         Option<JellyfinLibrary> maybeLibrary,
         int mediaSourceId,
@@ -289,7 +292,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         Func<IJellyfinApi, string, int, int, Task<JellyfinLibraryItemsResponse>> getItems,
         Func<Option<JellyfinLibrary>, JellyfinLibraryItemResponse, Option<TItem>> mapper)
     {
-        IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+        IJellyfinApi service = ServiceForAddress(address);
 
         const int PAGE_SIZE = 10;
 
@@ -1043,4 +1046,11 @@ public class JellyfinApiClient : IJellyfinApiClient
             return version;
         });
     }
+
+    private IJellyfinApi ServiceForAddress(string address)
+    {
+        var client = _httpClientFactory.CreateClient("RefitCustomClient");
+        client.BaseAddress = new Uri(address);
+        return RestService.For<IJellyfinApi>(client);
+    }
 }

ErsatzTV/SlowApiHandler.cs

@@ -0,0 +1,38 @@
+using ErsatzTV.Core;
+
+namespace ErsatzTV;
+
+using System.Diagnostics;
+
+public class SlowApiHandler : DelegatingHandler
+{
+    protected override async Task<HttpResponseMessage> SendAsync(
+        HttpRequestMessage request,
+        CancellationToken cancellationToken)
+    {
+        if (SystemEnvironment.SlowApiMs > 0)
+        {
+            var stopwatch = Stopwatch.StartNew();
+
+            var response = await base.SendAsync(request, cancellationToken);
+
+            stopwatch.Stop();
+
+            if (stopwatch.ElapsedMilliseconds > SystemEnvironment.SlowApiMs.Value)
+            {
+                string uri = request.RequestUri?.ToString() ?? "Unknown URI";
+                string method = request.Method.Method;
+
+                Serilog.Log.Logger.Debug(
+                    "[SLOW API] {Method} {Uri} took {Milliseconds}ms",
+                    method,
+                    uri,
+                    stopwatch.ElapsedMilliseconds);
+            }
+
+            return response;
+        }
+
+        return await base.SendAsync(request, cancellationToken);
+    }
+}

ErsatzTV/Startup.cs

@@ -409,9 +409,9 @@ public class Startup
         string mySqlConnectionString = Configuration.GetValue<string>("MySql:ConnectionString");
 
         SlowQueryInterceptor interceptor = null;
-        if (SystemEnvironment.SlowQueryMs.HasValue)
+        if (SystemEnvironment.SlowDbMs.HasValue)
         {
-            interceptor = new SlowQueryInterceptor(SystemEnvironment.SlowQueryMs.Value);
+            interceptor = new SlowQueryInterceptor(SystemEnvironment.SlowDbMs.Value);
         }
 
         services.AddDbContext<TvContext>(
@@ -525,6 +525,8 @@ public class Startup
                 c.DefaultRequestHeaders.Add("User-Agent", $"ErsatzTV/{etvVersion}");
             });
 
+        services.AddHttpClient("RefitCustomClient").AddHttpMessageHandler<SlowApiHandler>();
+
         services.Configure<TraktConfiguration>(Configuration.GetSection("Trakt"));
 
         services.AddResponseCompression(options => { options.EnableForHttps = true; });
@@ -867,6 +869,8 @@ public class Startup
 
         // services.AddTransient(typeof(IRequestHandler<,>), typeof(GetRecentLogEntriesHandler<>));
 
+        services.AddTransient<SlowApiHandler>();
+
         // run-once/blocking startup services
         services.AddHostedService<EndpointValidatorService>();
         services.AddHostedService<DatabaseMigratorService>();