joshpatra/allstarr
1
0
Fork 0
mirror of https://github.com/SoPat712/allstarr.git synced 2026-02-09 23:55:10 -05:00
Code Issues Actions 2 Packages Projects Releases Wiki Activity

refactor: reduce log spam by adjusting log levels

Browse Source 
- 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.
This commit is contained in:
Josh Patra
2026-02-07 23:11:48 -05:00
parent 6c06c59f61
commit f1dd01f6d5
4 changed files with 75 additions and 46 deletions
Download Patch File Download Diff File Expand all files Collapse all files

42
allstarr/Controllers/JellyfinController.cs
View File

@@ -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
{

20
allstarr/Middleware/WebSocketProxyMiddleware.cs
View File

@@ -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);
}
}
}

25
allstarr/Services/Jellyfin/JellyfinProxyService.cs
View File

@@ -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);

34
allstarr/Services/Jellyfin/JellyfinSessionManager.cs
View File

@@ -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);
}