diff --git a/DeepDrftManager/Program.cs b/DeepDrftManager/Program.cs index 5b875c6..923f8dd 100644 --- a/DeepDrftManager/Program.cs +++ b/DeepDrftManager/Program.cs @@ -44,17 +44,26 @@ builder.Services.AddHttpClient("DeepDrft.Content", client => client.BaseAddress = new Uri(contentApiUrl); }); -// Named HttpClient for ApiKey-protected Content API calls (CmsTrackService's vault delete). -// API key baked into the default request headers so callers need not add it manually. +// Named HttpClient for ApiKey-protected Content API calls (CmsTrackService's non-upload operations: +// delete, paged list, metadata read/write, waveform jobs, releases, genres). +// Timeout left at the default 100s — these are short request/response pairs and an infinite timeout +// would hang an InteractiveServer circuit forever on a dead connection. var contentApiKey = builder.Configuration["Api:ContentApiKey"] ?? throw new InvalidOperationException("Api:ContentApiKey is required"); builder.Services.AddHttpClient("DeepDrft.Content.Cms", client => { client.BaseAddress = new Uri(contentApiUrl); client.DefaultRequestHeaders.Add("ApiKey", contentApiKey); - // Large mix uploads (several hundred MB) outrun the 100s default whole-request timeout. The send - // path enforces an idle/heartbeat deadline instead (CmsTrackService), which can only express - // "no bytes for N seconds" if the client itself does not impose a total cap — hence Infinite here. +}); + +// Dedicated upload client — inherits the API key but removes the whole-request timeout. +// Large WAV uploads (several hundred MB) outrun the 100s default. The upload path enforces an +// idle/heartbeat deadline instead (body-streaming phase via ProgressStreamContent) plus a separate +// response-wait budget (CmsTrackService), so the client itself must not impose a total cap. +builder.Services.AddHttpClient("DeepDrft.Content.Cms.Upload", client => +{ + client.BaseAddress = new Uri(contentApiUrl); + client.DefaultRequestHeaders.Add("ApiKey", contentApiKey); client.Timeout = Timeout.InfiniteTimeSpan; }); diff --git a/DeepDrftManager/Services/CmsTrackService.cs b/DeepDrftManager/Services/CmsTrackService.cs index f588943..a84c971 100644 --- a/DeepDrftManager/Services/CmsTrackService.cs +++ b/DeepDrftManager/Services/CmsTrackService.cs @@ -18,16 +18,26 @@ namespace DeepDrftManager.Services; public class CmsTrackService : ICmsTrackService { private const string ContentCmsClientName = "DeepDrft.Content.Cms"; + private const string UploadClientName = "DeepDrft.Content.Cms.Upload"; private const string UploadPath = "api/track/upload"; // Idle/heartbeat window: abort an upload only after this long with zero bytes written to the wire. // The window resets on every progress tick, so a slow-but-moving half-gig upload never trips it; - // a genuinely stalled socket does. Operator-tunable via Upload:IdleTimeoutSeconds. + // a genuinely stalled socket does. Governs the BODY-STREAMING phase only. + // Operator-tunable via Upload:IdleTimeoutSeconds. private const int DefaultIdleTimeoutSeconds = 90; + // Response-wait budget: once the request body is fully on the wire the server runs AudioProcessor + // decode → vault write → SQL persist. For a several-hundred-MB WAV this can take many minutes. + // The idle heartbeat goes silent after the last byte, so a separate, larger deadline governs the + // response-wait phase so a fully-uploaded file is never killed mid-persist. + // Operator-tunable via Upload:ResponseTimeoutSeconds. + private const int DefaultResponseTimeoutSeconds = 600; // 10 minutes + private readonly IHttpClientFactory _httpClientFactory; private readonly ILogger _logger; private readonly TimeSpan _uploadIdleTimeout; + private readonly TimeSpan _uploadResponseTimeout; public CmsTrackService( IHttpClientFactory httpClientFactory, @@ -36,8 +46,10 @@ public class CmsTrackService : ICmsTrackService { _httpClientFactory = httpClientFactory; _logger = logger; - var seconds = configuration.GetValue("Upload:IdleTimeoutSeconds") ?? DefaultIdleTimeoutSeconds; - _uploadIdleTimeout = TimeSpan.FromSeconds(seconds > 0 ? seconds : DefaultIdleTimeoutSeconds); + var idleSeconds = configuration.GetValue("Upload:IdleTimeoutSeconds") ?? DefaultIdleTimeoutSeconds; + _uploadIdleTimeout = TimeSpan.FromSeconds(idleSeconds > 0 ? idleSeconds : DefaultIdleTimeoutSeconds); + var responseSeconds = configuration.GetValue("Upload:ResponseTimeoutSeconds") ?? DefaultResponseTimeoutSeconds; + _uploadResponseTimeout = TimeSpan.FromSeconds(responseSeconds > 0 ? responseSeconds : DefaultResponseTimeoutSeconds); } public async Task> UploadTrackAsync( @@ -59,22 +71,52 @@ public class CmsTrackService : ICmsTrackService IProgress? progress = null, CancellationToken ct = default) { - // Idle/heartbeat cancellation: HttpClient.Timeout is a whole-request cap and cannot express - // "no bytes for N seconds", so the named client runs with InfiniteTimeSpan and the deadline - // lives here. Each ProgressStreamContent tick resets CancelAfter(idle); a stalled socket lets - // the window elapse and cancels the send. Linked to the caller's ct so a page cancel still wins. + // Two-phase cancellation for the upload send: + // + // BODY-STREAMING phase (while bytes are on the wire): + // idleCts fires if no progress tick arrives within the idle window. Each + // ProgressStreamContent chunk resets CancelAfter(idle), so a slow-but-moving + // upload never trips it; a genuinely stalled socket does. + // + // RESPONSE-WAIT phase (after the last byte, while the server persists): + // The idle heartbeat goes silent once the body is fully sent. responseCts is + // armed at that moment with a larger budget so a fully-uploaded file is never + // killed mid-persist. idleCts is simultaneously disarmed (CancelAfter(Infinite)) + // so it cannot misfire during the response-wait. + // + // sendCts links both so either deadline — plus the caller's ct — cancels the send. using var idleCts = CancellationTokenSource.CreateLinkedTokenSource(ct); idleCts.CancelAfter(_uploadIdleTimeout); + // responseCts starts disarmed; the body-complete callback below arms it. + using var responseCts = CancellationTokenSource.CreateLinkedTokenSource(ct); + + // Umbrella token passed to SendAsync — either phase token (or the caller) can cancel. + using var sendCts = CancellationTokenSource.CreateLinkedTokenSource(idleCts.Token, responseCts.Token); + // Rebuild the multipart container so the boundary is owned by HttpClient and the // caller-supplied stream (already buffered by the SignalR upload) is the source. using var multipart = new MultipartFormDataContent(); - var wavContent = new ProgressStreamContent(wavStream, contentLength, written => - { - // One mechanism, two consumers: advance the UI meter and reset the idle heartbeat. - progress?.Report(written); - idleCts.CancelAfter(_uploadIdleTimeout); - }); + var wavContent = new ProgressStreamContent( + wavStream, + contentLength, + written => + { + // One mechanism, three consumers: advance the UI meter, reset the idle heartbeat, + // and on body-complete transition to the response-wait budget. + progress?.Report(written); + if (written < contentLength) + { + // Body still in flight — keep the idle heartbeat alive. + idleCts.CancelAfter(_uploadIdleTimeout); + } + else + { + // Last byte on the wire. Disarm the idle timer and start the response budget. + idleCts.CancelAfter(Timeout.InfiniteTimeSpan); + responseCts.CancelAfter(_uploadResponseTimeout); + } + }); wavContent.Headers.ContentType = new MediaTypeHeaderValue( string.IsNullOrWhiteSpace(contentType) ? "audio/wav" : contentType); multipart.Add(wavContent, "audioFile", fileName); @@ -93,21 +135,31 @@ public class CmsTrackService : ICmsTrackService // for an unrecognised value). Authoritative only when this upload creates the release. multipart.Add(new StringContent(medium.ToString()), "medium"); - var client = _httpClientFactory.CreateClient(ContentCmsClientName); + // Use the dedicated upload client (InfiniteTimeSpan) so the two-phase CTS logic above is the + // sole timeout authority. Non-upload operations use the bounded "DeepDrft.Content.Cms" client. + var client = _httpClientFactory.CreateClient(UploadClientName); using var request = new HttpRequestMessage(HttpMethod.Post, UploadPath) { Content = multipart }; HttpResponseMessage response; try { - response = await client.SendAsync(request, HttpCompletionOption.ResponseHeadersRead, idleCts.Token); + response = await client.SendAsync(request, HttpCompletionOption.ResponseHeadersRead, sendCts.Token); } - catch (OperationCanceledException) when (idleCts.IsCancellationRequested && !ct.IsCancellationRequested) + catch (OperationCanceledException) when (!ct.IsCancellationRequested) { - // Idle window elapsed with no bytes moving — a stalled connection, not a caller cancel. - _logger.LogWarning("Upload of {TrackName} stalled — no progress for {IdleSeconds}s; aborting.", - trackName, _uploadIdleTimeout.TotalSeconds); + // Either idle window (body-streaming stall) or response-wait budget (server persist too slow). + if (idleCts.IsCancellationRequested) + { + _logger.LogWarning("Upload of {TrackName} stalled — no progress for {IdleSeconds}s; aborting.", + trackName, _uploadIdleTimeout.TotalSeconds); + return ResultContainer.CreateFailResult( + $"Upload stalled — no data transferred for {_uploadIdleTimeout.TotalSeconds:0}s. Please retry."); + } + // responseCts fired: body reached the server but persist timed out. + _logger.LogWarning("Upload of {TrackName} timed out waiting for server response after {ResponseSeconds}s.", + trackName, _uploadResponseTimeout.TotalSeconds); return ResultContainer.CreateFailResult( - $"Upload stalled — no data transferred for {_uploadIdleTimeout.TotalSeconds:0}s. Please retry."); + $"Upload timed out waiting for the server to respond after {_uploadResponseTimeout.TotalSeconds:0}s. Please retry."); } catch (Exception ex) { diff --git a/DeepDrftTests/ProgressStreamContentTests.cs b/DeepDrftTests/ProgressStreamContentTests.cs index da7e4eb..c87fe94 100644 --- a/DeepDrftTests/ProgressStreamContentTests.cs +++ b/DeepDrftTests/ProgressStreamContentTests.cs @@ -90,6 +90,97 @@ public class ProgressStreamContentTests Assert.That(idleCts.IsCancellationRequested, Is.True); } + // --- Two-phase deadline switching (Finding 1 regression test) --- + // After the last body byte is reported the idle timer must be disarmed and the response-wait + // budget must be armed. This test simulates the exact scenario that triggered Finding 1: + // the body streams quickly, then a long server-side lag (standing in for AudioProcessor + + // vault write + SQL persist) follows. The idle window is short; the response budget is long. + // With the fix the operation must complete; without it idleCts would fire during the lag. + + [Test] + public async Task PostBodyLag_DoesNotTriggerIdleTimeout_WhenResponseBudgetIsLarger() + { + var idle = TimeSpan.FromMilliseconds(150); + var responseBudget = TimeSpan.FromMilliseconds(600); + + using var idleCts = new CancellationTokenSource(); + idleCts.CancelAfter(idle); + using var responseCts = new CancellationTokenSource(); + // responseCts starts disarmed — same as in CmsTrackService. + using var sendCts = CancellationTokenSource.CreateLinkedTokenSource(idleCts.Token, responseCts.Token); + + const long contentLength = 4096; + var source = new PacedStream(chunkCount: 1, chunkSize: (int)contentLength, delayPerChunk: TimeSpan.FromMilliseconds(10)); + var content = new ProgressStreamContent(source, contentLength, written => + { + if (written < contentLength) + { + idleCts.CancelAfter(idle); + } + else + { + // Body complete — disarm idle, arm response budget (mirrors CmsTrackService). + idleCts.CancelAfter(Timeout.InfiniteTimeSpan); + responseCts.CancelAfter(responseBudget); + } + }); + + using var sink = new MemoryStream(); + await content.CopyToAsync(sink, sendCts.Token); + + // Body is done. Simulate a slow server (longer than idle window, shorter than response budget). + var serverLag = TimeSpan.FromMilliseconds(300); // > idle (150 ms), < response budget (600 ms) + await Task.Delay(serverLag, sendCts.Token); + + Assert.That(sendCts.IsCancellationRequested, Is.False, + "A post-body server lag within the response budget must not cancel the send token."); + Assert.That(idleCts.IsCancellationRequested, Is.False, + "The idle CTS must be disarmed after body completes."); + Assert.That(responseCts.IsCancellationRequested, Is.False, + "The response CTS must not have fired — server lag was within the response budget."); + } + + [Test] + public async Task PostBodyLag_CancelsViaResponseCts_WhenResponseBudgetExceeded() + { + var idle = TimeSpan.FromMilliseconds(200); + var responseBudget = TimeSpan.FromMilliseconds(150); + + using var idleCts = new CancellationTokenSource(); + idleCts.CancelAfter(idle); + using var responseCts = new CancellationTokenSource(); + using var sendCts = CancellationTokenSource.CreateLinkedTokenSource(idleCts.Token, responseCts.Token); + + const long contentLength = 4096; + var source = new PacedStream(chunkCount: 1, chunkSize: (int)contentLength, delayPerChunk: TimeSpan.FromMilliseconds(10)); + var content = new ProgressStreamContent(source, contentLength, written => + { + if (written < contentLength) + { + idleCts.CancelAfter(idle); + } + else + { + idleCts.CancelAfter(Timeout.InfiniteTimeSpan); + responseCts.CancelAfter(responseBudget); + } + }); + + using var sink = new MemoryStream(); + await content.CopyToAsync(sink, sendCts.Token); + + // Simulate a slow server that exceeds the response budget. + var serverLag = TimeSpan.FromMilliseconds(400); // > response budget (150 ms) + Assert.That( + async () => await Task.Delay(serverLag, sendCts.Token), + Throws.InstanceOf(), + "A post-body lag exceeding the response budget must cancel via sendCts."); + Assert.That(responseCts.IsCancellationRequested, Is.True, + "responseCts must be the source of the cancellation, not idleCts."); + Assert.That(idleCts.IsCancellationRequested, Is.False, + "idleCts must remain disarmed — the response budget fired, not the idle window."); + } + /// /// A read-only stream that yields a fixed number of equal chunks, pausing between reads to emulate /// network pacing. Optionally inserts a longer stall before a given chunk to emulate a stalled link.