test(vision mixer): watch every PGM frame of a wipe, name a failed GL start

[srperens]

Refs #977

Problem

Since #977 put the GPU vision mixer tests on Linux CI (Mesa llvmpipe, surfaceless EGL, STROM_REQUIRE_GL=1), two of them fail now and then on the Linux runner. They pass on macOS.

• vision_mixer_fx_test::wipe_between_letterboxed_sources_animates failed 8 times on 2026-10-05, for example runs 37306914593, 37304562884, 37301781398 and 37324119848. It fails the same way every time, always in the first (classic) wipe: classic wipe: animated=false end white=0.00 red=0.76.
• vision_mixer_source_resize_test::source_resized_during_a_fade_is_fitted_after_it failed once (run 37304745163) with start GPU vision mixer pipeline: StateChange("State change failed: StateChangeError - current: Paused, pending: Playing").

Change

Wipe test: the observer now sees every PGM frame. The test pulled PGM from an appsink with max-buffers=1 drop=true, so it only ever saw the newest frame. If the observer falls behind for the length of the mid-wipe stretch (about 1.4 s of the 2 s wipe has both sources on screen), it jumps from the last white frame to the first red one. It then reports a hard switch, the exact signature above. The appsink now holds 4 frames and then pushes back (drop=false).

Holding the mixer back does not change what it renders. The pad keyframes, the shader's latched u_start and the PGM frames are all in stream time, and the live sources keep counting timestamps, so a mixer running behind the wall clock renders the same frames. Two things follow from that:

• The 1.5 s wall-clock settle sleep would no longer settle anything while the appsink holds the mixer back. It is replaced by a stream-state wait: a white picture, plus vision_mixer_input_resolutions reporting both sources' sizes. That is what the sleep was for: the take aspect-fits the pads from those sizes.
• The observation now ends when the picture settles. Its wall deadline went from 10 s to 30 s, with a cap of 300 frames (10 s of stream time, well past the 2 s wipe) for the hard-switch case.

When the test fails, the message now lists every frame it saw (PTS, white and red fractions). If CI fails again, the trace shows whether the PTS really jump from the before-wipe frame to the after-wipe frame (a product problem), or whether there are frames in between.

Resize test: a failed start now names the error. PipelineManager::start reported a state-change failure, not a timeout. get_state returns Err only for GST_STATE_CHANGE_FAILURE, which means an element posted an error during PAUSED to PLAYING. The bus watch logs that error with error! and broadcasts it as StromEvent::PipelineError. The tests run without a log subscriber, though, so the error was lost. Running::start now subscribes to the flow's events and puts the posted errors in the panic message. No test-side wait could fix this one: the start really failed. I did not retry the start, or serialise the 8 concurrent GL pipelines, because either would hide what may be a real "GPU mixer fails to start under load" bug.

Rejected:

• A longer wipe. It only lowers the odds, and the observer can still skip it.
• A larger mixer latency. It changes the setup under test, and nothing showed lateness. Injecting 0.3 to 2.5 s of branch lag locally made the wipe choppy, but it still animated.
• #[ignore] or skipping on llvmpipe.

Evidence

• The wipe guard still catches a hard switch. I temporarily forced shader_wipe_take to a 1 ms duration, and the test failed with classic wipe should animate (no frame showed both sources), frames: ["0:00:00.066666666: w=0.74 r=0.00", "0:00:00.100000000: w=0.00 r=0.76", "0:00:00.133333333: w=0.00 r=0.76", .... That is a clean cut between two consecutive frames, the same end state as on CI.
• The inverted-wipe guard still catches a hard switch too. With only the inverted mask forced to 1 ms, the test failed with inverted wipe should animate (no frame showed both sources), frames: ["0:00:01.633333333: w=0.00 r=0.76", "0:00:01.666666666: w=0.74 r=0.00", ....
• The start-failure message names the error. I added a temporary test that put a filesrc with a missing file into the flow, and it panicked with start GPU vision mixer pipeline: StateChange("Failed to start: Element failed to change its state"); errors posted: ["badsrc: Resource not found.", ...]. I removed that test afterwards.
• Unverified on llvmpipe. I could not run llvmpipe locally: Mesa is not installed on this macOS host. Whether the wipe flake was the observer skipping frames is a deduction from the failure signature and the drop-newest appsink. It has not been reproduced. CI on this PR is the first llvmpipe run. If the wipe still fails there, the new frame trace shows which cause it is.
• The resize start failure is not fixed, only made diagnosable. Its root cause is unknown until it fails again with the error named.

Tests

Ran, macOS (native GL, Apple Silicon):

• STROM_REQUIRE_GL=1 STROM_REQUIRE_GST_PLUGINS=1 cargo test --test vision_mixer_fx_test: 3 runs, 2/2 passed each time.
• STROM_REQUIRE_GL=1 STROM_REQUIRE_GST_PLUGINS=1 cargo test --test vision_mixer_source_resize_test: 3 runs, 8/8 passed each time.
• The fx test binary, 6 copies at once (load): all passed. The Mac's GL is too fast for this to stand in for llvmpipe.
• cargo fmt, cargo clippy --all-targets: clean.

Skipped: none (GL was required).
Not run: llvmpipe / Linux, see Evidence.

For the reviewer

• Changes are test-only. No product code changed.
• The wipe test now holds the GPU mixer back from its PGM appsink. If you would rather keep the mixer free-running, the alternative is an unbounded appsink (no backpressure), which costs about 3.7 MB of memory per queued frame.

Out of scope

• The per-frame GStreamer-CRITICAL: gst_mini_object_unref: assertion 'mini_object != NULL' failed that the GL tests print on the Linux runner, in passing runs too. It is worth its own look.
• The other resize tests still read PGM through max-buffers=1 drop=true. The fade test compares consecutive frames (largest_step < 40), so it has the same exposure to skipped frames, but it has not failed so far.
• The full-red flash at the start of a classic wipe when branch buffers lag the mixer (WIPE_ALPHA_LEAD_MS covers about 2 frames in flight). I saw it while injecting lag locally. It is a product nit, not this flake.

🤖 Generated with Claude Code

[srperens]

Verdict: Approve. I am posting this as a COMMENT review because GitHub refuses APPROVE on a PR from the account this stage runs under. The change is test-only and every mechanism claim holds in code. The two changed binaries executed on llvmpipe and passed. Merge order against #935/#936 is mechanical, see Overlaps.

Claims

Claim	Verdict	Evidence
The observer now sees every PGM frame	CONFIRMED	backend/tests/vision_mixer_fx_test.rs:324 — ("drop", PV::Bool(false)), (main had drop=true, max-buffers=1)
Holding the mixer back keeps the wipe consistent in stream time	CONFIRMED	The take's now is the mixer's own output position, not the wall clock: backend/src/gst/transitions/controller.rs:73 — mixer_position.ok_or(TransitionError::PositionQueryFailed). The shader's u_start latches from branch PTS (program_wipe_at_first_buffer)
The settle sleep can be replaced by a wait on input sizes	CONFIRMED	The take reads aspects synchronously, with no idle callback (this test runs no glib main loop): backend/src/gst/pipeline/effects/take.rs:145 — self.vision_mixer_source_aspects(block_instance_id, state.num_inputs);
A failed start now names the posted error	CONFIRMED	The subscription exists before start(): backend/tests/vision_mixer_source_resize_test.rs:248 — let mut posted = events.subscribe();. The main loop that dispatches the bus signal watch is already running (below)
The CI wipe flake was the observer skipping frames	EXTERNAL	This cannot be settled from the repo, and the body says so. The assumption is that a recurrence will now carry a per-frame PTS trace, which separates "observer skipped" from "product hard-switched"

The main loop starts first: backend/tests/vision_mixer_source_resize_test.rs:243 — std::thread::spawn(move || ml.run())

Diagnosis. The old max-buffers=1 drop=true observer could only report a hard switch if it fell behind for the whole mid-wipe stretch. That fits the fixed end white=0.00 red=0.76 signature. Fix coverage is BOUNDED: it covers the wipe flake only. The resize start failure is made diagnosable, not fixed, and the body states that honestly. The hard-switch guard survives because saw_both never sets, and the observer stops at 300 frames or the 30 s deadline (backend/tests/vision_mixer_fx_test.rs:481 — if trace.len() > 300 {). The author's 1 ms forced-wipe check shows the assert still fires.

Radius. LOCAL: two test files, no product code. Worst-case runtime on failure rises to about 90 s (three 30 s deadlines). Nothing on the passing path.

Overlaps

• #935 (and #936, which carries the same hunks) replaces the hand-built PipelineManager::new in both files with common::manager::build. This is a textual conflict only. #935 also adds build_with(flow, events, media_path), so whichever PR lands second keeps events.subscribe() by building through build_with. No design decision is involved.
• #1007 changes shader_fx.rs, which this wipe test guards. Landing #994 first means #1007's CI runs against the stricter observer. Preferable, not required.

Tests & CI. At fff843b, all runs are green: Check (Linux), Build (Linux x86_64/ARM64), Check & Build (WASM), API Contract Check, Static JS Tests. macOS and Windows were skipping, which is acceptable for test-only Rust that the author ran on macOS. In the Check (Linux) log, vision_mixer_fx_test passed 2 tests in 3.74 s and vision_mixer_source_resize_test passed 8 in 8.80 s. Real GL runs, not millisecond skips (STROM_REQUIRE_GL=1 is set in ci.yml). One green run cannot show the flake is gone. The per-frame gst_mini_object_unref CRITICAL also appears in this job and is pre-existing, as the body notes.

Confidence: MED

[srperens]

Closing.

• Wipe test. The premise did not hold. Traces on the runner showed the observer saw every PGM frame. The mixer itself was dropping the take slot's frames as late, because the runner's GL renders below real time. test(vision mixer): run the letterbox wipe test where the runner keeps real time #1027 fixed that, and the wipe test has been green on the runners since. Holding the mixer back through the appsink (drop=false) would make it worse: a mixer behind the clock is exactly when its branches' frames count as late.
• Resize start. The failure in source_resized_during_a_fade_is_fitted_after_it (posted errors in the panic message) was seen once, on 2026-10-05, and not since. We'll carve that diagnostic out on its own if it comes back.

🤖 Generated with Claude Code