From aea0670723d894e5ddff22f4d4f2ea48ec83677b Mon Sep 17 00:00:00 2001 From: gramps Date: Sat, 26 Sep 2026 12:45:40 -0700 Subject: [PATCH] fix(alerts): wire the frame-rate probe so alert-clip VIDEO paces to real time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 12:35 live session proved the decoder healthy (frames=240 audioChunks=156 failed=False both clips, alert audio in the mix at peakMix 0.277→0.733) yet the creator still saw 'no video plays / you lost the video'. Root cause: pacing, not decode. AlertClipDecoderFor built the decoder with no frameRateProbe, so RunAsync computed frameDuration = TimeSpan.Zero and RunVideoAsync's pace step was dead code — all 240 frames of the 10s clip dumped through the pipe in the first ~1-2s (130MB as fast as ffmpeg read), then the box froze on the LAST frame while audio chunk-paced its real-time ~7.8s. Reads exactly like a dead decoder on screen. The media path already wired this seam (MainViewModel.cs:308); the alert factory never supplied one. Derivative fix (media/decoder plumbing, cited in broad consensus of players): pass FfmpegFrameRateProbe into the per-play alert decoder exactly like MediaVideoSource does. Good Dog: AlertClipDecoderTests.AlertClipDecoder_PacesVideoFramesToTheProbedFrameRate — real AlertClipDecoder via the fake-process/fake-probe/delay-recorder seam; red on the old factory (zero pacing delays), green with the probe (one ~10ms delay per frame at 100fps). Full suite 321/322, one known-env flake (RealMouseDrag reorder). Docs in this commit: task-47 addendum, MyMistakes.md (a decoder that drops data faster than wall-clock looks identical to a dead one), HANDOFF rewrite. --- HANDOFF.md | 93 +++++++++++++++------------ MyMistakes.md | 15 +++++ TASKS/task-47-alert-videos.md | 28 ++++++++ ViewModels/MainViewModel.Chat.cs | 10 ++- ytLive.Tests/AlertClipDecoderTests.cs | 79 +++++++++++++++++++++++ 5 files changed, 182 insertions(+), 43 deletions(-) create mode 100644 ytLive.Tests/AlertClipDecoderTests.cs diff --git a/HANDOFF.md b/HANDOFF.md index d491b55..e877dec 100644 --- a/HANDOFF.md +++ b/HANDOFF.md @@ -1,20 +1,21 @@ -# HANDOFF — 2026-09-26 (TASK 47 shipping crash + the "nothing in the box" void both fixed; 3 local commits, NOT pushed) +# HANDOFF — 2026-09-26 (TASK 47: crash + silent-void + video-pacing all fixed; 4 local commits, NOT pushed) ## Branch / Commit State -`main` — three local commits ahead of `origin/main` (= `ecb329e`), **NOT pushed** (awaiting the +`main` — four local commits ahead of `origin/main` (= `ecb329e`), **NOT pushed** (awaiting the creator's go / milestone signal): 1. `a11b15e` — **TASK 47** alert box video (built-in/custom clip + read-time fade + message ticker + unity audio) + `AlertLayerVideoTests` (fake decoder, 0 warnings, 319/319 green). 2. `7b940b6` — **crash fix**: AlertOverlayLayer marshals the chat-poller seam to the UI thread - (regression test red pre-fix / green post-fix, both verified). Full suite 320/320. -3. *(uncommitted next — this session)* — **silent-decoder fallback + diagnostics** (see below), - scope: `Services/AlertOverlayLayer.cs`, `Services/AlertClipDecoder.cs`, - `ytLive.Tests/AlertLayerVideoTests.cs` + docs (task-47 addendum, `MyMistakes.md` lesson, this - file). New Good Dog test green; build 0 warnings; full suite 321 with the **known env flake** - (RealMouseDrag reorder failing while windows are up — passes with the desktop clean; unrelated - to this change). `scope-check.sh` pending, then commit. + (regression test red pre-fix / green post-fix). Full suite 320/320. +3. `80038ff` — **silent-decoder fallback + diagnostics** (no-frame grace 1.0s → six-animation; + BeginClip/RunAsync logging). Full suite 321 with the **known env flake** (RealMouseDrag + reorder failing while windows are up). +4. *(uncommitted next — this session)* — **video pacing fix** (below). Scope: + `ViewModels/MainViewModel.Chat.cs`, `ytLive.Tests/AlertClipDecoderTests.cs` (new), docs + (task-47 addendum, `MyMistakes.md`, this file). Test green; build 0 warnings; + `scope-check.sh` pending, then commit. ## ✅ Crash fixed (`7b940b6`) @@ -26,41 +27,53 @@ UI-thread marshal (`ChatOverlayLayer` has one); it ran `RefreshAlertPreviews` the MTA poller thread and stamped `alertBox.VideoImageSource` (INPC + WPF-bound) with a WriteableBitmap created there. Fix + Good Dog regression test `OnMessageReceived_FromPollerThread_MarshalsPreviewWritesToTheUiThread` (red/green verified). -`MyMistakes.md`: every INPC-raising seam fed by the poller must marshal WPF-object writes. -## ⚠️ The "nothing in the alert box" void — diagnosed + fixed (this unit) +## ✅ "Nothing in the alert box" void — fixed (`80038ff`) -After the crash fix the creator reported: On-Air → test → **remove and re-add** the Stream Alerts -layer → TEST event → procs in the chat windows but **nothing in the alert box**. startup.log 11:44: -`peakMix 0.105` (no alert audio) vs 11:21's 0.375–0.891. No exception anywhere — every stage of the -clip path was silent by design (`UpdatePreview` catch = `Debug.WriteLine`-only; `RunAsync` bare -`catch { }` firing `Completed` regardless). Established the guaranteed-invisible fail: a decoder -whose `Start()` succeeds but yields **no frames AND no audio** leaves `_clip != null` with -`_latestClipFrame == null` → `RenderClipFrame` returns null forever → box transparent FOREVER; the -six-animation fallback only ran on setup-time throws. (Hunted & ruled out meanwhile: `LiveScene` is -never assigned — the encoder always renders `StagedScene` (MainViewModel.cs:323), so the re-added -box IS in the render graph; the bake invalidates per element on add; DB row -`c85b46ac-…` X=602 Y=26 680×200 healthy; pinned ffmpeg decodes the default clip to `scale=680:200` -rawvideo correctly to a file. Frame pacing silently off too: no probe → `frameDuration=0`.) +After the crash fix: On-Air → test → **remove and re-add** the Stream Alerts layer → TEST event → +procs in chat but **nothing in the alert box**. startup.log 11:44 `peakMix 0.105` (no alert audio) +vs 11:21's 0.375–0.891. Every stage of the clip path was silent by design; a decoder whose `Start()` +succeeds but yields **no frames AND no audio** left `_clip != null` with `_latestClipFrame == null` +→ blank box forever. Fix: no-frame grace (1.0s) in `AlertOverlayLayer.Advance` → tear down + same +alert as six-animation; BeginClip/RunAsync diagnostics stop the silence. Good Dog: +`SilentDecoder_FallsBackToTheAnimationAfterTheNoFrameGrace`. -**Fix (uncommitted):** `AlertOverlayLayer.Advance` — a started clip that produced neither a frame -nor an audio chunk inside `NoFrameFallbackSeconds` (1.0 s) is torn down, `_elapsed` resets, and the -SAME alert continues as the six-animation render (never blank, never drained early). -Diagnostics: `BeginClip` logs box id / resolved path / size + setup failure; `AlertClipDecoder.RunAsync` -logs frame/chunk end-state + the swallowed exception. Good Dog test -`SilentDecoder_FallsBackToTheAnimationAfterTheNoFrameGrace`: transparent inside the grace → -decoder disposed past it → animation renders → drains to idle. `MyMistakes.md`: an alert that plays -is a promise — degrade on dead-air, and a `catch` hiding WHY output vanished is a lie. +## ✅ "No video plays" — decoder HEALTHY, video UNPACED — fixed (this unit) + +Creator repro after `80038ff` (12:35 session): still "no video plays in the web-alert box", "like +you lost the video" — but the new diagnostics PROVED the decoder healthy: `Alert clip start: box …` +→ `Alert clip end: … frames=240 audioChunks=156 failed=False` twice, alert audio in the live mix +(`peakMix 0.277 → 0.733`, mic/loop 0.000). Root cause was **pacing, never decode**: +`AlertClipDecoderFor` (MainViewModel.Chat.cs:113) built the decoder with **no frame-rate probe** → +`RunAsync` computed `frameDuration = TimeSpan.Zero` → `RunVideoAsync`'s pace step +(`if (frameDuration > 0)`) was dead code → all 240 frames of the 10s clip dumped through the pipe +in the first ~1-2s (130MB as fast as ffmpeg read), then the box sat frozen on the LAST frame while +the audio pipeline paced 156 chunks at real-time ~7.8s. Reading exactly like "no video / you lost +it". The media path already had the seam wired (`MediaVideoSource` gets +`frameRateProbe: new FfmpegFrameRateProbe(…)`, MainViewModel.cs:308) — the alert factory just +never passed one. + +**Fix (uncommitted):** `AlertClipDecoderFor` passes +`frameRateProbe: new FfmpegFrameRateProbe(new FfmpegLocator(), () => new FfmpegDecodeProcess())` so +video paces at the clip's native ~24fps (10s real-time) in lockstep with audio. Good Dog test +`AlertClipDecoderTests.AlertClipDecoder_PacesVideoFramesToTheProbedFrameRate` drives the REAL +`AlertClipDecoder` through the media-style fake process + fake probe + recorded delay seam +(3 frames at 100fps → one ~10ms delay per frame; red on the old factory, green now). Full suite +321/322 (one known-env flake). `MyMistakes.md`: **a decoder that drops data faster than wall-clock +looks identical to a dead decoder on screen — "plays but you don't see it" is a PACING bug before +it's a decode bug.** Rules: never ship a pipe whose `frameDuration` can be zero; check pacing +(bytes/s vs wall-clock) before re-auditing the codec. ## Follow-ups queued (NOT done in this unit) - **TASK 3 item 20 persistence half** — canonical `RewardEvents` SQLite table + `superChatEvents.list` (30-day) backfill + session-report rollup (still in-memory only). - TASK 3 item 16 (Text source); TASK 40 units A/C/D; TASK 32–36; TASK 12 master limiter — queued. -- If the alert box is STILL blank after this fix + relaunch: the new logs make the failure - conclusive (look for `Alert clip start:` → `Alert clip decode failed` → `Alert clip end:`). The - creator's Live scene also has a WebSource "Web Resource-0" bottom-right — confirm which element - they watch when describing the "stream-alerts layer". +- If the alert box is STILL "no video" after this fix + relaunch: check the 12:35-style + `Alert clip end: … frames=240` line (now logged) — a healthy decode with no visual means the + painter/render path, not the decoder; the creator's Live scene also has a WebSource + "Web Resource-0" bottom-right — confirm which element they watch when describing the + "web-alert / stream-alerts" box. - The known pump stall (`render=full-render … totalMs=147`, ~6fps worst) is recorded as a pre-existing perf item, NOT part of this unit. @@ -75,17 +88,15 @@ is a promise — degrade on dead-air, and a `catch` hiding WHY output vanished i from `liveChat/messages.insert` = wrong body shape (missing `snippet.type`). - TASK 47 sticky facts: bgra from ffmpeg is opaque (alpha=255); audio pipe = carry-buffer loop; default clip = `%TEMP%\ytLive-alert-{id}.mp4`; decoder per-play; DB stays `user_version 10`. -- ChatOverlayLayer.OnMessageReceived marshals the poller seam; AlertOverlayLayer mirrors it; the - no-frame fallback lives in Advance (has the 1 s grace + diagnostics). - Every committed change needs a **close + relaunch** of the running app to be seen. ## Next step 1. Commit this unit with the declared scope - `./scripts/scope-check.sh "Services/AlertOverlayLayer.cs" "Services/AlertClipDecoder.cs" "ytLive.Tests/AlertLayerVideoTests.cs"`. -2. Push the three local commits at the creator's go / milestone signal. -3. Creator to relaunch and re-run the repro (compare the 11:21 vs 11:44 behavior) — the new logs - will say exactly what the decoder did. + `./scripts/scope-check.sh "ViewModels/MainViewModel.Chat.cs" "ytLive.Tests/AlertClipDecoderTests.cs"`. +2. Push the four local commits at the creator's go / milestone signal. +3. Creator to relaunch and re-run the repro — with the probe wired the clip plays real-time + (~10s of motion, not a blur + frozen frame); the `Alert clip end:` line confirms decode health. ## Critical working rules (unchanged, still binding) diff --git a/MyMistakes.md b/MyMistakes.md index 56fd13f..4af7278 100644 --- a/MyMistakes.md +++ b/MyMistakes.md @@ -908,3 +908,18 @@ frame/chunk end-state AND the exception it swallowed. Rules for every future gam (2) any producer that yields zero output inside a grace becomes a fallback trigger, not a wait; (3) one integration test per rescue: `SilentDecoder_FallsBackToTheAnimationAfterTheNoFrameGrace` pins transparent→fell-back→renders→drains. + +The pacing half that this entry flagged came true the same day: the 12:35 session showed a FULLY +HEALTHY decoder (`frames=240 audioChunks=156 failed=False`, alert audio in the mix) and the creator +still saw "no video / you lost the video". The clip played at ~240× for a second then froze on the +last frame: `AlertClipDecoderFor` passed no `frameRateProbe`, so `RunVideoAsync`'s pace +(`if (frameDuration > 0)`) was dead code while the audio chunk-pacer ran real-time. LESSON, sharper +than the whole fallback saga: **a decoder that drops data faster than wall-clock looks identical to a +dead decoder on screen — "plays but you don't see it" is a PACING bug before it's a decode bug.** +A healthy pipeline still needs an explicit pace per stream; never ship a pipe whose `frameDuration` +can be `TimeSpan.Zero`. Fix: the alert factory passes `FfmpegFrameRateProbe` exactly like the media +path does (MainViewModel.cs:308). Verify-by-seam once, everywhere: the same fake-process + +fake-probe delay-recorder test now pins real-time video pacing +(`AlertClipDecoderTests.AlertClipDecoder_PacesVideoFramesToTheProbedFrameRate`). Rule added to the +list above: (4) if output arrives but the USER still reports no/motionless picture, check pacing +before decode — count the bytes/s against wall-clock, don't re-audit the codec. diff --git a/TASKS/task-47-alert-videos.md b/TASKS/task-47-alert-videos.md index 2672c56..1c34772 100644 --- a/TASKS/task-47-alert-videos.md +++ b/TASKS/task-47-alert-videos.md @@ -177,6 +177,34 @@ idle. This lands the corpus at 321, with the one known-env flake (RealMouseDrag passes with no fullscreen windows up) — unrelated to this change. Unit was the direct lineage of bug surface: **a decoder booth production failure surfaces as dead air.** +## Video-frame pacing fix (2026-09-26) + +Second creator repro after the fallback commit (12:35 session): decoder HEALTHY — +`Alert clip start: box …` → `Alert clip end: … frames=240 audioChunks=156 failed=False` +twice, alert audio in the live mix (`peakMix 0.277 → 0.733`, mic/loop 0.000) — yet +"no video plays in the web-alert box", "like you lost the video". The hole was never +decode: **the video pipe was unpaced.** `AlertClipDecoderFor` (MainViewModel.Chat.cs:113) +built the decoder with no `frameRateProbe`, so `RunAsync` computed +`frameDuration = TimeSpan.Zero` and `RunVideoAsync`'s pace (`if (frameDuration > 0)`) +was skipped — all 240 frames (a 10s, 680×200 clip, ~130MB) dumped through the pipe in +the first ~1-2s as fast as ffmpeg read them, then the box sat on the LAST frame frozen +for the remaining ~6-8s while the audio chunk-pacer (50ms/chunk × 156) ran out its +real-time cadence. To the eye: a blur then a dead frame = "no video / you lost the +video". The media path already wired exactly this seam (`MediaVideoSource` gets +`frameRateProbe: new FfmpegFrameRateProbe(…)`, MainViewModel.cs:308) — the alert +factory just never supplied one. + +Fix (commit `…`): `AlertClipDecoderFor` now passes +`frameRateProbe: new FfmpegFrameRateProbe(new FfmpegLocator(), () => new FfmpegDecodeProcess())` +so the 240 frames pace at the clip's native ~24fps (10s real-time), matching the audio +cadence. Good Dog test `AlertClipDecoderTests.AlertClipDecoder_PacesVideoFramesToTheProbedFrameRate` +drives the REAL `AlertClipDecoder` through the same fake-process/fake-probe seam the +media test uses (3 frames, probe 100fps → one ~10ms pacing delay per frame) — red on +the old factory (no delay), green with a probe. Full suite 321/322, one known-env flake +(RealMouseDrag reorder). **Derivative lesson → `MyMistakes.md`: a decoder that reads +faster than wall-clock needs an explicit pace; "plays but you don't see it" is pacing, +not decode.** + ## Open follow-ups (NOT this unit) - TASK 3 item 20 (RewardEvent SQLite persistence half) and item 16 (Text source) remain diff --git a/ViewModels/MainViewModel.Chat.cs b/ViewModels/MainViewModel.Chat.cs index aec2b58..496671d 100644 --- a/ViewModels/MainViewModel.Chat.cs +++ b/ViewModels/MainViewModel.Chat.cs @@ -109,9 +109,15 @@ public partial class MainViewModel : ViewModelBase /// One decoder per play (the refcounted MediaVideoSourceManager sessions /// can't restart per replay). The clip is full-box in video + 48k stereo audio; - /// both steams pace themselves to real time inside the decoder. + /// both steams pace themselves to real time inside the decoder — the frame-rate + /// probe is what makes the VIDEO pace (without it every frame dumps in ~1-2s and + /// the box freezes on the last frame for the rest of the audio). private IAlertClipDecoder AlertClipDecoderFor(string path, int width, int height) => - new AlertClipDecoder(path, width, height, new FfmpegLocator(), () => new FfmpegDecodeProcess()); + new AlertClipDecoder( + path, width, height, + new FfmpegLocator(), + () => new FfmpegDecodeProcess(), + frameRateProbe: new FfmpegFrameRateProbe(new FfmpegLocator(), () => new FfmpegDecodeProcess())); /// Stamp the shipped llama placeholder into the Asset table at startup /// (idempotent — hash-keyed UpsertAsset dedupes). Best-effort: if it fails the diff --git a/ytLive.Tests/AlertClipDecoderTests.cs b/ytLive.Tests/AlertClipDecoderTests.cs new file mode 100644 index 0000000..f5168e5 --- /dev/null +++ b/ytLive.Tests/AlertClipDecoderTests.cs @@ -0,0 +1,79 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.IO; +using System.Threading; +using System.Threading.Tasks; +using Xunit; +using ytLive.Services; +using ytLive.Services.Encoder; + +namespace ytLive.Tests; + +/// +/// TASK 47 Good Dog: the alert clip decoder paces VIDEO to real time via the +/// frame-rate probe. The 2026-09-26 live failure was a healthy decoder whose +/// frames all dumped in the first ~1-2s (no probe = no pacing), leaving the box +/// frozen on the last frame while the audio ran its ~8s — read as "no video +/// plays". This drives the REAL against a fake +/// process + probe and records the pacing delay it requests per frame (the same +/// seam the media path's decoder test uses — the repo never runs a real codec). +/// +public class AlertClipDecoderTests +{ + [Fact] + public async Task AlertClipDecoder_PacesVideoFramesToTheProbedFrameRate() + { + const int w = 1, h = 1; // frame bytes = 4 + var payload = new byte[12]; // three frames + var delays = new List(); + + using var decoder = new AlertClipDecoder( + "clip.mp4", w, h, + new FakeLocator(), + () => new FakeDecodeProcess(payload), + frameRateProbe: new FakeFrameRateProbe(100.0), + delay: (t, _) => { delays.Add(t); return Task.CompletedTask; }); + + var forwarded = 0; + var completed = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + decoder.FrameAvailable += _ => forwarded++; + decoder.Completed += () => completed.TrySetResult(true); + + decoder.Start(); + await completed.Task.WaitAsync(TimeSpan.FromSeconds(5)); + + Assert.Equal(3, forwarded); + // One pacing delay per emitted frame, each = 1/100s (the probed rate). + Assert.Equal(forwarded, delays.Count); + foreach (var d in delays) + Assert.True(Math.Abs((d - TimeSpan.FromMilliseconds(10)).TotalMilliseconds) < 0.001, + $"expected ~10ms, got {d.TotalMilliseconds}ms"); + } + + private sealed class FakeDecodeProcess : IDecodeProcess + { + private readonly MemoryStream _stream; + public FakeDecodeProcess(byte[] bytes) => _stream = new MemoryStream(bytes); + public void Start(ProcessStartInfo startInfo) { } + public Stream StandardOutput => _stream; + public bool HasExited => _stream.Position >= _stream.Length; + public int ExitCode => 0; + public void Kill() { } + public Task WaitForExitAsync(CancellationToken ct = default) => Task.CompletedTask; + public void Dispose() => _stream.Dispose(); + } + + private sealed class FakeFrameRateProbe : IFrameRateProbe + { + private readonly double _fps; + public FakeFrameRateProbe(double fps) => _fps = fps; + public Task ProbeAsync(string path, CancellationToken ct = default) + => Task.FromResult(_fps); + } + + private sealed class FakeLocator : IFfmpegLocator + { + public Task LocateAsync(CancellationToken ct = default) => Task.FromResult("ffmpeg.exe"); + } +} \ No newline at end of file