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
This commit is contained in:
2026-02-01 11:28:00 -05:00
parent c0c7668cc4
commit c54a32ccfc

View File

@@ -129,35 +129,88 @@ public class SpotifyMissingTracksFetcher : BackgroundService
private async Task<bool> 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");
}
}