diff --git a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs index cfffa6a..2e6badc 100644 --- a/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs +++ b/DeepDrftPublic.Client/Services/StreamingAudioPlayerService.cs @@ -64,16 +64,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS private readonly ILogger _logger; private string? _currentTrackId; - // The track key of the load currently in flight, set at LoadTrackStreaming entry BEFORE ResetToIdle - // (which clears _currentTrackId) and cleared only when that load's finally runs as the still-active - // operation. It is the idempotency key that collapses a duplicate same-track entry for ONE play - // action into the first load: a second SelectTrackStreaming for the SAME track while its load is - // still in flight is a redundant re-dispatch (UI double-fire, queue re-entry, or a JS false-end - // auto-advance back onto the same track), not a real track switch, so it is dropped. A load for a - // DIFFERENT track is a genuine switch and supersedes as before — this guard never suppresses it. - // Null when no load is in flight. - private string? _loadInFlightTrackId; - // Monotonic load-generation counter (diagnostic). Incremented on every LoadTrackStreaming entry and // stamped into the load's logs so two loads for ONE user play action — the "Duration set from header // logged twice" double-load hypothesis that needs in-browser confirmation — are unmistakable: a @@ -209,29 +199,19 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS private async Task LoadTrackStreaming(TrackDto track, double? startPosition = null) { - // Idempotency guard (single-load invariant). A load already in flight for THIS SAME track means - // a duplicate dispatch of one play action — a UI double-fire, a queue re-entry, or a JS false-end - // that auto-advanced back onto the same track. Dropping it collapses the play to exactly one load - // without touching the live operation. A load for a DIFFERENT track is a real switch and falls - // through to supersede the in-flight one exactly as before, so this never blocks navigation. The - // check is on the WASM single-threaded dispatcher, so reading/writing _loadInFlightTrackId needs - // no lock; the field is set below before the first await and cleared in finally for the active load. - if (_loadInFlightTrackId is { } inFlight && inFlight == track.EntryKey) - { - _logger.LogInformation( - "Streaming load for track {TrackId} skipped — a load for the same track is already in flight (single-load guard)", - track.EntryKey); - return; - } - _loadInFlightTrackId = track.EntryKey; + // [RELOAD-DIAG] Entry probe — captures every LoadTrackStreaming with its startPosition so a + // same-track reload (format switch) is distinguishable from a fresh play. _loadGeneration here + // is the PREVIOUS load's id (incremented below); it pins which generation this entry follows. + _logger.LogInformation( + "[RELOAD-DIAG] LoadTrackStreaming ENTRY track={TrackId} startPosition={StartPosition} (prevGen={Gen})", + track.EntryKey, startPosition?.ToString("F2") ?? "null", _loadGeneration); // Always reset to clean state before loading new track. ResetToIdle // both cancels and awaits any in-flight streaming loop, so by the time // we return from it the previous loop is guaranteed to have exited and // there is no risk of interleaved ProcessStreamingChunk calls against - // the single-instance JS StreamDecoder. clearLoadGuard:false — we just armed - // _loadInFlightTrackId for THIS load; the prologue reset must not wipe it. - await ResetToIdle(clearLoadGuard: false); + // the single-instance JS StreamDecoder. + await ResetToIdle("prologue"); // Stamp this load with a fresh generation id (diagnostic — see _loadGeneration). Logged at // start and finish so a double-load shows as two overlapping start/finish pairs for one play. @@ -403,17 +383,10 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS IsLoading = false; _logger.LogInformation("Streaming load #{Gen} finished for track {TrackId} (superseded={Superseded})", loadGeneration, track.EntryKey, !ReferenceEquals(_streamingCancellation, loadCts)); - // Release the single-load guard only when this load is still the active operation. A - // superseding load for a DIFFERENT track has already overwritten _loadInFlightTrackId with - // its own key before its first await; clearing it here would unlatch the guard mid-way - // through that newer load and let a duplicate of IT slip through. The CTS identity is the - // same "am I still the active operation?" test the notify/state guards use. ResetToIdle - // (the supersede path) does not touch this field — the incoming load owns its lifecycle. + // Only notify if this load is still the active operation. A superseding seek + // owns state notifications; firing here mid-seek would push a stale snapshot. if (ReferenceEquals(_streamingCancellation, loadCts)) { - _loadInFlightTrackId = null; - // Only notify if this load is still the active operation. A superseding seek - // owns state notifications; firing here mid-seek would push a stale snapshot. await NotifyStateChanged(); } } @@ -440,6 +413,11 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS double startPosition, CancellationToken cancellationToken) { + // [RELOAD-DIAG] Positioned-start entry (the format-switch / load-at-timestamp path). + _logger.LogInformation( + "[RELOAD-DIAG] StartFromPositionAsync ENTRY track={TrackId} startPosition={StartPosition:F2} (gen={Gen})", + trackId, startPosition, _loadGeneration); + // Resolve the byte offset for the target time. Opus answers immediately from its sidecar; WAV // returns failure until its header is parsed, so we probe the byte-0 segment and retry. The // byte-0 segment is disposed once it has served its purpose (header probe / nothing for Opus), @@ -536,6 +514,10 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS // Capture the once-only duration the header yields so the UI and play session have it. if (result.Duration.HasValue && Duration == null) { + // [RELOAD-DIAG] Header duration set via the probe path (StartFromPositionAsync probe). + _logger.LogInformation( + "[RELOAD-DIAG] Duration set from header (PROBE path) {Duration:F2}s (gen={Gen})", + result.Duration.Value, _loadGeneration); Duration = result.Duration.Value; _playTracker?.SetDuration(result.Duration.Value); } @@ -681,6 +663,13 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS double? seekPosition, CancellationToken cancellationToken) { + // [RELOAD-DIAG] Distinguishes a fresh forward load (seekPosition null) from a seek/refill re-entry + // (seekPosition non-null), which reinitializes the decoder — a candidate for a second header parse. + _logger.LogInformation( + "[RELOAD-DIAG] RunSegmentedStreamAsync ENTRY track={TrackId} cursor={Cursor} seekPosition={SeekPosition} kind={Kind} (gen={Gen})", + trackId, cursor, seekPosition?.ToString("F2") ?? "null", + seekPosition is null ? "forward-load" : "seek/refill-reentry", _loadGeneration); + byte[]? buffer = null; var segment = firstSegment; try @@ -747,6 +736,12 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS if (chunkResult.Duration.HasValue && Duration == null) { Duration = chunkResult.Duration.Value; + // [RELOAD-DIAG] Header duration set via the stream-loop path. The gen + seekPosition + // context (logged at RunSegmentedStreamAsync entry) tells whether this is the fresh + // forward load or a seek/refill re-entry re-parsing the header. + _logger.LogInformation( + "[RELOAD-DIAG] Duration set from header (STREAM-LOOP path) {Duration:F2}s (gen={Gen})", + Duration, _loadGeneration); _logger.LogInformation("Duration set from header: {Duration:F2} seconds", Duration); // Feed the once-only duration to the play session for the completion // fraction. No-op when no session is open; idempotent otherwise. @@ -923,7 +918,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS public override async Task Stop() { // In streaming mode, Stop = Unload (data is consumed, can't replay) - await ResetToIdle(); + await ResetToIdle("stop"); } /// @@ -931,7 +926,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// public override async Task Unload() { - await ResetToIdle(); + await ResetToIdle("unload"); } /// @@ -941,6 +936,9 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS { if (!IsLoaded || !IsStreamingMode) return; + // [RELOAD-DIAG] Seek entry — precedes the within-buffer vs beyond-buffer branch below. + _logger.LogInformation("[RELOAD-DIAG] Seek ENTRY position={Position:F2} (gen={Gen})", position, _loadGeneration); + try { var result = await _audioInterop.SeekAsync(PlayerId, position); @@ -981,6 +979,11 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// private async Task SeekBeyondBuffer(double seekPosition, long byteOffset) { + // [RELOAD-DIAG] Seek-beyond-buffer entry — re-streams from an offset and reinitializes the decoder. + _logger.LogInformation( + "[RELOAD-DIAG] SeekBeyondBuffer ENTRY seekPosition={SeekPosition:F2} byteOffset={ByteOffset} (gen={Gen})", + seekPosition, byteOffset, _loadGeneration); + if (string.IsNullOrEmpty(_currentTrackId)) { ErrorMessage = "Cannot seek - no track loaded"; @@ -1118,6 +1121,11 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// private async Task RecoverFromFailedRefill(double seekPosition, string userFacingError) { + // [RELOAD-DIAG] Refill-failure recovery entry — a mid-stream re-fetch failed and we are halting. + _logger.LogInformation( + "[RELOAD-DIAG] RecoverFromFailedRefill ENTRY seekPosition={SeekPosition:F2} (gen={Gen})", + seekPosition, _loadGeneration); + // Halt the starved scheduler JS-side (stop sources, drop stale buffers, anchor at the target). // Best-effort: if even this interop fails the player is no worse off, and we still surface the // error and settle C# state below. @@ -1144,15 +1152,16 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS /// /// Single method to reset all state - called by both Stop and Unload, and as the prologue of a new - /// load. is true for the direct stop/unload/dispose callers and - /// false when a fresh calls it: that load has already set - /// _loadInFlightTrackId to its own key to arm the single-load guard, so the prologue must not - /// wipe it. The direct callers DO clear it so a later replay of the same track is not wrongly - /// suppressed by a guard key left over from an interrupted in-flight load (whose CTS-identity check - /// in finally fails after ResetToIdle nulls the CTS, so the load itself never clears the field). + /// load. /// - private async Task ResetToIdle(bool clearLoadGuard = true) + /// [RELOAD-DIAG] Diagnostic label naming the call site (prologue / stop / unload + /// / dispose) so a trace shows WHICH reset nulled Duration. Removable with the rest of the + /// instrumentation; defaults so existing call shapes are unaffected. + private async Task ResetToIdle(string caller = "unspecified") { + // [RELOAD-DIAG] Which caller is resetting, and at which generation. + _logger.LogInformation("[RELOAD-DIAG] ResetToIdle caller={Caller} (gen={Gen})", caller, _loadGeneration); + // 0. Close any open play session BEFORE tearing down (§2.1). ResetToIdle is the single funnel // for stop / unload / dispose / track-switch (a new LoadTrackStreaming calls it first), so a // superseded listen is recorded here with its high-water bucket. Close is idempotent — if the @@ -1185,6 +1194,9 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS IsLoaded = false; IsLoading = false; CurrentTime = 0; + // [RELOAD-DIAG] Duration nulled here — the only site that nulls it. If "Duration set from header" + // appears after this line for the SAME generation, a reset ran mid-load. + _logger.LogInformation("[RELOAD-DIAG] ResetToIdle nulling Duration (gen={Gen})", _loadGeneration); Duration = null; LoadProgress = 0; ErrorMessage = null; @@ -1201,12 +1213,6 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS _currentTrackId = null; _currentFormat = AudioFormat.Lossless; - // Direct stop/unload/dispose: release the single-load guard so a later replay of the same track - // is not suppressed. NOT cleared on the load prologue (clearLoadGuard:false) — that load owns the - // key it just armed. - if (clearLoadGuard) - _loadInFlightTrackId = null; - await NotifyStateChanged(); } @@ -1286,7 +1292,7 @@ public class StreamingAudioPlayerService : AudioPlayerService, IStreamingPlayerS try { // ResetToIdle closes any open play session, so a dispose mid-play still records the listen. - await ResetToIdle(); + await ResetToIdle("dispose"); } catch {