diff --git a/DeepDrftPublic.Client/Clients/TrackMediaClient.cs b/DeepDrftPublic.Client/Clients/TrackMediaClient.cs index cd715e1..fa65636 100644 --- a/DeepDrftPublic.Client/Clients/TrackMediaClient.cs +++ b/DeepDrftPublic.Client/Clients/TrackMediaClient.cs @@ -3,6 +3,7 @@ using System.Net.Http.Headers; using System.Net.Http.Json; using DeepDrftModels.DTOs; using DeepDrftModels.Enums; +using Microsoft.AspNetCore.Components.WebAssembly.Http; using Microsoft.Extensions.DependencyInjection; using NetBlocks.Models; @@ -79,6 +80,18 @@ public class TrackMediaClient using var request = new HttpRequestMessage(HttpMethod.Get, uri); request.Headers.Range = new RangeHeaderValue(byteOffset, null); + // Stream the response body incrementally instead of buffering it whole (Phase 21.4 fix). + // In Blazor WebAssembly the HttpClient is backed by the browser fetch API; without this the + // browser buffers the ENTIRE body before the response stream yields a byte, so the 21.2 + // read-loop pause (StreamingAudioPlayerService) backpressures nothing — the whole payload is + // already in memory. Enabling streaming makes ReadAsync pull from a browser ReadableStream + // whose backpressure reaches the underlying fetch, so pausing reads genuinely throttles the + // network. This is a request-option flag, not a runtime call: on the SSR server-to-server path + // the SocketsHttpHandler simply ignores the unknown option, so it is safe unguarded. Applies to + // BOTH the initial stream (byteOffset 0) and the seek/refill Range requests (21.3) — both share + // this method, so both depend on the same backpressure. + request.SetBrowserResponseStreamingEnabled(true); + // Use HttpCompletionOption.ResponseHeadersRead to get stream immediately var response = await _http.SendAsync(request, HttpCompletionOption.ResponseHeadersRead, cancellationToken); response.EnsureSuccessStatusCode(); diff --git a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs index d3b6439..3996dd0 100644 --- a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs +++ b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs @@ -35,6 +35,14 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS public int BufferedChunks { get; private set; } = 0; public bool IsSeekingBeyondBuffer { get; private set; } = false; + // ─────────────────────────────────────────────────────────────────────────────────────────── + // [BP-DIAG] Phase 21.4 back-pressure diagnostic. TEMPORARY — strip once the cause is confirmed + // in Daniel's browser run. Logs every Nth chunk's ProductionPaused flag plus pause-poll + // enter/exit so a grep for "[BP-DIAG]" in the WASM console tells whether the read loop ever sees + // the pause signal and whether the poll actually holds. Throttled by chunk count to avoid flooding. + private const int BpDiagChunkLogEvery = 16; + // ─────────────────────────────────────────────────────────────────────────────────────────── + private bool _streamingPlaybackStarted = false; private CancellationTokenSource? _streamingCancellation; private Task? _activeStreamingTask; @@ -386,6 +394,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS buffer = ArrayPool.Shared.Rent(MaxBufferSize); // Rent larger buffer to accommodate adaptive sizing int currentBytes; var readTimer = System.Diagnostics.Stopwatch.StartNew(); + var bpDiagChunkIndex = 0; // [BP-DIAG] per-stream chunk counter for throttled logging do { @@ -420,6 +429,20 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS HeaderParsed = chunkResult.HeaderParsed; BufferedChunks = chunkResult.BufferCount; + // [BP-DIAG] Phase 21.4 — throttled per-chunk view of the back-pressure signal as + // the C# loop sees it. If ProductionPaused never logs True while bytes keep + // flowing, the break is upstream (JS latch / lookahead math); if it logs True but + // the transfer still races to 100%, the break is the transport (browser buffered + // the whole body, SetBrowserResponseStreamingEnabled not in effect). TEMPORARY. + if (bpDiagChunkIndex % BpDiagChunkLogEvery == 0) + { + _logger.LogInformation( + "[BP-DIAG] chunk #{Chunk} bytesRead={Bytes} totalRead={Total} bufferCount={BufCount} canStart={CanStart} productionPaused={Paused} isPaused={IsPaused}", + bpDiagChunkIndex, currentBytes, totalBytesRead, chunkResult.BufferCount, + chunkResult.CanStartStreaming, chunkResult.ProductionPaused, IsPaused); + } + bpDiagChunkIndex++; + // Set duration from WAV header when available (only set once) if (chunkResult.Duration.HasValue && Duration == null) { @@ -487,6 +510,15 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS // no separate cancellation path, no stale read racing a reinit. if (chunkResult.ProductionPaused) { + // [BP-DIAG] Phase 21.4 — the read loop is ENTERING the pause-poll: reads have + // stopped, the socket should now stall and the transfer should plateau. If you + // see this line but the network transfer still completes, the transport is + // buffered (streaming flag not in effect). TEMPORARY. + _logger.LogInformation( + "[BP-DIAG] ENTER pause-poll at chunk #{Chunk} totalRead={Total} isPaused={IsPaused}", + bpDiagChunkIndex, totalBytesRead, IsPaused); + var bpDiagPollCount = 0; + // UC5: while the user is paused, the playhead is frozen so forward lookahead // never shrinks and the poll would spin indefinitely. Wait here until playback // resumes (IsPaused clears) OR the fill drains on its own. Cancellation is @@ -495,8 +527,23 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS while (IsPaused || await _audioInterop.IsProductionPaused(PlayerId)) { cancellationToken.ThrowIfCancellationRequested(); + // [BP-DIAG] Phase 21.4 — heartbeat every ~1 s (10 × 100 ms) so a held poll + // is visible without flooding; shows the loop is genuinely parked. TEMPORARY. + if (bpDiagPollCount % 10 == 0) + { + _logger.LogInformation( + "[BP-DIAG] HOLD pause-poll iter={Iter} isPaused={IsPaused}", + bpDiagPollCount, IsPaused); + } + bpDiagPollCount++; await Task.Delay(BackpressurePollMs, cancellationToken); } + + // [BP-DIAG] Phase 21.4 — the read loop is EXITING the pause-poll and resuming + // ReadAsync: the fill drained below low-water. TEMPORARY. + _logger.LogInformation( + "[BP-DIAG] EXIT pause-poll at chunk #{Chunk} after {Iters} polls", + bpDiagChunkIndex, bpDiagPollCount); } } } while (currentBytes > 0); diff --git a/DeepDrftPublic/Interop/audio/AudioPlayer.ts b/DeepDrftPublic/Interop/audio/AudioPlayer.ts index d33572f..6577294 100644 --- a/DeepDrftPublic/Interop/audio/AudioPlayer.ts +++ b/DeepDrftPublic/Interop/audio/AudioPlayer.ts @@ -269,13 +269,19 @@ export class AudioPlayer { const headerParsed = decoder.ready; const canStart = headerParsed && this.scheduler.hasMinimumBuffers(this.minBuffersForPlayback); + // [BP-DIAG] Phase 21.4 — value of productionPaused actually placed on the Opus chunk + // result handed to C#. Confirms the flag is populated on THIS path (not just the WAV + // path). TEMPORARY — strip once confirmed. + const opusPaused = this.scheduler.evaluateProductionPause(); + this.bpDiagLogChunkResult('opus', canStart, opusPaused); + return { success: true, canStartStreaming: canStart, headerParsed, bufferCount: this.scheduler.getBufferCount(), duration: this.duration, - productionPaused: this.scheduler.evaluateProductionPause() + productionPaused: opusPaused }; } catch (error) { return { success: false, error: (error as Error).message }; @@ -314,13 +320,18 @@ export class AudioPlayer { const canStart = this.streamDecoder.headerParsed && this.scheduler.hasMinimumBuffers(this.minBuffersForPlayback); + // [BP-DIAG] Phase 21.4 — value of productionPaused actually placed on the WAV/MP3/FLAC + // chunk result handed to C#. TEMPORARY — strip once confirmed. + const formatPaused = this.scheduler.evaluateProductionPause(); + this.bpDiagLogChunkResult('format', canStart, formatPaused); + return { success: true, canStartStreaming: canStart, headerParsed: this.streamDecoder.headerParsed, bufferCount: this.scheduler.getBufferCount(), duration: this.duration, - productionPaused: this.scheduler.evaluateProductionPause() + productionPaused: formatPaused }; } catch (error) { return { success: false, error: (error as Error).message }; @@ -731,6 +742,21 @@ export class AudioPlayer { // ==================== Private Methods ==================== + // ───────────────────────────────────────────────────────────────────────────────────────── + // [BP-DIAG] Phase 21.4 back-pressure diagnostic. TEMPORARY — strip once confirmed in Daniel's + // browser run. Logs the productionPaused flag on the chunk result handed back to C#, throttled + // to ~4 Hz so it does not flood. Grep "[BP-DIAG] chunk-result" in the browser console. + private bpDiagChunkResultLastMs = 0; + private bpDiagLogChunkResult(path: 'opus' | 'format', canStart: boolean, paused: boolean): void { + const now = (typeof performance !== 'undefined' ? performance.now() : Date.now()); + if (now - this.bpDiagChunkResultLastMs < 250) return; + this.bpDiagChunkResultLastMs = now; + console.log( + `[BP-DIAG] chunk-result path=${path} productionPaused=${paused} canStart=${canStart} ` + + `bufCount=${this.scheduler.getBufferCount()} streamingStarted=${this.streamingStarted} isPlaying=${this.isPlaying}`); + } + // ───────────────────────────────────────────────────────────────────────────────────────── + private resetState(): void { this.isPlaying = false; this.isPaused = false; diff --git a/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts b/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts index 5379130..341e0e3 100644 --- a/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts +++ b/DeepDrftPublic/Interop/audio/PlaybackScheduler.ts @@ -107,6 +107,14 @@ export class PlaybackScheduler { // Mutated by evaluateProductionPause() — named to signal the state-advance on each call. private productionPaused_: boolean = false; + // ───────────────────────────────────────────────────────────────────────────────────────── + // [BP-DIAG] Phase 21.4 back-pressure diagnostic. TEMPORARY — strip once the cause is confirmed + // in Daniel's browser run. Throttles evaluateProductionPause() logging to one line per ~250 ms + // so the console shows the live lookahead / byte-estimate / latch without flooding (the signal + // is evaluated on every chunk + every poll). Grep "[BP-DIAG]" in the browser console. + private bpDiagLastLogMs: number = 0; + // ───────────────────────────────────────────────────────────────────────────────────────── + // Callbacks public onPlaybackEnded: (() => void) | null = null; @@ -237,6 +245,22 @@ export class PlaybackScheduler { this.productionPaused_ = true; } + // [BP-DIAG] Phase 21.4 — the single source of truth for the latch decision. If `paused` + // never goes true while bytes keep arriving, the lookahead is not growing as expected: + // inspect `lookahead` vs `high` (should cross 30 during a fast fill) and `bufCount`/`bytes` + // (decode must actually be populating the scheduler). Throttled to ~4 Hz. TEMPORARY — strip + // once the cause is confirmed. (Uses performance.now when present; Date.now fallback.) + const bpNow = (typeof performance !== 'undefined' ? performance.now() : Date.now()); + if (bpNow - this.bpDiagLastLogMs >= 250) { + this.bpDiagLastLogMs = bpNow; + console.log( + `[BP-DIAG] evaluateProductionPause paused=${this.productionPaused_} ` + + `lookahead=${lookahead.toFixed(2)}s high=${this.forwardHighWaterSeconds} low=${this.forwardLowWaterSeconds} ` + + `bytes=${(this.getDecodedByteEstimate() / (1024 * 1024)).toFixed(1)}MB cap=${(this.maxDecodedBytes / (1024 * 1024)).toFixed(0)}MB ` + + `overByteCeiling=${overByteCeiling} bufCount=${this.buffers.length} pos=${this.getCurrentPosition().toFixed(2)}s ` + + `decodedEnd=${(this.getTotalDuration() + this.playbackOffset).toFixed(2)}s active=${this.isActive_}`); + } + return this.productionPaused_; } diff --git a/DeepDrftTests/TrackMediaStreamingEnabledTests.cs b/DeepDrftTests/TrackMediaStreamingEnabledTests.cs new file mode 100644 index 0000000..dc0501a --- /dev/null +++ b/DeepDrftTests/TrackMediaStreamingEnabledTests.cs @@ -0,0 +1,80 @@ +using System.Net; +using DeepDrftModels.Enums; +using DeepDrftPublic.Client.Clients; + +namespace DeepDrftTests; + +/// +/// Pins the Phase 21.4 transport fix: every audio media fetch must carry the browser response-streaming +/// option so the body streams incrementally in WASM. Without it the browser buffers the whole payload +/// before the response stream yields a byte, and the 21.2 read-loop pause backpressures nothing. +/// +/// The flag is set by SetBrowserResponseStreamingEnabled(true), which records it in +/// under the framework key "WebAssemblyEnableStreamingResponse". +/// A stub handler reads that option back during SendAsync — the same network-boundary fake the Opus +/// format-selection tests use. True network backpressure is browser-only and cannot be unit-profiled; this +/// asserts the request is *configured* for streaming, which is the part the harness can observe. Daniel's +/// 21.4 manual re-run confirms the actual bounded-memory behaviour. +/// +/// Both the initial full-stream request (byteOffset 0) and the seek/refill Range request (byteOffset > 0, +/// Phase 21.3) flow through , so both are asserted here. +/// +[TestFixture] +public class TrackMediaStreamingEnabledTests +{ + // The framework key SetBrowserResponseStreamingEnabled writes into HttpRequestMessage.Options. + private static readonly HttpRequestOptionsKey StreamingOptionKey = new("WebAssemblyEnableStreamingResponse"); + + // Captures the streaming option off each outgoing request, then returns a minimal 200 with a body so + // GetTrackMedia reaches its pass path (ReadAsStreamAsync over ByteArrayContent). + private sealed class CapturingHandler : HttpMessageHandler + { + public bool? StreamingEnabled { get; private set; } + + protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + StreamingEnabled = request.Options.TryGetValue(StreamingOptionKey, out var enabled) ? enabled : null; + + var response = new HttpResponseMessage(HttpStatusCode.OK) + { + Content = new ByteArrayContent("audio-bytes"u8.ToArray()), + }; + return Task.FromResult(response); + } + } + + private sealed class SingleClientFactory : IHttpClientFactory + { + private readonly HttpMessageHandler _handler; + public SingleClientFactory(HttpMessageHandler handler) => _handler = handler; + + public HttpClient CreateClient(string name) => + new(_handler, disposeHandler: false) { BaseAddress = new Uri("https://content.test/") }; + } + + [Test] + public async Task GetTrackMedia_InitialStream_EnablesBrowserResponseStreaming() + { + var handler = new CapturingHandler(); + var client = new TrackMediaClient(new SingleClientFactory(handler)); + + var result = await client.GetTrackMedia("track-1", byteOffset: 0, format: AudioFormat.Lossless); + + Assert.That(result.Success, Is.True, "the fetch should succeed against the stub"); + Assert.That(handler.StreamingEnabled, Is.True, + "the initial media stream must enable browser response streaming or the read-loop pause backpressures nothing"); + } + + [Test] + public async Task GetTrackMedia_SeekOffsetStream_EnablesBrowserResponseStreaming() + { + var handler = new CapturingHandler(); + var client = new TrackMediaClient(new SingleClientFactory(handler)); + + var result = await client.GetTrackMedia("track-1", byteOffset: 1_048_576, format: AudioFormat.Opus); + + Assert.That(result.Success, Is.True, "the offset fetch should succeed against the stub"); + Assert.That(handler.StreamingEnabled, Is.True, + "the seek/refill Range request must also enable streaming — 21.3 refill depends on the same backpressure"); + } +}