From f1dd01f6d570215043cd00c93c7868c37bbe0d9c Mon Sep 17 00:00:00 2001 From: Josh Patra Date: Sat, 7 Feb 2026 23:11:48 -0500 Subject: [PATCH] refactor: reduce log spam by adjusting log levels - Change WebSocket logs to Debug/Trace (connection events, message proxying) - Change session management logs to Debug (creation, removal, capabilities) - Change auth header forwarding logs to Debug - Change playback forwarding logs to Debug - Change 401 responses to Debug (expected when tokens expire) - Keep Info level for significant business events (external playback, downloads) - Keep Warning/Error for actual issues This significantly reduces log noise while maintaining visibility of important events. --- allstarr/Controllers/JellyfinController.cs | 42 +++++++++++-------- .../Middleware/WebSocketProxyMiddleware.cs | 20 ++++++--- .../Services/Jellyfin/JellyfinProxyService.cs | 25 +++++++---- .../Jellyfin/JellyfinSessionManager.cs | 34 ++++++++------- 4 files changed, 75 insertions(+), 46 deletions(-) diff --git a/allstarr/Controllers/JellyfinController.cs b/allstarr/Controllers/JellyfinController.cs index 4a5d907..209bdfe 100644 --- a/allstarr/Controllers/JellyfinController.cs +++ b/allstarr/Controllers/JellyfinController.cs @@ -2183,7 +2183,7 @@ public class JellyfinController : ControllerBase var method = Request.Method; var queryString = Request.QueryString.HasValue ? Request.QueryString.Value : ""; - _logger.LogInformation("πŸ“‘ Session capabilities reported - Method: {Method}, Query: {Query}", method, queryString); + _logger.LogDebug("πŸ“‘ Session capabilities reported - Method: {Method}, Query: {Query}", method, queryString); _logger.LogInformation("Headers: {Headers}", string.Join(", ", Request.Headers.Where(h => h.Key.Contains("Auth", StringComparison.OrdinalIgnoreCase) || h.Key.Contains("Device", StringComparison.OrdinalIgnoreCase) || h.Key.Contains("Client", StringComparison.OrdinalIgnoreCase)) .Select(h => $"{h.Key}={h.Value}"))); @@ -2208,7 +2208,11 @@ public class JellyfinController : ControllerBase if (statusCode == 204 || statusCode == 200) { - _logger.LogInformation("βœ“ Session capabilities forwarded to Jellyfin ({StatusCode})", statusCode); + _logger.LogDebug("βœ“ Session capabilities forwarded to Jellyfin ({StatusCode})", statusCode); + } + else if (statusCode == 401) + { + _logger.LogDebug("⚠ Jellyfin returned 401 for capabilities (token expired)"); } else { @@ -2242,7 +2246,7 @@ public class JellyfinController : ControllerBase } Request.Body.Position = 0; - _logger.LogInformation("πŸ“» Playback START reported"); + _logger.LogDebug("πŸ“» Playback START reported"); // Parse the body to check if it's an external track var doc = JsonDocument.Parse(body); @@ -2318,7 +2322,7 @@ public class JellyfinController : ControllerBase if (ghostStatusCode == 204 || ghostStatusCode == 200) { - _logger.LogInformation("βœ“ Ghost playback start forwarded to Jellyfin for external track ({StatusCode})", ghostStatusCode); + _logger.LogDebug("βœ“ Ghost playback start forwarded to Jellyfin for external track ({StatusCode})", ghostStatusCode); } else { @@ -2346,7 +2350,7 @@ public class JellyfinController : ControllerBase } // For local tracks, forward playback start to Jellyfin FIRST - _logger.LogInformation("Forwarding playback start to Jellyfin..."); + _logger.LogDebug("Forwarding playback start to Jellyfin..."); // Fetch full item details to include in playback report try @@ -2372,7 +2376,7 @@ public class JellyfinController : ControllerBase if (statusCode == 204 || statusCode == 200) { - _logger.LogInformation("βœ“ Playback start forwarded to Jellyfin ({StatusCode})", statusCode); + _logger.LogDebug("βœ“ Playback start forwarded to Jellyfin ({StatusCode})", statusCode); // NOW ensure session exists with capabilities (after playback is reported) if (!string.IsNullOrEmpty(deviceId)) @@ -2380,7 +2384,7 @@ public class JellyfinController : ControllerBase var sessionCreated = await _sessionManager.EnsureSessionAsync(deviceId, client ?? "Unknown", device ?? "Unknown", version ?? "1.0", Request.Headers); if (sessionCreated) { - _logger.LogWarning("βœ“ SESSION: Session ensured for device {DeviceId} after playback start", deviceId); + _logger.LogDebug("βœ“ SESSION: Session ensured for device {DeviceId} after playback start", deviceId); } else { @@ -2404,7 +2408,7 @@ public class JellyfinController : ControllerBase var (result, statusCode) = await _proxyService.PostJsonAsync("Sessions/Playing", body, Request.Headers); if (statusCode == 204 || statusCode == 200) { - _logger.LogInformation("βœ“ Basic playback start forwarded to Jellyfin ({StatusCode})", statusCode); + _logger.LogDebug("βœ“ Basic playback start forwarded to Jellyfin ({StatusCode})", statusCode); } } } @@ -2517,7 +2521,7 @@ public class JellyfinController : ControllerBase // Only log at 10-second intervals if (position.Seconds % 10 == 0 && position.Milliseconds < 500) { - _logger.LogInformation("▢️ Progress: {Position:mm\\:ss} for item {ItemId}", position, itemId); + _logger.LogDebug("▢️ Progress: {Position:mm\\:ss} for item {ItemId}", position, itemId); } } } @@ -2557,7 +2561,7 @@ public class JellyfinController : ControllerBase } Request.Body.Position = 0; - _logger.LogInformation("⏹️ Playback STOPPED reported"); + _logger.LogDebug("⏹️ Playback STOPPED reported"); // Parse the body to check if it's an external track var doc = JsonDocument.Parse(body); @@ -2615,7 +2619,7 @@ public class JellyfinController : ControllerBase if (stopStatusCode == 204 || stopStatusCode == 200) { - _logger.LogInformation("βœ“ Ghost playback stop forwarded to Jellyfin ({StatusCode})", stopStatusCode); + _logger.LogDebug("βœ“ Ghost playback stop forwarded to Jellyfin ({StatusCode})", stopStatusCode); } return NoContent(); @@ -2626,7 +2630,7 @@ public class JellyfinController : ControllerBase } // For local tracks, forward to Jellyfin - _logger.LogInformation("Forwarding playback stop to Jellyfin..."); + _logger.LogDebug("Forwarding playback stop to Jellyfin..."); // Log the body being sent for debugging _logger.LogInformation("πŸ“€ Sending playback stop body: {Body}", body); @@ -2649,7 +2653,11 @@ public class JellyfinController : ControllerBase if (statusCode == 204 || statusCode == 200) { - _logger.LogInformation("βœ“ Playback stop forwarded to Jellyfin ({StatusCode})", statusCode); + _logger.LogDebug("βœ“ Playback stop forwarded to Jellyfin ({StatusCode})", statusCode); + } + else if (statusCode == 401) + { + _logger.LogDebug("Playback stop returned 401 (token expired)"); } else { @@ -2708,7 +2716,7 @@ public class JellyfinController : ControllerBase var queryString = Request.QueryString.HasValue ? Request.QueryString.Value : ""; var endpoint = string.IsNullOrEmpty(path) ? $"Sessions{queryString}" : $"Sessions/{path}{queryString}"; - _logger.LogInformation("πŸ”„ Proxying session request: {Method} {Endpoint}", method, endpoint); + _logger.LogDebug("πŸ”„ Proxying session request: {Method} {Endpoint}", method, endpoint); _logger.LogDebug("Session proxy headers: {Headers}", string.Join(", ", Request.Headers.Where(h => h.Key.Contains("Auth", StringComparison.OrdinalIgnoreCase)) .Select(h => $"{h.Key}={h.Value}"))); @@ -2738,11 +2746,11 @@ public class JellyfinController : ControllerBase if (result != null) { - _logger.LogInformation("βœ“ Session request proxied successfully ({StatusCode})", statusCode); + _logger.LogDebug("βœ“ Session request proxied successfully ({StatusCode})", statusCode); return new JsonResult(result.RootElement.Clone()); } - _logger.LogInformation("βœ“ Session request proxied ({StatusCode}, no body)", statusCode); + _logger.LogDebug("βœ“ Session request proxied ({StatusCode}, no body)", statusCode); return StatusCode(statusCode); } catch (Exception ex) @@ -2800,7 +2808,7 @@ public class JellyfinController : ControllerBase if (path.Contains("session", StringComparison.OrdinalIgnoreCase) || path.Contains("capabilit", StringComparison.OrdinalIgnoreCase)) { - _logger.LogWarning("πŸ” SESSION/CAPABILITY REQUEST: {Method} /{Path}{Query}", Request.Method, path, Request.QueryString); + _logger.LogDebug("πŸ” SESSION/CAPABILITY REQUEST: {Method} /{Path}{Query}", Request.Method, path, Request.QueryString); } else { diff --git a/allstarr/Middleware/WebSocketProxyMiddleware.cs b/allstarr/Middleware/WebSocketProxyMiddleware.cs index ddf7679..705cdcc 100644 --- a/allstarr/Middleware/WebSocketProxyMiddleware.cs +++ b/allstarr/Middleware/WebSocketProxyMiddleware.cs @@ -54,7 +54,7 @@ public class WebSocketProxyMiddleware if (context.Request.Path.StartsWithSegments("/socket", StringComparison.OrdinalIgnoreCase) && context.WebSockets.IsWebSocketRequest) { - _logger.LogInformation("πŸ”Œ WEBSOCKET: WebSocket connection request received from {RemoteIp}", + _logger.LogDebug("πŸ”Œ WEBSOCKET: WebSocket connection request received from {RemoteIp}", context.Connection.RemoteIpAddress); await HandleWebSocketProxyAsync(context); @@ -142,7 +142,7 @@ public class WebSocketProxyMiddleware serverWebSocket.Options.SetRequestHeader("User-Agent", "Allstarr/1.0"); await serverWebSocket.ConnectAsync(new Uri(jellyfinWsUrl), context.RequestAborted); - _logger.LogInformation("βœ“ WEBSOCKET: Connected to Jellyfin WebSocket"); + _logger.LogDebug("βœ“ WEBSOCKET: Connected to Jellyfin WebSocket"); // Start bidirectional proxying var clientToServer = ProxyMessagesAsync(clientWebSocket, serverWebSocket, "Clientβ†’Server", context.RequestAborted); @@ -155,7 +155,15 @@ public class WebSocketProxyMiddleware } catch (WebSocketException wsEx) { - _logger.LogWarning(wsEx, "⚠️ WEBSOCKET: WebSocket error: {Message}", wsEx.Message); + // 403 is expected when tokens expire or session ends - don't spam logs + if (wsEx.Message.Contains("403")) + { + _logger.LogDebug("WEBSOCKET: Connection rejected with 403 (token expired or session ended)"); + } + else + { + _logger.LogWarning(wsEx, "⚠️ WEBSOCKET: WebSocket error: {Message}", wsEx.Message); + } } catch (Exception ex) { @@ -194,7 +202,7 @@ public class WebSocketProxyMiddleware // CRITICAL: Notify session manager that client disconnected if (!string.IsNullOrEmpty(deviceId)) { - _logger.LogInformation("🧹 WEBSOCKET: Client disconnected, removing session for device {DeviceId}", deviceId); + _logger.LogDebug("🧹 WEBSOCKET: Client disconnected, removing session for device {DeviceId}", deviceId); await _sessionManager.RemoveSessionAsync(deviceId); } @@ -239,7 +247,7 @@ public class WebSocketProxyMiddleware if (direction == "Serverβ†’Client") { var messageText = System.Text.Encoding.UTF8.GetString(messageBytes); - _logger.LogInformation("πŸ“₯ WEBSOCKET {Direction}: {Preview}", + _logger.LogTrace("πŸ“₯ WEBSOCKET {Direction}: {Preview}", direction, messageText.Length > 500 ? messageText[..500] + "..." : messageText); } @@ -274,7 +282,7 @@ public class WebSocketProxyMiddleware } catch (Exception ex) { - _logger.LogWarning(ex, "⚠️ WEBSOCKET {Direction}: Error proxying messages", direction); + _logger.LogDebug(ex, "WEBSOCKET {Direction}: Error proxying messages (connection closed)", direction); } } } diff --git a/allstarr/Services/Jellyfin/JellyfinProxyService.cs b/allstarr/Services/Jellyfin/JellyfinProxyService.cs index f4c34b1..aa0d02c 100644 --- a/allstarr/Services/Jellyfin/JellyfinProxyService.cs +++ b/allstarr/Services/Jellyfin/JellyfinProxyService.cs @@ -179,7 +179,7 @@ public class JellyfinProxyService var headerValue = header.Value.ToString(); request.Headers.TryAddWithoutValidation("X-Emby-Authorization", headerValue); authHeaderAdded = true; - _logger.LogInformation("βœ“ Forwarded X-Emby-Authorization: {Value}", headerValue); + _logger.LogDebug("βœ“ Forwarded X-Emby-Authorization: {Value}", headerValue); break; } } @@ -201,14 +201,14 @@ public class JellyfinProxyService // Forward as X-Emby-Authorization (Jellyfin's expected header) request.Headers.TryAddWithoutValidation("X-Emby-Authorization", headerValue); authHeaderAdded = true; - _logger.LogInformation("βœ“ Converted Authorization to X-Emby-Authorization: {Value}", headerValue); + _logger.LogDebug("βœ“ Converted Authorization to X-Emby-Authorization: {Value}", headerValue); } else { // Standard Bearer token - forward as-is request.Headers.TryAddWithoutValidation("Authorization", headerValue); authHeaderAdded = true; - _logger.LogInformation("βœ“ Forwarded Authorization (Bearer): {Value}", headerValue); + _logger.LogDebug("βœ“ Forwarded Authorization (Bearer): {Value}", headerValue); } break; } @@ -248,7 +248,7 @@ public class JellyfinProxyService { if (response.StatusCode == System.Net.HttpStatusCode.Unauthorized) { - _logger.LogWarning("Jellyfin returned 401 Unauthorized for {Url} - passing through to client", url); + _logger.LogDebug("Jellyfin returned 401 Unauthorized for {Url} - passing through to client", url); } else if (!isBrowserStaticRequest) // Don't log 404s for browser static requests { @@ -372,8 +372,17 @@ public class JellyfinProxyService if (!response.IsSuccessStatusCode) { var errorContent = await response.Content.ReadAsStringAsync(); - _logger.LogWarning("❌ SESSION: Jellyfin POST request failed: {StatusCode} for {Url}. Response: {Response}", - response.StatusCode, url, errorContent); + + // 401 is expected when tokens expire - don't spam logs + if (response.StatusCode == System.Net.HttpStatusCode.Unauthorized) + { + _logger.LogDebug("SESSION: Jellyfin POST request returned 401 for {Url} (token expired)", url); + } + else + { + _logger.LogWarning("❌ SESSION: Jellyfin POST request failed: {StatusCode} for {Url}. Response: {Response}", + response.StatusCode, url, errorContent); + } // Try to parse error response as JSON to pass through to client if (!string.IsNullOrWhiteSpace(errorContent)) @@ -395,7 +404,7 @@ public class JellyfinProxyService // Log successful session-related responses if (endpoint.Contains("Sessions", StringComparison.OrdinalIgnoreCase)) { - _logger.LogWarning("βœ“ SESSION: Jellyfin responded {StatusCode} for {Endpoint}", statusCode, endpoint); + _logger.LogDebug("βœ“ SESSION: Jellyfin responded {StatusCode} for {Endpoint}", statusCode, endpoint); } // Handle 204 No Content responses (e.g., /sessions/playing, /sessions/playing/progress) @@ -416,7 +425,7 @@ public class JellyfinProxyService if (endpoint.Contains("Sessions", StringComparison.OrdinalIgnoreCase) && !string.IsNullOrWhiteSpace(responseContent)) { var preview = responseContent.Length > 200 ? responseContent[..200] + "..." : responseContent; - _logger.LogWarning("πŸ“₯ SESSION: Jellyfin response body: {Body}", preview); + _logger.LogTrace("πŸ“₯ SESSION: Jellyfin response body: {Body}", preview); } return (JsonDocument.Parse(responseContent), statusCode); diff --git a/allstarr/Services/Jellyfin/JellyfinSessionManager.cs b/allstarr/Services/Jellyfin/JellyfinSessionManager.cs index 9c8cc98..596919f 100644 --- a/allstarr/Services/Jellyfin/JellyfinSessionManager.cs +++ b/allstarr/Services/Jellyfin/JellyfinSessionManager.cs @@ -58,7 +58,7 @@ public class JellyfinSessionManager : IDisposable return true; } - _logger.LogInformation("πŸ”§ SESSION: Creating new session for device: {DeviceId} ({Client} on {Device})", deviceId, client, device); + _logger.LogDebug("πŸ”§ SESSION: Creating new session for device: {DeviceId} ({Client} on {Device})", deviceId, client, device); // Log the headers we received for debugging _logger.LogDebug("πŸ” SESSION: Headers received for session creation: {Headers}", @@ -69,7 +69,7 @@ public class JellyfinSessionManager : IDisposable // Post session capabilities to Jellyfin - this creates the session await PostCapabilitiesAsync(headers); - _logger.LogInformation("βœ“ SESSION: Session created for {DeviceId}", deviceId); + _logger.LogDebug("βœ“ SESSION: Session created for {DeviceId}", deviceId); // Track this session _sessions[deviceId] = new SessionInfo @@ -120,10 +120,14 @@ public class JellyfinSessionManager : IDisposable { _logger.LogDebug("βœ“ SESSION: Posted capabilities successfully ({StatusCode})", statusCode); } + else if (statusCode == 401) + { + // Token expired - this is expected, don't spam logs + _logger.LogDebug("SESSION: Capabilities returned 401 (token expired, will use fresh headers on next request)"); + } else { - // 401 is common when cached headers have expired - not a critical error - _logger.LogDebug("SESSION: Capabilities post returned {StatusCode} (may be expected if token expired)", statusCode); + _logger.LogDebug("SESSION: Capabilities post returned {StatusCode}", statusCode); } } @@ -178,7 +182,7 @@ public class JellyfinSessionManager : IDisposable if (_sessions.TryGetValue(deviceId, out var currentSession) && currentSession.LastActivity <= markedTime) { - _logger.LogInformation("🧹 SESSION: Auto-removing inactive session {DeviceId} after playback stop", deviceId); + _logger.LogDebug("🧹 SESSION: Auto-removing inactive session {DeviceId} after playback stop", deviceId); await RemoveSessionAsync(deviceId); } else @@ -223,7 +227,7 @@ public class JellyfinSessionManager : IDisposable { if (_sessions.TryRemove(deviceId, out var session)) { - _logger.LogInformation("πŸ—‘οΈ SESSION: Removing session for device {DeviceId}", deviceId); + _logger.LogDebug("πŸ—‘οΈ SESSION: Removing session for device {DeviceId}", deviceId); // Close WebSocket if it exists if (session.WebSocket != null && session.WebSocket.State == WebSocketState.Open) @@ -235,7 +239,7 @@ public class JellyfinSessionManager : IDisposable } catch (Exception ex) { - _logger.LogWarning(ex, "⚠️ WEBSOCKET: Error closing WebSocket for {DeviceId}", deviceId); + _logger.LogDebug(ex, "WEBSOCKET: Error closing WebSocket for {DeviceId}", deviceId); } finally { @@ -255,7 +259,7 @@ public class JellyfinSessionManager : IDisposable }; var stopJson = JsonSerializer.Serialize(stopPayload); await _proxyService.PostJsonAsync("Sessions/Playing/Stopped", stopJson, session.Headers); - _logger.LogInformation("πŸ›‘ SESSION: Reported playback stopped for {DeviceId} (ItemId: {ItemId}, Position: {Position})", + _logger.LogDebug("πŸ›‘ SESSION: Reported playback stopped for {DeviceId} (ItemId: {ItemId}, Position: {Position})", deviceId, session.LastPlayingItemId, session.LastPlayingPositionTicks); } @@ -339,11 +343,11 @@ public class JellyfinSessionManager : IDisposable if (!string.IsNullOrEmpty(_settings.ApiKey)) { jellyfinWsUrl += $"?api_key={_settings.ApiKey}"; - _logger.LogWarning("⚠️ WEBSOCKET: No client auth found in headers, falling back to server API key for {DeviceId}", deviceId); + _logger.LogDebug("WEBSOCKET: No client auth found in headers, falling back to server API key for {DeviceId}", deviceId); } else { - _logger.LogWarning("❌ WEBSOCKET: No authentication available for {DeviceId}!", deviceId); + _logger.LogWarning("❌ WEBSOCKET: No authentication available for {DeviceId} - WebSocket will fail", deviceId); } } @@ -354,7 +358,7 @@ public class JellyfinSessionManager : IDisposable // Connect to Jellyfin await webSocket.ConnectAsync(new Uri(jellyfinWsUrl), CancellationToken.None); - _logger.LogInformation("βœ“ WEBSOCKET: Connected to Jellyfin for device {DeviceId}", deviceId); + _logger.LogDebug("βœ“ WEBSOCKET: Connected to Jellyfin for device {DeviceId}", deviceId); // CRITICAL: Send ForceKeepAlive message to initialize session in Jellyfin // This tells Jellyfin to create/show the session in the dashboard @@ -410,8 +414,8 @@ public class JellyfinSessionManager : IDisposable } else { - // Log other message types at info level - _logger.LogInformation("πŸ“₯ WEBSOCKET: {DeviceId}: {Message}", + // Log other message types at trace level + _logger.LogTrace("πŸ“₯ WEBSOCKET: {DeviceId}: {Message}", deviceId, message.Length > 100 ? message[..100] + "..." : message); } } @@ -433,7 +437,7 @@ public class JellyfinSessionManager : IDisposable } catch (WebSocketException wsEx) { - _logger.LogWarning(wsEx, "⚠️ WEBSOCKET: WebSocket error for device {DeviceId}", deviceId); + _logger.LogDebug(wsEx, "WEBSOCKET: Connection closed for device {DeviceId}", deviceId); break; } } @@ -502,7 +506,7 @@ public class JellyfinSessionManager : IDisposable var staleSessions = _sessions.Where(kvp => now - kvp.Value.LastActivity > TimeSpan.FromMinutes(3)).ToList(); foreach (var stale in staleSessions) { - _logger.LogInformation("🧹 SESSION: Removing stale session for {DeviceId} (inactive for {Minutes:F1} minutes)", + _logger.LogDebug("🧹 SESSION: Removing stale session for {DeviceId} (inactive for {Minutes:F1} minutes)", stale.Key, (now - stale.Value.LastActivity).TotalMinutes); await RemoveSessionAsync(stale.Key); }