diff --git a/allstarr/Services/Common/BaseDownloadService.cs b/allstarr/Services/Common/BaseDownloadService.cs index 68012c1..9e971a7 100644 --- a/allstarr/Services/Common/BaseDownloadService.cs +++ b/allstarr/Services/Common/BaseDownloadService.cs @@ -95,22 +95,50 @@ public abstract class BaseDownloadService : IDownloadService public async Task DownloadAndStreamAsync(string externalProvider, string externalId, CancellationToken cancellationToken = default) { + var startTime = DateTime.UtcNow; + // Check if already downloaded locally var localPath = await LocalLibraryService.GetLocalPathForExternalSongAsync(externalProvider, externalId); if (localPath != null && IOFile.Exists(localPath)) { - Logger.LogInformation("Streaming from local cache: {Path}", localPath); + var elapsed = (DateTime.UtcNow - startTime).TotalMilliseconds; + Logger.LogInformation("Streaming from local cache ({ElapsedMs}ms): {Path}", elapsed, localPath); + + // Update access time for cache cleanup + if (SubsonicSettings.StorageMode == StorageMode.Cache) + { + IOFile.SetLastAccessTime(localPath, DateTime.UtcNow); + } + return IOFile.OpenRead(localPath); } - // For on-demand streaming, download to disk first to ensure complete file + // Download to disk first to ensure complete file with metadata // This is necessary because: // 1. Clients may seek to arbitrary positions (requires full file) // 2. Metadata embedding requires complete file // 3. Caching for future plays Logger.LogInformation("Downloading song for streaming: {Provider}:{ExternalId}", externalProvider, externalId); - localPath = await DownloadSongInternalAsync(externalProvider, externalId, triggerAlbumDownload: true, cancellationToken); - return IOFile.OpenRead(localPath); + + try + { + localPath = await DownloadSongInternalAsync(externalProvider, externalId, triggerAlbumDownload: true, cancellationToken); + var elapsed = (DateTime.UtcNow - startTime).TotalMilliseconds; + Logger.LogInformation("Download completed, starting stream ({ElapsedMs}ms total): {Path}", elapsed, localPath); + return IOFile.OpenRead(localPath); + } + catch (OperationCanceledException) + { + var elapsed = (DateTime.UtcNow - startTime).TotalMilliseconds; + Logger.LogWarning("Download cancelled by client after {ElapsedMs}ms for {Provider}:{ExternalId}", elapsed, externalProvider, externalId); + throw; + } + catch (Exception ex) + { + var elapsed = (DateTime.UtcNow - startTime).TotalMilliseconds; + Logger.LogError(ex, "Download failed after {ElapsedMs}ms for {Provider}:{ExternalId}", elapsed, externalProvider, externalId); + throw; + } } public DownloadInfo? GetDownloadStatus(string songId) @@ -219,21 +247,26 @@ public abstract class BaseDownloadService : IDownloadService // Check if download in progress if (ActiveDownloads.TryGetValue(songId, out var activeDownload) && activeDownload.Status == DownloadStatus.InProgress) { - Logger.LogInformation("Download already in progress for {SongId}, waiting...", songId); + Logger.LogDebug("Download already in progress for {SongId}, waiting for completion...", songId); // Release lock while waiting DownloadLock.Release(); + // Wait for download to complete, checking every 100ms (faster than 500ms) + // Also respect cancellation token so client timeouts are handled immediately while (ActiveDownloads.TryGetValue(songId, out activeDownload) && activeDownload.Status == DownloadStatus.InProgress) { - await Task.Delay(500, cancellationToken); + cancellationToken.ThrowIfCancellationRequested(); + await Task.Delay(100, cancellationToken); } if (activeDownload?.Status == DownloadStatus.Completed && activeDownload.LocalPath != null) { + Logger.LogDebug("Download completed while waiting, returning path: {Path}", activeDownload.LocalPath); return activeDownload.LocalPath; } - throw new Exception(activeDownload?.ErrorMessage ?? "Download failed"); + // Download failed or was cancelled + throw new Exception(activeDownload?.ErrorMessage ?? "Download failed while waiting"); } // Get metadata