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
This commit is contained in:
2026-02-03 14:09:40 -05:00
parent 375e1894f3
commit 494b4bbbc2
2 changed files with 54 additions and 14 deletions

View File

@@ -2004,20 +2004,48 @@ public class JellyfinController : ControllerBase
// Parse the body to check if it's an external track // Parse the body to check if it's an external track
var doc = JsonDocument.Parse(body); var doc = JsonDocument.Parse(body);
string? itemId = null;
long? positionTicks = null;
if (doc.RootElement.TryGetProperty("ItemId", out var itemIdProp)) if (doc.RootElement.TryGetProperty("ItemId", out var itemIdProp))
{ {
var itemId = itemIdProp.GetString(); itemId = itemIdProp.GetString();
var (isExternal, provider, externalId) = _localLibraryService.ParseSongId(itemId ?? ""); }
if (doc.RootElement.TryGetProperty("PositionTicks", out var posProp))
{
positionTicks = posProp.GetInt64();
}
if (!string.IsNullOrEmpty(itemId))
{
var (isExternal, provider, externalId) = _localLibraryService.ParseSongId(itemId);
if (isExternal) if (isExternal)
{ {
// For external tracks, just acknowledge // For external tracks, just acknowledge (no logging to avoid spam)
return NoContent(); 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 // For local tracks, forward to Jellyfin
var (result, statusCode) = await _proxyService.PostJsonAsync("Sessions/Playing/Progress", body, Request.Headers); 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(); return NoContent();
} }
catch (Exception ex) catch (Exception ex)

View File

@@ -118,11 +118,12 @@ public class JellyfinSessionManager : IDisposable
if (statusCode == 204 || statusCode == 200) if (statusCode == 204 || statusCode == 200)
{ {
_logger.LogWarning("✓ SESSION: Posted capabilities successfully ({StatusCode})", statusCode); _logger.LogDebug("✓ SESSION: Posted capabilities successfully ({StatusCode})", statusCode);
} }
else 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; break;
} }
// Log received messages for debugging // Log received messages for debugging (only non-routine messages)
if (result.MessageType == WebSocketMessageType.Text) if (result.MessageType == WebSocketMessageType.Text)
{ {
var message = Encoding.UTF8.GetString(buffer, 0, result.Count); 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 // Respond to KeepAlive requests from Jellyfin
if (message.Contains("\"MessageType\":\"KeepAlive\"")) 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
/// <summary> /// <summary>
/// Periodically pings Jellyfin to keep sessions alive. /// Periodically pings Jellyfin to keep sessions alive.
/// Note: This is a backup mechanism. The WebSocket connection is the primary keep-alive.
/// </summary> /// </summary>
private async void KeepSessionsAlive(object? state) private async void KeepSessionsAlive(object? state)
{ {
@@ -380,19 +391,20 @@ public class JellyfinSessionManager : IDisposable
return; return;
} }
_logger.LogWarning("💓 SESSION: Keeping {Count} sessions alive", activeSessions.Count); _logger.LogDebug("💓 SESSION: Keeping {Count} sessions alive", activeSessions.Count);
foreach (var session in activeSessions) foreach (var session in activeSessions)
{ {
try try
{ {
// Post capabilities again to keep session alive // 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); await PostCapabilitiesAsync(session.Headers);
_logger.LogWarning("✓ SESSION: Kept session alive for {DeviceId}", session.DeviceId);
} }
catch (Exception ex) 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(); var staleSessions = _sessions.Where(kvp => now - kvp.Value.LastActivity > TimeSpan.FromMinutes(10)).ToList();
foreach (var stale in staleSessions) 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 _); _sessions.TryRemove(stale.Key, out _);
} }
} }