From 494b4bbbc2c02d6d03c33c77241b29d087f4ef94 Mon Sep 17 00:00:00 2001 From: Josh Patra Date: Tue, 3 Feb 2026 14:09:40 -0500 Subject: [PATCH] Reduce WebSocket/session logging noise, add playback progress logging - Changed routine WebSocket messages (Sessions, KeepAlive) to debug level - Reduced keep-alive spam - 401 on expired tokens is expected, not an error - Added periodic progress logging for local tracks (every 10 seconds) - Log warnings only when progress reports fail --- allstarr/Controllers/JellyfinController.cs | 34 +++++++++++++++++-- .../Jellyfin/JellyfinSessionManager.cs | 34 +++++++++++++------ 2 files changed, 54 insertions(+), 14 deletions(-) diff --git a/allstarr/Controllers/JellyfinController.cs b/allstarr/Controllers/JellyfinController.cs index 082183a..1651b56 100644 --- a/allstarr/Controllers/JellyfinController.cs +++ b/allstarr/Controllers/JellyfinController.cs @@ -2004,20 +2004,48 @@ public class JellyfinController : ControllerBase // Parse the body to check if it's an external track var doc = JsonDocument.Parse(body); + string? itemId = null; + long? positionTicks = null; + if (doc.RootElement.TryGetProperty("ItemId", out var itemIdProp)) { - var itemId = itemIdProp.GetString(); - var (isExternal, provider, externalId) = _localLibraryService.ParseSongId(itemId ?? ""); + itemId = itemIdProp.GetString(); + } + if (doc.RootElement.TryGetProperty("PositionTicks", out var posProp)) + { + positionTicks = posProp.GetInt64(); + } + + if (!string.IsNullOrEmpty(itemId)) + { + var (isExternal, provider, externalId) = _localLibraryService.ParseSongId(itemId); if (isExternal) { - // For external tracks, just acknowledge + // For external tracks, just acknowledge (no logging to avoid spam) return NoContent(); } + + // Log progress for local tracks (only every ~10 seconds to avoid spam) + if (positionTicks.HasValue) + { + var position = TimeSpan.FromTicks(positionTicks.Value); + // 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); + } + } } // For local tracks, forward to Jellyfin var (result, statusCode) = await _proxyService.PostJsonAsync("Sessions/Playing/Progress", body, Request.Headers); + + if (statusCode != 204 && statusCode != 200) + { + _logger.LogWarning("⚠️ Progress report returned {StatusCode} for item {ItemId}", statusCode, itemId); + } + return NoContent(); } catch (Exception ex) diff --git a/allstarr/Services/Jellyfin/JellyfinSessionManager.cs b/allstarr/Services/Jellyfin/JellyfinSessionManager.cs index 53f4620..9e49bd5 100644 --- a/allstarr/Services/Jellyfin/JellyfinSessionManager.cs +++ b/allstarr/Services/Jellyfin/JellyfinSessionManager.cs @@ -118,11 +118,12 @@ public class JellyfinSessionManager : IDisposable if (statusCode == 204 || statusCode == 200) { - _logger.LogWarning("✓ SESSION: Posted capabilities successfully ({StatusCode})", statusCode); + _logger.LogDebug("✓ SESSION: Posted capabilities successfully ({StatusCode})", statusCode); } else { - _logger.LogWarning("⚠️ SESSION: Failed to post capabilities - status {StatusCode}", statusCode); + // 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); } } @@ -303,17 +304,26 @@ public class JellyfinSessionManager : IDisposable break; } - // Log received messages for debugging + // Log received messages for debugging (only non-routine messages) if (result.MessageType == WebSocketMessageType.Text) { var message = Encoding.UTF8.GetString(buffer, 0, result.Count); - _logger.LogWarning("📥 WEBSOCKET: Received from Jellyfin for {DeviceId}: {Message}", - deviceId, message.Length > 100 ? message[..100] + "..." : message); - + // Respond to KeepAlive requests from Jellyfin if (message.Contains("\"MessageType\":\"KeepAlive\"")) { - _logger.LogWarning("💓 WEBSOCKET: Received KeepAlive from Jellyfin for {DeviceId}", deviceId); + _logger.LogDebug("💓 WEBSOCKET: Received KeepAlive from Jellyfin for {DeviceId}", deviceId); + } + else if (message.Contains("\"MessageType\":\"Sessions\"")) + { + // Session updates are routine, log at debug level + _logger.LogDebug("📥 WEBSOCKET: Session update for {DeviceId}", deviceId); + } + else + { + // Log other message types at info level + _logger.LogInformation("📥 WEBSOCKET: {DeviceId}: {Message}", + deviceId, message.Length > 100 ? message[..100] + "..." : message); } } } @@ -369,6 +379,7 @@ public class JellyfinSessionManager : IDisposable /// /// Periodically pings Jellyfin to keep sessions alive. + /// Note: This is a backup mechanism. The WebSocket connection is the primary keep-alive. /// private async void KeepSessionsAlive(object? state) { @@ -380,19 +391,20 @@ public class JellyfinSessionManager : IDisposable return; } - _logger.LogWarning("💓 SESSION: Keeping {Count} sessions alive", activeSessions.Count); + _logger.LogDebug("💓 SESSION: Keeping {Count} sessions alive", activeSessions.Count); foreach (var session in activeSessions) { try { // Post capabilities again to keep session alive + // Note: This may fail with 401 if the client's token has expired + // That's okay - the WebSocket connection keeps the session alive anyway await PostCapabilitiesAsync(session.Headers); - _logger.LogWarning("✓ SESSION: Kept session alive for {DeviceId}", session.DeviceId); } catch (Exception ex) { - _logger.LogWarning(ex, "⚠️ SESSION: Error keeping session alive for {DeviceId}", session.DeviceId); + _logger.LogDebug(ex, "SESSION: Error keeping session alive for {DeviceId} (WebSocket still active)", session.DeviceId); } } @@ -400,7 +412,7 @@ public class JellyfinSessionManager : IDisposable var staleSessions = _sessions.Where(kvp => now - kvp.Value.LastActivity > TimeSpan.FromMinutes(10)).ToList(); foreach (var stale in staleSessions) { - _logger.LogWarning("🧹 SESSION: Removing stale session for {DeviceId}", stale.Key); + _logger.LogInformation("🧹 SESSION: Removing stale session for {DeviceId}", stale.Key); _sessions.TryRemove(stale.Key, out _); } }