From c54a32ccfc827fe939519177d5a480c248d058dd Mon Sep 17 00:00:00 2001 From: Josh Patra Date: Sun, 1 Feb 2026 11:28:00 -0500 Subject: [PATCH] Add extensive logging to debug startup cache loading - List all files in cache directory on startup - Show expected file paths and actual file existence - Log each step of cache checking process - Add phase indicators for forward/backward search - Show when cache exists and fetch is skipped - Help diagnose why yesterday's cache files aren't being loaded --- .../Spotify/SpotifyMissingTracksFetcher.cs | 84 ++++++++++++++++--- 1 file changed, 73 insertions(+), 11 deletions(-) diff --git a/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs b/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs index d377cc8..d3775ff 100644 --- a/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs +++ b/allstarr/Services/Spotify/SpotifyMissingTracksFetcher.cs @@ -129,35 +129,88 @@ public class SpotifyMissingTracksFetcher : BackgroundService private async Task ShouldRunOnStartupAsync() { + _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 for {Playlist} (age: {Age:F1}h)", - playlistName, fileAge.TotalHours); + _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) @@ -225,22 +278,28 @@ public class SpotifyMissingTracksFetcher : BackgroundService // 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; } if (bypassSyncWindowCheck) { - _logger.LogInformation("Fetching missing tracks (startup mode, bypassing sync window check)..."); + _logger.LogInformation("=== FETCHING MISSING TRACKS (STARTUP MODE) ==="); } else { - _logger.LogInformation("Sync window passed, searching last 24 hours for missing tracks..."); + _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( @@ -251,17 +310,19 @@ 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 for {Playlist}", playlistName); + _logger.LogWarning(" Jellyfin URL or API key not configured, skipping fetch"); return; } @@ -276,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 ±12 hours around {SyncTime}", syncTime); var found = false; // Search forward 12 hours from sync time + _logger.LogInformation(" Phase 1: Searching forward from sync time..."); for (var minutesAhead = 0; minutesAhead <= 720; minutesAhead++) // 720 minutes = 12 hours { if (cancellationToken.IsCancellationRequested) break; @@ -303,6 +364,7 @@ public class SpotifyMissingTracksFetcher : BackgroundService // Then search backwards 12 hours from sync time if (!found) { + _logger.LogInformation(" Phase 2: Searching backward from sync time..."); for (var minutesBehind = 1; minutesBehind <= 720; minutesBehind++) { if (cancellationToken.IsCancellationRequested) break; @@ -324,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 in ±12 hour window"); } }