From 6ea2331127813de9a3c3183fefe85264c88fafcf Mon Sep 17 00:00:00 2001 From: Josh Patra Date: Sun, 1 Feb 2026 18:32:52 -0500 Subject: [PATCH] Lyrics and favorites improvements - Fix unsynced lyrics displaying all at 0:00 by omitting Start field - Improve LRC parsing with fuzzy search and synced lyrics preference - Add DeleteAsync to proxy service for proper auth forwarding - Support both /UserFavoriteItems and /Users/{userId}/FavoriteItems routes - Fix favorite endpoints to properly forward authentication - Add comprehensive logging for debugging - Extend Spotify sync backward search window to 24 hours --- .env.example | 6 + README.md | 1 + allstarr.Tests/JellyfinProxyServiceTests.cs | 11 +- allstarr/Controllers/JellyfinController.cs | 627 +++++++++++++++--- .../Services/Jellyfin/JellyfinProxyService.cs | 116 +++- allstarr/Services/Lyrics/LrclibService.cs | 125 +++- .../Spotify/SpotifyMissingTracksFetcher.cs | 188 +++++- docker-compose.yml | 2 + 8 files changed, 946 insertions(+), 130 deletions(-) diff --git a/.env.example b/.env.example index f1292e9..5824c1d 100644 --- a/.env.example +++ b/.env.example @@ -30,6 +30,12 @@ MUSIC_SERVICE=SquidWTF # Path where downloaded songs will be stored on the host (only applies if STORAGE_MODE=Permanent) DOWNLOAD_PATH=./downloads +# Path where favorited external tracks are permanently kept +KEPT_PATH=./kept + +# Path for cache files (Spotify missing tracks, etc.) +CACHE_PATH=./cache + # ===== SQUIDWTF CONFIGURATION ===== # Different quality options for SquidWTF. Only FLAC supported right now SQUIDWTF_QUALITY=FLAC diff --git a/README.md b/README.md index b3432b7..08b19d3 100644 --- a/README.md +++ b/README.md @@ -83,6 +83,7 @@ This project brings together all the music streaming providers into one unified - **Transparent Proxy**: Sits between your music clients and media server - **Automatic Search**: Searches streaming providers when songs aren't local - **On-the-Fly Downloads**: Songs download and cache for future use +- **Favorite to Keep**: When you favorite an external track, it's automatically copied to a permanent `/kept` folder separate from the cache - **External Playlist Support**: Search and download playlists from Deezer, Qobuz, and SquidWTF with M3U generation - **Hi-Res Audio**: SquidWTF supports up to 24-bit/192kHz FLAC - **Full Metadata**: Downloaded files include complete ID3 tags (title, artist, album, track number, year, genre, BPM, ISRC, etc.) and cover art diff --git a/allstarr.Tests/JellyfinProxyServiceTests.cs b/allstarr.Tests/JellyfinProxyServiceTests.cs index 6d268db..088581f 100644 --- a/allstarr.Tests/JellyfinProxyServiceTests.cs +++ b/allstarr.Tests/JellyfinProxyServiceTests.cs @@ -85,7 +85,7 @@ public class JellyfinProxyServiceTests } [Fact] - public async Task GetJsonAsync_IncludesAuthHeader() + public async Task GetJsonAsync_WithoutClientHeaders_SendsNoAuth() { // Arrange HttpRequestMessage? captured = null; @@ -102,13 +102,10 @@ public class JellyfinProxyServiceTests // Act await _service.GetJsonAsync("Items"); - // Assert + // Assert - Should NOT include auth when no client headers provided Assert.NotNull(captured); - Assert.True(captured!.Headers.Contains("Authorization")); - var authHeader = captured.Headers.GetValues("Authorization").First(); - Assert.Contains("MediaBrowser", authHeader); - Assert.Contains(_settings.ApiKey!, authHeader); - Assert.Contains(_settings.ClientName!, authHeader); + Assert.False(captured!.Headers.Contains("Authorization")); + Assert.False(captured.Headers.Contains("X-Emby-Authorization")); } [Fact] diff --git a/allstarr/Controllers/JellyfinController.cs b/allstarr/Controllers/JellyfinController.cs index 9afa4d4..13e2fc8 100644 --- a/allstarr/Controllers/JellyfinController.cs +++ b/allstarr/Controllers/JellyfinController.cs @@ -121,6 +121,13 @@ public class JellyfinController : ControllerBase return Unauthorized(new { error = "Authentication required" }); } + // Update Spotify playlist counts if enabled and response contains playlists + if (_spotifySettings.Enabled && browseResult.RootElement.TryGetProperty("Items", out var _)) + { + _logger.LogInformation("Browse result has Items, checking for Spotify playlists to update counts"); + browseResult = await UpdateSpotifyPlaylistCounts(browseResult); + } + var result = JsonSerializer.Deserialize(browseResult.RootElement.GetRawText()); if (_logger.IsEnabled(LogLevel.Debug)) { @@ -1026,15 +1033,21 @@ public class JellyfinController : ControllerBase var lyricsText = lyrics.SyncedLyrics ?? lyrics.PlainLyrics ?? ""; var isSynced = !string.IsNullOrEmpty(lyrics.SyncedLyrics); + _logger.LogInformation("Lyrics for {Artist} - {Track}: synced={HasSynced}, plainLength={PlainLen}, syncedLength={SyncLen}", + song.Artist, song.Title, isSynced, lyrics.PlainLyrics?.Length ?? 0, lyrics.SyncedLyrics?.Length ?? 0); + // Parse LRC format into individual lines for Jellyfin - var lyricLines = new List(); + var lyricLines = new List>(); if (isSynced && !string.IsNullOrEmpty(lyrics.SyncedLyrics)) { + _logger.LogInformation("Parsing synced lyrics (LRC format)"); // Parse LRC format: [mm:ss.xx] text + // Skip ID tags like [ar:Artist], [ti:Title], etc. var lines = lyrics.SyncedLyrics.Split('\n', StringSplitOptions.RemoveEmptyEntries); foreach (var line in lines) { + // Match timestamp format [mm:ss.xx] or [mm:ss.xxx] var match = System.Text.RegularExpressions.Regex.Match(line, @"^\[(\d+):(\d+)\.(\d+)\]\s*(.*)$"); if (match.Success) { @@ -1047,21 +1060,40 @@ public class JellyfinController : ControllerBase var totalMilliseconds = (minutes * 60 + seconds) * 1000 + centiseconds * 10; var ticks = totalMilliseconds * 10000L; - lyricLines.Add(new + // For synced lyrics, include Start timestamp + lyricLines.Add(new Dictionary { - Start = ticks, - Text = text + ["Text"] = text, + ["Start"] = ticks }); } + // Skip ID tags like [ar:Artist], [ti:Title], [length:2:23], etc. } + _logger.LogInformation("Parsed {Count} synced lyric lines (skipped ID tags)", lyricLines.Count); + } + else if (!string.IsNullOrEmpty(lyricsText)) + { + _logger.LogInformation("Splitting plain lyrics into lines (no timestamps)"); + // Plain lyrics - split by newlines and return each line separately + // IMPORTANT: Do NOT include "Start" field at all for unsynced lyrics + // Including it (even as null) causes clients to treat it as synced with timestamp 0:00 + var lines = lyricsText.Split(new[] { '\n', '\r' }, StringSplitOptions.RemoveEmptyEntries); + foreach (var line in lines) + { + lyricLines.Add(new Dictionary + { + ["Text"] = line.Trim() + }); + } + _logger.LogInformation("Split into {Count} plain lyric lines", lyricLines.Count); } else { - // Plain lyrics - return as single block - lyricLines.Add(new + _logger.LogWarning("No lyrics text available"); + // No lyrics at all + lyricLines.Add(new Dictionary { - Start = (long?)null, - Text = lyricsText + ["Text"] = "" }); } @@ -1078,6 +1110,17 @@ public class JellyfinController : ControllerBase Lyrics = lyricLines }; + _logger.LogInformation("Returning lyrics response: {LineCount} lines, synced={IsSynced}", lyricLines.Count, isSynced); + + // Log a sample of the response for debugging + if (lyricLines.Count > 0) + { + var sampleLine = lyricLines[0]; + var hasStart = sampleLine.ContainsKey("Start"); + _logger.LogInformation("Sample line: Text='{Text}', HasStart={HasStart}", + sampleLine.GetValueOrDefault("Text"), hasStart); + } + return Ok(response); } @@ -1087,10 +1130,21 @@ public class JellyfinController : ControllerBase /// /// Marks an item as favorite. For playlists, triggers a full download. + /// Supports both /Users/{userId}/FavoriteItems/{itemId} and /UserFavoriteItems/{itemId}?userId=xxx /// [HttpPost("Users/{userId}/FavoriteItems/{itemId}")] - public async Task MarkFavorite(string userId, string itemId) + [HttpPost("UserFavoriteItems/{itemId}")] + public async Task MarkFavorite(string itemId, string? userId = null) { + // Get userId from query string if not in path + if (string.IsNullOrEmpty(userId)) + { + userId = Request.Query["userId"].ToString(); + } + + _logger.LogInformation("MarkFavorite called: userId={UserId}, itemId={ItemId}, route={Route}", + userId, itemId, Request.Path); + // Check if this is an external playlist - trigger download if (PlaylistIdHelper.IsExternalPlaylist(itemId)) { @@ -1114,97 +1168,115 @@ public class JellyfinController : ControllerBase } }); - return Ok(new { IsFavorite = true }); + // Return a minimal UserItemDataDto response + return Ok(new + { + IsFavorite = true, + ItemId = itemId + }); } // Check if this is an external song/album - var (isExternal, _, _) = _localLibraryService.ParseSongId(itemId); + var (isExternal, provider, externalId) = _localLibraryService.ParseSongId(itemId); if (isExternal) { - // External items don't exist in Jellyfin, so we can't favorite them there - // Just return success - the client will show it as favorited - _logger.LogDebug("Favoriting external item {ItemId} (not synced to Jellyfin)", itemId); - return Ok(new { IsFavorite = true }); + _logger.LogInformation("Favoriting external item {ItemId}, copying to kept folder", itemId); + + // Copy the track to kept folder in background + _ = Task.Run(async () => + { + try + { + await CopyExternalTrackToKeptAsync(itemId, provider!, externalId!); + } + catch (Exception ex) + { + _logger.LogError(ex, "Failed to copy external track {ItemId} to kept folder", itemId); + } + }); + + // Return a minimal UserItemDataDto response + return Ok(new + { + IsFavorite = true, + ItemId = itemId + }); } // For local Jellyfin items, proxy the request through - var endpoint = $"Users/{userId}/FavoriteItems/{itemId}"; + // Use the official Jellyfin endpoint format + var endpoint = $"UserFavoriteItems/{itemId}"; + if (!string.IsNullOrEmpty(userId)) + { + endpoint = $"{endpoint}?userId={userId}"; + } - try + _logger.LogInformation("Proxying favorite request to Jellyfin: {Endpoint}", endpoint); + + var result = await _proxyService.PostJsonAsync(endpoint, "{}", Request.Headers); + + if (result == null) { - using var request = new HttpRequestMessage(HttpMethod.Post, $"{_settings.Url?.TrimEnd('/')}/{endpoint}"); - - // Forward client authentication - if (Request.Headers.TryGetValue("X-Emby-Authorization", out var embyAuth)) - { - request.Headers.TryAddWithoutValidation("X-Emby-Authorization", embyAuth.ToString()); - } - else if (Request.Headers.TryGetValue("Authorization", out var auth)) - { - request.Headers.TryAddWithoutValidation("Authorization", auth.ToString()); - } - - var response = await _proxyService.HttpClient.SendAsync(request); - - if (response.IsSuccessStatusCode) - { - return Ok(new { IsFavorite = true }); - } - - _logger.LogWarning("Failed to favorite item in Jellyfin: {StatusCode}", response.StatusCode); - return _responseBuilder.CreateError((int)response.StatusCode, "Failed to mark favorite"); - } - catch (Exception ex) - { - _logger.LogError(ex, "Error favoriting item {ItemId}", itemId); - return _responseBuilder.CreateError(500, "Failed to mark favorite"); + _logger.LogWarning("Failed to favorite item in Jellyfin - proxy returned null"); + return StatusCode(500, new { error = "Failed to mark favorite" }); } + + return new JsonResult(JsonSerializer.Deserialize(result.RootElement.GetRawText())); } /// /// Removes an item from favorites. + /// Supports both /Users/{userId}/FavoriteItems/{itemId} and /UserFavoriteItems/{itemId}?userId=xxx /// [HttpDelete("Users/{userId}/FavoriteItems/{itemId}")] - public async Task UnmarkFavorite(string userId, string itemId) + [HttpDelete("UserFavoriteItems/{itemId}")] + public async Task UnmarkFavorite(string itemId, string? userId = null) { - // External items can't be unfavorited + // Get userId from query string if not in path + if (string.IsNullOrEmpty(userId)) + { + userId = Request.Query["userId"].ToString(); + } + + _logger.LogInformation("UnmarkFavorite called: userId={UserId}, itemId={ItemId}, route={Route}", + userId, itemId, Request.Path); + + // External items can't be unfavorited (they're not really favorited in Jellyfin) var (isExternal, _, _) = _localLibraryService.ParseSongId(itemId); if (isExternal || PlaylistIdHelper.IsExternalPlaylist(itemId)) { - return Ok(new { IsFavorite = false }); + _logger.LogInformation("Unfavoriting external item {ItemId} - returning success", itemId); + return Ok(new + { + IsFavorite = false, + ItemId = itemId + }); } // Proxy to Jellyfin to unfavorite - var url = $"Users/{userId}/FavoriteItems/{itemId}"; + // Use the official Jellyfin endpoint format + var endpoint = $"UserFavoriteItems/{itemId}"; + if (!string.IsNullOrEmpty(userId)) + { + endpoint = $"{endpoint}?userId={userId}"; + } - try + _logger.LogInformation("Proxying unfavorite request to Jellyfin: {Endpoint}", endpoint); + + var result = await _proxyService.DeleteAsync(endpoint, Request.Headers); + + if (result == null) { - using var request = new HttpRequestMessage(HttpMethod.Delete, $"{_settings.Url?.TrimEnd('/')}/{url}"); - - // Forward client authentication - if (Request.Headers.TryGetValue("X-Emby-Authorization", out var embyAuth)) - { - request.Headers.TryAddWithoutValidation("X-Emby-Authorization", embyAuth.ToString()); - } - else if (Request.Headers.TryGetValue("Authorization", out var auth)) - { - request.Headers.TryAddWithoutValidation("Authorization", auth.ToString()); - } - - var response = await _proxyService.HttpClient.SendAsync(request); - - if (response.IsSuccessStatusCode) - { - return Ok(new { IsFavorite = false }); - } - - return _responseBuilder.CreateError(500, "Failed to unfavorite item"); - } - catch (Exception ex) - { - _logger.LogError(ex, "Error unfavoriting item {ItemId}", itemId); - return _responseBuilder.CreateError(500, "Failed to unfavorite item"); + // DELETE often returns 204 No Content, which is success + _logger.LogInformation("Unfavorite succeeded (no content returned)"); + return Ok(new + { + IsFavorite = false, + ItemId = itemId + }); } + + return new JsonResult(JsonSerializer.Deserialize(result.RootElement.GetRawText())); } #endregion @@ -1650,6 +1722,7 @@ public class JellyfinController : ControllerBase /// /// Catch-all endpoint that proxies unhandled requests to Jellyfin transparently. /// This route has the lowest priority and should only match requests that don't have SearchTerm. + /// Blocks dangerous admin endpoints for security. /// [HttpGet("{**path}", Order = 100)] [HttpPost("{**path}", Order = 100)] @@ -1658,6 +1731,42 @@ public class JellyfinController : ControllerBase // DEBUG: Log EVERY request to see what's happening _logger.LogWarning("ProxyRequest called with path: {Path}", path); + // Log endpoint usage to file for analysis + await LogEndpointUsageAsync(path, Request.Method); + + // Block dangerous admin endpoints + var blockedPrefixes = new[] + { + "system/restart", // Server restart + "system/shutdown", // Server shutdown + "system/configuration", // System configuration changes + "system/logs", // Server logs access + "system/activitylog", // Activity log access + "plugins/", // Plugin management (install/uninstall/configure) + "scheduledtasks/", // Scheduled task management + "startup/", // Initial server setup + "users/new", // User creation + "library/refresh", // Library scan (expensive operation) + "library/virtualfolders", // Library folder management + "branding/", // Branding configuration + "displaypreferences/", // Display preferences (if not user-specific) + "notifications/admin" // Admin notifications + }; + + // Check if path matches any blocked prefix + if (blockedPrefixes.Any(prefix => + path.StartsWith(prefix, StringComparison.OrdinalIgnoreCase))) + { + _logger.LogWarning("BLOCKED: Access denied to admin endpoint: {Path} from {IP}", + path, + HttpContext.Connection.RemoteIpAddress); + return StatusCode(403, new + { + error = "Access to administrative endpoints is not allowed through this proxy", + path = path + }); + } + // Intercept Spotify playlist requests by ID if (_spotifySettings.Enabled && path.StartsWith("playlists/", StringComparison.OrdinalIgnoreCase) && @@ -1812,6 +1921,13 @@ public class JellyfinController : ControllerBase return NoContent(); } + // Modify response if it contains Spotify playlists to update ChildCount + if (_spotifySettings.Enabled && result.RootElement.TryGetProperty("Items", out var items)) + { + _logger.LogInformation("Response has Items property, checking for Spotify playlists to update counts"); + result = await UpdateSpotifyPlaylistCounts(result); + } + return new JsonResult(JsonSerializer.Deserialize(result.RootElement.GetRawText())); } catch (Exception ex) @@ -1825,6 +1941,141 @@ public class JellyfinController : ControllerBase #region Helpers + /// + /// Updates ChildCount for Spotify playlists in the response to show total tracks (local + matched). + /// + private async Task UpdateSpotifyPlaylistCounts(JsonDocument response) + { + try + { + if (!response.RootElement.TryGetProperty("Items", out var items)) + { + return response; + } + + var itemsArray = items.EnumerateArray().ToList(); + var modified = false; + var updatedItems = new List>(); + + _logger.LogInformation("Checking {Count} items for Spotify playlists", itemsArray.Count); + + foreach (var item in itemsArray) + { + var itemDict = JsonSerializer.Deserialize>(item.GetRawText()); + if (itemDict == null) + { + continue; + } + + // Check if this is a Spotify playlist + if (item.TryGetProperty("Id", out var idProp)) + { + var playlistId = idProp.GetString(); + _logger.LogDebug("Checking item with ID: {Id}", playlistId); + + if (!string.IsNullOrEmpty(playlistId) && + _spotifySettings.PlaylistIds.Any(id => id.Equals(playlistId, StringComparison.OrdinalIgnoreCase))) + { + _logger.LogInformation("Found Spotify playlist: {Id}", playlistId); + + // This is a Spotify playlist - get the actual track count + var playlistIndex = _spotifySettings.PlaylistIds.FindIndex(id => + id.Equals(playlistId, StringComparison.OrdinalIgnoreCase)); + + if (playlistIndex >= 0 && playlistIndex < _spotifySettings.PlaylistNames.Count) + { + var playlistName = _spotifySettings.PlaylistNames[playlistIndex]; + var missingTracksKey = $"spotify:missing:{playlistName}"; + var missingTracks = await _cache.GetAsync>(missingTracksKey); + + _logger.LogInformation("Cache lookup for {Key}: {Count} tracks", + missingTracksKey, missingTracks?.Count ?? 0); + + // Fallback to file cache + if (missingTracks == null || missingTracks.Count == 0) + { + _logger.LogInformation("Trying file cache for {Name}", playlistName); + missingTracks = await LoadMissingTracksFromFile(playlistName); + _logger.LogInformation("File cache result: {Count} tracks", missingTracks?.Count ?? 0); + } + + if (missingTracks != null && missingTracks.Count > 0) + { + // Update ChildCount to show the number of tracks we'll provide + itemDict["ChildCount"] = missingTracks.Count; + modified = true; + _logger.LogInformation("✓ Updated ChildCount for Spotify playlist {Name} to {Count}", + playlistName, missingTracks.Count); + } + else + { + _logger.LogWarning("No missing tracks found for {Name}", playlistName); + } + } + } + } + + updatedItems.Add(itemDict); + } + + if (!modified) + { + _logger.LogInformation("No Spotify playlists found to update"); + return response; + } + + _logger.LogInformation("Modified {Count} Spotify playlists, rebuilding response", + updatedItems.Count(i => i.ContainsKey("ChildCount"))); + + // Rebuild the response with updated items + var responseDict = JsonSerializer.Deserialize>(response.RootElement.GetRawText()); + if (responseDict != null) + { + responseDict["Items"] = updatedItems; + var updatedJson = JsonSerializer.Serialize(responseDict); + return JsonDocument.Parse(updatedJson); + } + + return response; + } + catch (Exception ex) + { + _logger.LogWarning(ex, "Failed to update Spotify playlist counts"); + return response; + } + } + + /// + /// Logs endpoint usage to a file for analysis. + /// Creates a CSV file with timestamp, method, path, and query string. + /// + private async Task LogEndpointUsageAsync(string path, string method) + { + try + { + var logDir = "/app/cache/endpoint-usage"; + Directory.CreateDirectory(logDir); + + var logFile = Path.Combine(logDir, "endpoints.csv"); + var timestamp = DateTime.UtcNow.ToString("yyyy-MM-dd HH:mm:ss"); + var queryString = Request.QueryString.HasValue ? Request.QueryString.Value : ""; + + // Sanitize path and query for CSV (remove commas, quotes, newlines) + var sanitizedPath = path.Replace(",", ";").Replace("\"", "'").Replace("\n", " ").Replace("\r", " "); + var sanitizedQuery = queryString.Replace(",", ";").Replace("\"", "'").Replace("\n", " ").Replace("\r", " "); + + var logLine = $"{timestamp},{method},{sanitizedPath},{sanitizedQuery}\n"; + + // Append to file (thread-safe) + await System.IO.File.AppendAllTextAsync(logFile, logLine); + } + catch (Exception ex) + { + // Don't let logging failures break the request + _logger.LogDebug(ex, "Failed to log endpoint usage"); + } + } + private static string[]? ParseItemTypes(string? includeItemTypes) { if (string.IsNullOrWhiteSpace(includeItemTypes)) @@ -1962,6 +2213,20 @@ public class JellyfinController : ControllerBase var missingTracksKey = $"spotify:missing:{spotifyPlaylistName}"; var missingTracks = await _cache.GetAsync>(missingTracksKey); + // Fallback to file cache if Redis is empty + if (missingTracks == null || missingTracks.Count == 0) + { + missingTracks = await LoadMissingTracksFromFile(spotifyPlaylistName); + + // If we loaded from file, restore to Redis + if (missingTracks != null && missingTracks.Count > 0) + { + await _cache.SetAsync(missingTracksKey, missingTracks, TimeSpan.FromHours(24)); + _logger.LogInformation("Restored {Count} missing tracks from file cache for {Playlist}", + missingTracks.Count, spotifyPlaylistName); + } + } + if (missingTracks == null || missingTracks.Count == 0) { _logger.LogInformation("No missing tracks found for {Playlist}, returning {Count} existing tracks", @@ -2069,11 +2334,116 @@ public class JellyfinController : ControllerBase } } + /// + /// Copies an external track to the kept folder when favorited. + /// + private async Task CopyExternalTrackToKeptAsync(string itemId, string provider, string externalId) + { + try + { + // Get the song metadata + var song = await _metadataService.GetSongAsync(provider, externalId); + if (song == null) + { + _logger.LogWarning("Could not find song metadata for {ItemId}", itemId); + return; + } + + // Trigger download first + _logger.LogInformation("Downloading track for kept folder: {ItemId}", itemId); + string downloadPath; + + try + { + downloadPath = await _downloadService.DownloadSongAsync(provider, externalId); + } + catch (Exception ex) + { + _logger.LogWarning(ex, "Failed to download track {ItemId}", itemId); + return; + } + + // Create kept folder structure: /app/kept/Artist/Album/ + var keptBasePath = "/app/kept"; + var keptArtistPath = Path.Combine(keptBasePath, PathHelper.SanitizeFileName(song.Artist)); + var keptAlbumPath = Path.Combine(keptArtistPath, PathHelper.SanitizeFileName(song.Album)); + + Directory.CreateDirectory(keptAlbumPath); + + // Copy file to kept folder + var fileName = Path.GetFileName(downloadPath); + var keptFilePath = Path.Combine(keptAlbumPath, fileName); + + if (System.IO.File.Exists(keptFilePath)) + { + _logger.LogInformation("Track already exists in kept folder: {Path}", keptFilePath); + return; + } + + System.IO.File.Copy(downloadPath, keptFilePath, overwrite: false); + _logger.LogInformation("✓ Copied favorited track to kept folder: {Path}", keptFilePath); + + // Also copy cover art if it exists + var coverPath = Path.Combine(Path.GetDirectoryName(downloadPath)!, "cover.jpg"); + if (System.IO.File.Exists(coverPath)) + { + var keptCoverPath = Path.Combine(keptAlbumPath, "cover.jpg"); + if (!System.IO.File.Exists(keptCoverPath)) + { + System.IO.File.Copy(coverPath, keptCoverPath, overwrite: false); + _logger.LogDebug("Copied cover art to kept folder"); + } + } + } + catch (Exception ex) + { + _logger.LogError(ex, "Error copying external track {ItemId} to kept folder", itemId); + } + } + + /// + /// Loads missing tracks from file cache as fallback when Redis is empty. + /// + private async Task?> LoadMissingTracksFromFile(string playlistName) + { + try + { + var safeName = string.Join("_", playlistName.Split(Path.GetInvalidFileNameChars())); + var filePath = Path.Combine("/app/cache/spotify", $"{safeName}_missing.json"); + + if (!System.IO.File.Exists(filePath)) + { + _logger.LogDebug("No file cache found for {Playlist} at {Path}", playlistName, filePath); + return null; + } + + var fileAge = DateTime.UtcNow - System.IO.File.GetLastWriteTimeUtc(filePath); + if (fileAge > TimeSpan.FromHours(24)) + { + _logger.LogDebug("File cache for {Playlist} is too old ({Age:F1}h)", playlistName, fileAge.TotalHours); + return null; + } + + var json = await System.IO.File.ReadAllTextAsync(filePath); + var tracks = JsonSerializer.Deserialize>(json); + + _logger.LogInformation("Loaded {Count} missing tracks from file cache for {Playlist} (age: {Age:F1}h)", + tracks?.Count ?? 0, playlistName, fileAge.TotalHours); + + return tracks; + } + catch (Exception ex) + { + _logger.LogWarning(ex, "Failed to load missing tracks from file for {Playlist}", playlistName); + return null; + } + } + /// /// Manual trigger endpoint to force fetch Spotify missing tracks. /// GET /spotify/sync?api_key=YOUR_KEY /// - [HttpGet("spotify/sync")] + [HttpGet("spotify/sync", Order = 1)] [ServiceFilter(typeof(ApiKeyAuthFilter))] public async Task TriggerSpotifySync() { @@ -2228,5 +2598,114 @@ public class JellyfinController : ControllerBase } #endregion + + #region Debug & Monitoring + + /// + /// Gets endpoint usage statistics from the log file. + /// GET /debug/endpoint-usage?api_key=YOUR_KEY + /// Optional query params: top=50 (default 100), since=2024-01-01 + /// + [HttpGet("debug/endpoint-usage")] + [ServiceFilter(typeof(ApiKeyAuthFilter))] + public async Task GetEndpointUsage( + [FromQuery] int top = 100, + [FromQuery] string? since = null) + { + try + { + var logFile = "/app/cache/endpoint-usage/endpoints.csv"; + + if (!System.IO.File.Exists(logFile)) + { + return Ok(new + { + message = "No endpoint usage data collected yet", + endpoints = Array.Empty() + }); + } + + var lines = await System.IO.File.ReadAllLinesAsync(logFile); + + // Parse CSV and filter by date if provided + DateTime? sinceDate = null; + if (!string.IsNullOrEmpty(since) && DateTime.TryParse(since, out var parsedDate)) + { + sinceDate = parsedDate; + } + + var entries = lines + .Select(line => line.Split(',')) + .Where(parts => parts.Length >= 3) + .Where(parts => !sinceDate.HasValue || + (DateTime.TryParse(parts[0], out var entryDate) && entryDate >= sinceDate.Value)) + .Select(parts => new + { + Timestamp = parts[0], + Method = parts.Length > 1 ? parts[1] : "", + Path = parts.Length > 2 ? parts[2] : "", + Query = parts.Length > 3 ? parts[3] : "" + }) + .ToList(); + + // Group by path and count + var pathCounts = entries + .GroupBy(e => new { e.Method, e.Path }) + .Select(g => new + { + Method = g.Key.Method, + Path = g.Key.Path, + Count = g.Count(), + FirstSeen = g.Min(e => e.Timestamp), + LastSeen = g.Max(e => e.Timestamp) + }) + .OrderByDescending(x => x.Count) + .Take(top) + .ToList(); + + return Ok(new + { + totalRequests = entries.Count, + uniqueEndpoints = pathCounts.Count, + topEndpoints = pathCounts, + logFile = logFile, + logSize = new FileInfo(logFile).Length + }); + } + catch (Exception ex) + { + _logger.LogError(ex, "Failed to get endpoint usage"); + return StatusCode(500, new { error = ex.Message }); + } + } + + /// + /// Clears the endpoint usage log file. + /// DELETE /debug/endpoint-usage?api_key=YOUR_KEY + /// + [HttpDelete("debug/endpoint-usage")] + [ServiceFilter(typeof(ApiKeyAuthFilter))] + public IActionResult ClearEndpointUsage() + { + try + { + var logFile = "/app/cache/endpoint-usage/endpoints.csv"; + + if (System.IO.File.Exists(logFile)) + { + System.IO.File.Delete(logFile); + return Ok(new { status = "success", message = "Endpoint usage log cleared" }); + } + + return Ok(new { status = "success", message = "No log file to clear" }); + } + catch (Exception ex) + { + _logger.LogError(ex, "Failed to clear endpoint usage log"); + return StatusCode(500, new { error = ex.Message }); + } + } + + #endregion } // force rebuild Sun Jan 25 13:22:47 EST 2026 diff --git a/allstarr/Services/Jellyfin/JellyfinProxyService.cs b/allstarr/Services/Jellyfin/JellyfinProxyService.cs index 308dfd3..4c9b6dc 100644 --- a/allstarr/Services/Jellyfin/JellyfinProxyService.cs +++ b/allstarr/Services/Jellyfin/JellyfinProxyService.cs @@ -205,18 +205,11 @@ public class JellyfinProxyService _logger.LogWarning("✗ No client headers provided for {Url}", url); } - // Use API key if no valid client auth was found + // DO NOT use server API key as fallback - let Jellyfin handle unauthenticated requests + // If client doesn't provide auth, they get what they deserve (401 from Jellyfin) if (!authHeaderAdded) { - if (!string.IsNullOrEmpty(_settings.ApiKey)) - { - request.Headers.Add("Authorization", GetAuthorizationHeader()); - _logger.LogInformation("→ Using API key for {Url}", url); - } - else - { - _logger.LogWarning("✗ No authentication available for {Url} - request will fail", url); - } + _logger.LogInformation("No client auth provided for {Url} - forwarding without auth", url); } request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("application/json")); @@ -333,16 +326,12 @@ public class JellyfinProxyService } } - // For non-auth requests without headers, use API key - // For auth requests, client MUST provide their own client info - if (!authHeaderAdded && !endpoint.Contains("Authenticate", StringComparison.OrdinalIgnoreCase)) + // DO NOT use server credentials as fallback + // Exception: For auth endpoints, client provides their own credentials in the body + // For all other endpoints, if client doesn't provide auth, let Jellyfin reject it + if (!authHeaderAdded) { - var clientAuthHeader = $"MediaBrowser Client=\"{_settings.ClientName}\", " + - $"Device=\"{_settings.DeviceName}\", " + - $"DeviceId=\"{_settings.DeviceId}\", " + - $"Version=\"{_settings.ClientVersion}\""; - request.Headers.TryAddWithoutValidation("X-Emby-Authorization", clientAuthHeader); - _logger.LogDebug("Using server API key for non-auth request"); + _logger.LogInformation("No client auth provided for POST {Url} - forwarding without auth", url); } request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("application/json")); @@ -409,6 +398,95 @@ public class JellyfinProxyService return (body, contentType); } + /// + /// Sends a DELETE request to the Jellyfin server. + /// Forwards client headers for authentication passthrough. + /// + public async Task DeleteAsync(string endpoint, IHeaderDictionary clientHeaders) + { + var url = BuildUrl(endpoint, null); + + using var request = new HttpRequestMessage(HttpMethod.Delete, url); + + bool authHeaderAdded = false; + + // Forward authentication headers from client (case-insensitive) + foreach (var header in clientHeaders) + { + if (header.Key.Equals("X-Emby-Authorization", StringComparison.OrdinalIgnoreCase)) + { + var headerValue = header.Value.ToString(); + request.Headers.TryAddWithoutValidation("X-Emby-Authorization", headerValue); + authHeaderAdded = true; + _logger.LogDebug("Forwarded X-Emby-Authorization from client"); + break; + } + } + + if (!authHeaderAdded) + { + foreach (var header in clientHeaders) + { + if (header.Key.Equals("Authorization", StringComparison.OrdinalIgnoreCase)) + { + var headerValue = header.Value.ToString(); + + // Check if it's MediaBrowser/Jellyfin format + if (headerValue.Contains("MediaBrowser", StringComparison.OrdinalIgnoreCase) || + headerValue.Contains("Client=", StringComparison.OrdinalIgnoreCase)) + { + // Forward as X-Emby-Authorization + request.Headers.TryAddWithoutValidation("X-Emby-Authorization", headerValue); + _logger.LogDebug("Converted Authorization to X-Emby-Authorization"); + } + else + { + // Standard Bearer token + request.Headers.TryAddWithoutValidation("Authorization", headerValue); + _logger.LogDebug("Forwarded Authorization header"); + } + authHeaderAdded = true; + break; + } + } + } + + if (!authHeaderAdded) + { + _logger.LogInformation("No client auth provided for DELETE {Url} - forwarding without auth", url); + } + + request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("application/json")); + + _logger.LogInformation("DELETE to Jellyfin: {Url}", url); + + var response = await _httpClient.SendAsync(request); + + if (!response.IsSuccessStatusCode) + { + var errorContent = await response.Content.ReadAsStringAsync(); + _logger.LogWarning("Jellyfin DELETE request failed: {StatusCode} for {Url}. Response: {Response}", + response.StatusCode, url, errorContent); + return null; + } + + // Handle 204 No Content responses + if (response.StatusCode == System.Net.HttpStatusCode.NoContent) + { + return null; + } + + var responseContent = await response.Content.ReadAsStringAsync(); + + // Handle empty responses + if (string.IsNullOrWhiteSpace(responseContent)) + { + return null; + } + + return JsonDocument.Parse(responseContent); + } + /// /// Safely sends a GET request to the Jellyfin server, returning null on failure. /// diff --git a/allstarr/Services/Lyrics/LrclibService.cs b/allstarr/Services/Lyrics/LrclibService.cs index cc5e758..be0687f 100644 --- a/allstarr/Services/Lyrics/LrclibService.cs +++ b/allstarr/Services/Lyrics/LrclibService.cs @@ -42,25 +42,100 @@ public class LrclibService try { - var url = $"{BaseUrl}/get?" + - $"track_name={Uri.EscapeDataString(trackName)}&" + - $"artist_name={Uri.EscapeDataString(artistName)}&" + - $"album_name={Uri.EscapeDataString(albumName)}&" + - $"duration={durationSeconds}"; + // First try search API for fuzzy matching (more forgiving) + var searchUrl = $"{BaseUrl}/search?" + + $"track_name={Uri.EscapeDataString(trackName)}&" + + $"artist_name={Uri.EscapeDataString(artistName)}"; - _logger.LogDebug("Fetching lyrics from LRCLIB: {Url}", url); + _logger.LogInformation("Searching LRCLIB: {Url}", searchUrl); - var response = await _httpClient.GetAsync(url); + var searchResponse = await _httpClient.GetAsync(searchUrl); - if (response.StatusCode == System.Net.HttpStatusCode.NotFound) + if (searchResponse.IsSuccessStatusCode) + { + var searchJson = await searchResponse.Content.ReadAsStringAsync(); + var searchResults = JsonSerializer.Deserialize>(searchJson, JsonOptions); + + if (searchResults != null && searchResults.Count > 0) + { + // Find best match by comparing track name, artist, and duration + LrclibResponse? bestMatch = null; + double bestScore = 0; + + foreach (var result in searchResults) + { + // Calculate similarity scores + var trackScore = CalculateSimilarity(trackName, result.TrackName ?? ""); + var artistScore = CalculateSimilarity(artistName, result.ArtistName ?? ""); + + // Duration match (within 5 seconds is good) + var durationDiff = Math.Abs(result.Duration - durationSeconds); + var durationScore = durationDiff <= 5 ? 100.0 : Math.Max(0, 100 - (durationDiff * 2)); + + // Bonus for having synced lyrics (prefer synced over plain) + var syncedBonus = !string.IsNullOrEmpty(result.SyncedLyrics) ? 20.0 : 0.0; + + // Weighted score: track name most important, then artist, then duration, plus synced bonus + var totalScore = (trackScore * 0.5) + (artistScore * 0.3) + (durationScore * 0.2) + syncedBonus; + + _logger.LogDebug("Candidate: {Track} by {Artist} - Score: {Score:F1} (track:{TrackScore:F1}, artist:{ArtistScore:F1}, duration:{DurationScore:F1}, synced:{Synced})", + result.TrackName, result.ArtistName, totalScore, trackScore, artistScore, durationScore, !string.IsNullOrEmpty(result.SyncedLyrics)); + + if (totalScore > bestScore) + { + bestScore = totalScore; + bestMatch = result; + } + } + + // Only use result if score is good enough (>60%) + if (bestMatch != null && bestScore >= 60) + { + _logger.LogInformation("✓ Found lyrics via search for {Artist} - {Track} (ID: {Id}, score: {Score:F1}, synced: {HasSynced})", + artistName, trackName, bestMatch.Id, bestScore, !string.IsNullOrEmpty(bestMatch.SyncedLyrics)); + + var result = new LyricsInfo + { + Id = bestMatch.Id, + TrackName = bestMatch.TrackName ?? trackName, + ArtistName = bestMatch.ArtistName ?? artistName, + AlbumName = bestMatch.AlbumName ?? albumName, + Duration = (int)Math.Round(bestMatch.Duration), + Instrumental = bestMatch.Instrumental, + PlainLyrics = bestMatch.PlainLyrics, + SyncedLyrics = bestMatch.SyncedLyrics + }; + + await _cache.SetStringAsync(cacheKey, JsonSerializer.Serialize(result, JsonOptions), TimeSpan.FromDays(30)); + return result; + } + else + { + _logger.LogInformation("Best match score too low ({Score:F1}), trying exact match", bestScore); + } + } + } + + // Fall back to exact match API if search didn't find good results + var exactUrl = $"{BaseUrl}/get?" + + $"track_name={Uri.EscapeDataString(trackName)}&" + + $"artist_name={Uri.EscapeDataString(artistName)}&" + + $"album_name={Uri.EscapeDataString(albumName)}&" + + $"duration={durationSeconds}"; + + _logger.LogDebug("Trying exact match from LRCLIB: {Url}", exactUrl); + + var exactResponse = await _httpClient.GetAsync(exactUrl); + + if (exactResponse.StatusCode == System.Net.HttpStatusCode.NotFound) { _logger.LogDebug("Lyrics not found for {Artist} - {Track}", artistName, trackName); return null; } - response.EnsureSuccessStatusCode(); + exactResponse.EnsureSuccessStatusCode(); - var json = await response.Content.ReadAsStringAsync(); + var json = await exactResponse.Content.ReadAsStringAsync(); var lyrics = JsonSerializer.Deserialize(json, JsonOptions); if (lyrics == null) @@ -68,7 +143,7 @@ public class LrclibService return null; } - var result = new LyricsInfo + var exactResult = new LyricsInfo { Id = lyrics.Id, TrackName = lyrics.TrackName ?? trackName, @@ -80,11 +155,11 @@ public class LrclibService SyncedLyrics = lyrics.SyncedLyrics }; - await _cache.SetStringAsync(cacheKey, JsonSerializer.Serialize(result, JsonOptions), TimeSpan.FromDays(30)); + await _cache.SetStringAsync(cacheKey, JsonSerializer.Serialize(exactResult, JsonOptions), TimeSpan.FromDays(30)); - _logger.LogInformation("Retrieved lyrics for {Artist} - {Track} (ID: {Id})", artistName, trackName, lyrics.Id); + _logger.LogInformation("Retrieved lyrics via exact match for {Artist} - {Track} (ID: {Id})", artistName, trackName, lyrics.Id); - return result; + return exactResult; } catch (HttpRequestException ex) { @@ -98,6 +173,28 @@ public class LrclibService } } + private static double CalculateSimilarity(string str1, string str2) + { + if (string.IsNullOrEmpty(str1) || string.IsNullOrEmpty(str2)) + return 0; + + str1 = str1.ToLowerInvariant(); + str2 = str2.ToLowerInvariant(); + + if (str1 == str2) + return 100; + + // Simple token-based matching + var tokens1 = str1.Split(new[] { ' ', '-', '_' }, StringSplitOptions.RemoveEmptyEntries); + var tokens2 = str2.Split(new[] { ' ', '-', '_' }, StringSplitOptions.RemoveEmptyEntries); + + if (tokens1.Length == 0 || tokens2.Length == 0) + return 0; + + var matchedTokens = tokens1.Count(t1 => tokens2.Any(t2 => t2.Contains(t1) || t1.Contains(t2))); + return (matchedTokens * 100.0) / Math.Max(tokens1.Length, tokens2.Length); + } + public async Task GetLyricsCachedAsync(string trackName, string artistName, string albumName, int durationSeconds) { try diff --git a/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs b/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs index 3d46347..036dc31 100644 --- a/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs +++ b/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs @@ -17,6 +17,7 @@ public class SpotifyMissingTracksFetcher : BackgroundService private readonly IServiceProvider _serviceProvider; private bool _hasRunOnce = false; private Dictionary _playlistIdToName = new(); + private const string CacheDirectory = "/app/cache/spotify"; public SpotifyMissingTracksFetcher( IOptions spotifySettings, @@ -39,6 +40,9 @@ public class SpotifyMissingTracksFetcher : BackgroundService _logger.LogInformation("========================================"); _logger.LogInformation("SpotifyMissingTracksFetcher: Starting up..."); + // Ensure cache directory exists + Directory.CreateDirectory(CacheDirectory); + if (!_spotifySettings.Value.Enabled) { _logger.LogInformation("Spotify playlist injection is DISABLED"); @@ -74,10 +78,10 @@ public class SpotifyMissingTracksFetcher : BackgroundService var shouldRunOnStartup = await ShouldRunOnStartupAsync(); if (shouldRunOnStartup) { - _logger.LogInformation("Running initial fetch on startup"); + _logger.LogInformation("Running initial fetch on startup (bypassing sync window check)"); try { - await FetchMissingTracksAsync(stoppingToken); + await FetchMissingTracksAsync(stoppingToken, bypassSyncWindowCheck: true); _hasRunOnce = true; } catch (Exception ex) @@ -87,7 +91,7 @@ public class SpotifyMissingTracksFetcher : BackgroundService } else { - _logger.LogInformation("Skipping startup fetch - already ran within last 24 hours"); + _logger.LogInformation("Skipping startup fetch - already have recent cache"); _hasRunOnce = true; } } @@ -125,19 +129,144 @@ public class SpotifyMissingTracksFetcher : BackgroundService private async Task ShouldRunOnStartupAsync() { - // Check if any playlist has cached data from the last 24 hours + _logger.LogInformation("=== STARTUP CACHE CHECK ==="); + _logger.LogInformation("Cache directory: {Dir}", CacheDirectory); + _logger.LogInformation("Checking {Count} playlists", _playlistIdToName.Count); + + // List all files in cache directory for debugging + try + { + if (Directory.Exists(CacheDirectory)) + { + var files = Directory.GetFiles(CacheDirectory, "*.json"); + _logger.LogInformation("Found {Count} JSON files in cache directory:", files.Length); + foreach (var file in files) + { + var fileInfo = new FileInfo(file); + var age = DateTime.UtcNow - fileInfo.LastWriteTimeUtc; + _logger.LogInformation(" - {Name} (age: {Age:F1}h, size: {Size} bytes)", + Path.GetFileName(file), age.TotalHours, fileInfo.Length); + } + } + else + { + _logger.LogWarning("Cache directory does not exist: {Dir}", CacheDirectory); + } + } + catch (Exception ex) + { + _logger.LogError(ex, "Error listing cache directory"); + } + + // Check file cache first, then Redis foreach (var playlistName in _playlistIdToName.Values) { + var filePath = GetCacheFilePath(playlistName); + _logger.LogInformation("Checking playlist: {Playlist}", playlistName); + _logger.LogInformation(" Expected file path: {Path}", filePath); + + if (File.Exists(filePath)) + { + var fileAge = DateTime.UtcNow - File.GetLastWriteTimeUtc(filePath); + _logger.LogInformation(" File exists! Age: {Age:F1}h", fileAge.TotalHours); + + if (fileAge < TimeSpan.FromHours(24)) + { + _logger.LogInformation(" ✓ Found recent file cache (age: {Age:F1}h)", fileAge.TotalHours); + + // Load from file into Redis if not already there + var key = $"spotify:missing:{playlistName}"; + if (!await _cache.ExistsAsync(key)) + { + _logger.LogInformation(" Loading into Redis..."); + await LoadFromFileCache(playlistName); + } + else + { + _logger.LogInformation(" Already in Redis"); + } + return false; + } + else + { + _logger.LogInformation(" File too old ({Age:F1}h > 24h), will fetch new", fileAge.TotalHours); + } + } + else + { + _logger.LogInformation(" File does not exist at expected path"); + } + var cacheKey = $"spotify:missing:{playlistName}"; if (await _cache.ExistsAsync(cacheKey)) { - return false; // Already have recent data + _logger.LogInformation(" ✓ Found in Redis cache"); + return false; + } + else + { + _logger.LogInformation(" Not in Redis cache"); } } - return true; // No recent data, should fetch + + _logger.LogInformation("=== NO RECENT CACHE FOUND - WILL FETCH ==="); + return true; + } + + private string GetCacheFilePath(string playlistName) + { + var safeName = string.Join("_", playlistName.Split(Path.GetInvalidFileNameChars())); + return Path.Combine(CacheDirectory, $"{safeName}_missing.json"); + } + + private async Task LoadFromFileCache(string playlistName) + { + try + { + var filePath = GetCacheFilePath(playlistName); + if (!File.Exists(filePath)) + return; + + var json = await File.ReadAllTextAsync(filePath); + var tracks = JsonSerializer.Deserialize>(json); + + if (tracks != null && tracks.Count > 0) + { + var cacheKey = $"spotify:missing:{playlistName}"; + var fileAge = DateTime.UtcNow - File.GetLastWriteTimeUtc(filePath); + var ttl = TimeSpan.FromHours(24) - fileAge; + + if (ttl > TimeSpan.Zero) + { + await _cache.SetAsync(cacheKey, tracks, ttl); + _logger.LogInformation("Loaded {Count} tracks from file cache for {Playlist}", + tracks.Count, playlistName); + } + } + } + catch (Exception ex) + { + _logger.LogWarning(ex, "Failed to load file cache for {Playlist}", playlistName); + } + } + + private async Task SaveToFileCache(string playlistName, List tracks) + { + try + { + var filePath = GetCacheFilePath(playlistName); + var json = JsonSerializer.Serialize(tracks, new JsonSerializerOptions { WriteIndented = true }); + await File.WriteAllTextAsync(filePath, json); + _logger.LogInformation("Saved {Count} tracks to file cache for {Playlist}", + tracks.Count, playlistName); + } + catch (Exception ex) + { + _logger.LogError(ex, "Failed to save file cache for {Playlist}", playlistName); + } } - private async Task FetchMissingTracksAsync(CancellationToken cancellationToken) + private async Task FetchMissingTracksAsync(CancellationToken cancellationToken, bool bypassSyncWindowCheck = false) { var settings = _spotifySettings.Value; var now = DateTime.UtcNow; @@ -146,18 +275,31 @@ public class SpotifyMissingTracksFetcher : BackgroundService .AddMinutes(settings.SyncStartMinute); var syncEnd = syncStart.AddHours(settings.SyncWindowHours); - // Only run after the sync window has passed - if (now < syncEnd) + // Only run after the sync window has passed (unless bypassing for startup) + if (!bypassSyncWindowCheck && now < syncEnd) { + _logger.LogInformation("Skipping fetch - sync window not passed yet (now: {Now}, window ends: {End})", + now, syncEnd); return; } - _logger.LogInformation("Sync window passed, searching last 24 hours for missing tracks..."); + if (bypassSyncWindowCheck) + { + _logger.LogInformation("=== FETCHING MISSING TRACKS (STARTUP MODE) ==="); + } + else + { + _logger.LogInformation("=== FETCHING MISSING TRACKS (SYNC WINDOW PASSED) ==="); + } + _logger.LogInformation("Processing {Count} playlists", _playlistIdToName.Count); foreach (var kvp in _playlistIdToName) { + _logger.LogInformation("Fetching playlist: {Name}", kvp.Value); await FetchPlaylistMissingTracksAsync(kvp.Value, cancellationToken); } + + _logger.LogInformation("=== FINISHED FETCHING MISSING TRACKS ==="); } private async Task FetchPlaylistMissingTracksAsync( @@ -168,13 +310,22 @@ public class SpotifyMissingTracksFetcher : BackgroundService if (await _cache.ExistsAsync(cacheKey)) { - _logger.LogDebug("Cache already exists for {Playlist}", playlistName); + _logger.LogInformation(" ✓ Cache already exists for {Playlist}, skipping fetch", playlistName); return; } + _logger.LogInformation(" No cache found, will search for missing tracks file..."); + var settings = _spotifySettings.Value; var jellyfinUrl = _jellyfinSettings.Value.Url; var apiKey = _jellyfinSettings.Value.ApiKey; + + if (string.IsNullOrEmpty(jellyfinUrl) || string.IsNullOrEmpty(apiKey)) + { + _logger.LogWarning(" Jellyfin URL or API key not configured, skipping fetch"); + return; + } + var httpClient = _httpClientFactory.CreateClient(); // Start from the configured sync time (most likely time) @@ -186,12 +337,12 @@ public class SpotifyMissingTracksFetcher : BackgroundService // If we haven't reached today's sync time yet, start from yesterday's sync time var syncTime = now >= todaySync ? todaySync : todaySync.AddDays(-1); - _logger.LogInformation("Searching ±12 hours around {SyncTime} for {Playlist}", - syncTime, playlistName); + _logger.LogInformation(" Searching +12h forward, -24h backward from {SyncTime}", syncTime); var found = false; // Search forward 12 hours from sync time + _logger.LogInformation(" Phase 1: Searching forward 12 hours from sync time..."); for (var minutesAhead = 0; minutesAhead <= 720; minutesAhead++) // 720 minutes = 12 hours { if (cancellationToken.IsCancellationRequested) break; @@ -210,10 +361,11 @@ public class SpotifyMissingTracksFetcher : BackgroundService } } - // Then search backwards 12 hours from sync time + // Then search backwards 24 hours from sync time to catch yesterday's file if (!found) { - for (var minutesBehind = 1; minutesBehind <= 720; minutesBehind++) + _logger.LogInformation(" Phase 2: Searching backward 24 hours from sync time..."); + for (var minutesBehind = 1; minutesBehind <= 1440; minutesBehind++) // 1440 minutes = 24 hours { if (cancellationToken.IsCancellationRequested) break; @@ -234,7 +386,7 @@ public class SpotifyMissingTracksFetcher : BackgroundService if (!found) { - _logger.LogWarning("Could not find missing tracks file for {Playlist} in ±12 hour window", playlistName); + _logger.LogWarning(" ✗ Could not find missing tracks file (searched +12h/-24h window)"); } } @@ -262,7 +414,11 @@ public class SpotifyMissingTracksFetcher : BackgroundService if (tracks.Count > 0) { var cacheKey = $"spotify:missing:{playlistName}"; + + // Save to both Redis and file await _cache.SetAsync(cacheKey, tracks, TimeSpan.FromHours(24)); + await SaveToFileCache(playlistName, tracks); + _logger.LogInformation( "✓ Cached {Count} missing tracks for {Playlist} from {Filename}", tracks.Count, playlistName, filename); diff --git a/docker-compose.yml b/docker-compose.yml index 73f572e..ec79566 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -93,6 +93,8 @@ services: - Qobuz__Quality=${QOBUZ_QUALITY:-FLAC} volumes: - ${DOWNLOAD_PATH:-./downloads}:/app/downloads + - ${KEPT_PATH:-./kept}:/app/kept + - ${CACHE_PATH:-./cache}:/app/cache networks: allstarr-network: