From f85496e3568ec4214a484179f9a619f90bb88c8f Mon Sep 17 00:00:00 2001 From: Luke Curley Date: Fri, 9 Oct 2026 20:08:44 -0700 Subject: [PATCH 1/2] quest: claim media-audio-tone Co-Authored-By: Claude Opus 5.5 From 53f5868ed25b742463a68dd14c335056ebf23d70 Mon Sep 17 00:00:00 2001 From: Luke Curley Date: Fri, 9 Oct 2026 20:58:31 -0700 Subject: [PATCH 2/2] test(media): open each window once playback starts, and prove late join can fail The audio-tone misses under load were the player's startup, not gaps in playback. A player paints its first decoded frame and holds it, silent, until its audio ring fills to the sync delay, which rises past 400ms under load. Windows opened on that held frame, so the buffering counted against the 90% tone floor: 9 misses at a 460ms delay is 72/81. Each window now opens once the ring has filled and plays, and the rejoin and reattach windows first wait for live playback, since after a demand gap the first frame can come from the stale GOP. "late join reaches live" accepted the held preview frame, so a player delayed 3s behind live passed it. Live now needs a moving frame, and a new negative control delays the latecomer 3s and must fail there. Co-Authored-By: Claude Opus 5.5 --- quest/m1/README.md | 1 - quest/m1/media-audio-tone.md | 24 ------ quest/m1/publish-audio-channel-count.md | 5 +- quest/m1/test-flakes-2/README.md | 1 - test/interop/README.md | 16 ++-- test/interop/clients/js/media.ts | 101 +++++++++++++++++------- test/interop/clients/js/src/setup.ts | 4 + test/interop/interop.sh | 1 + 8 files changed, 92 insertions(+), 61 deletions(-) delete mode 100644 quest/m1/media-audio-tone.md diff --git a/quest/m1/README.md b/quest/m1/README.md index cd8e8a09d7..c4477f7040 100644 --- a/quest/m1/README.md +++ b/quest/m1/README.md @@ -63,7 +63,6 @@ ladders. - [Late lower groups](/quest/m1/lite-late-lower-group.md) - a moq-lite subscriber with a floor receives a group created below the first served one, as moq-transport does - [A watch and publish release ships assets()](/quest/m1/assets-release.md) - the release that lets the sites host the worklets - [Dogfood hosted worklets](/quest/m1/dogfood-assets.md) - the moq.pro dashboard hosts the worklets and calls `assets()` after the release -- [Media audio-tone check](/quest/m1/media-audio-tone.md) - the media lane's audio-tone check passes under load, fixed at its cause - [More tests under load](/quest/m1/test-flakes-2/README.md) - the second round of load-only failures, one quest per flake, fixed at the cause - [Test TypeScript check](/quest/m1/test-ts-check.md) - `just check` type-checks the TypeScript harnesses under test/ - [IETF request headers](/quest/m1/ietf-dispatch-headers.md) - each bidi request reads its header in its own task, so a slow one never blocks the next diff --git a/quest/m1/media-audio-tone.md b/quest/m1/media-audio-tone.md deleted file mode 100644 index 553eb78554..0000000000 --- a/quest/m1/media-audio-tone.md +++ /dev/null @@ -1,24 +0,0 @@ -# [S] Media audio-tone check holds under load - -## Goal - -The `just test media` audio-tone check passes under load, fixed at its cause. -It failed with 66 of 75 samples audible in #4719's runs and 72 of 81 in -the 2026-10-06 late-join loops (#4914), 68 of 81 once in 45 late-join runs -on 2026-10-09 under `stress-ng --cpu 20`, and passed on rerun. - -## Plan - -First decide whether the missing samples are real playback (a stall, -underrun, or late start the check correctly catches) or how the check samples -the tone. Reproduce it looped under synthetic CPU load (approved by the -maintainer for these runs) before changing anything, and don't widen the -window or lower the agreement threshold to hide the symptom. Keep this -standalone because its root cause is independent of the late-join regression; -apply the load-flake questline's cause-first rules and include it in the final -loaded check. - -## Related - -- [More tests under load](/quest/m1/test-flakes-2/README.md) - shares the loaded-check validation -- [Forced channel count](/quest/m1/publish-audio-channel-count.md) - another source of audio gaps on the JS publish path; rule it in or out first diff --git a/quest/m1/publish-audio-channel-count.md b/quest/m1/publish-audio-channel-count.md index eb97455981..a229288ed0 100644 --- a/quest/m1/publish-audio-channel-count.md +++ b/quest/m1/publish-audio-channel-count.md @@ -55,7 +55,10 @@ pin a channel count again once this is fixed, and not. A unit test that counts worklet callbacks under an explicit downmix would be cheaper than a full media run, if one can be made to fail reliably. +The `just test media` audio-tone misses under load were not this: the fixture +takes the `"max"` path, and every miss was the player's own buffering silence +with audio still arriving. + ## Related - [Browser benchmarks](/quest/m1/browser-benchmarks.md) - the other place browser-side capture and encode costs get measured -- [Media audio-tone check](/quest/m1/media-audio-tone.md) - a test that misses tone samples, possibly from the same cause diff --git a/quest/m1/test-flakes-2/README.md b/quest/m1/test-flakes-2/README.md index 93f0d160bc..b787d399a0 100644 --- a/quest/m1/test-flakes-2/README.md +++ b/quest/m1/test-flakes-2/README.md @@ -35,4 +35,3 @@ Public API: none. Wire: none. - [Relay restart rebind](/quest/m1/test-flakes-2/relay-restart-rebind.md) - the crash drill restarts on its original UDP address under concurrent load - [Impaired handshake](/quest/m1/test-flakes-2/impaired-handshake.md) - the impaired cluster drills' clients never time out while connecting - [Cluster burst overrun](/quest/m1/test-flakes-2/cluster-burst-overrun.md) - the impaired cluster burst drill always overruns its bottleneck, so it always exercises it -- [Media audio tone](/quest/m1/media-audio-tone.md) - the `just test media` audio-tone check passes under load, fixed at its cause diff --git a/test/interop/README.md b/test/interop/README.md index 8fc5d53e08..eaab54b809 100644 --- a/test/interop/README.md +++ b/test/interop/README.md @@ -188,9 +188,10 @@ Each run covers, against a real local relay: - **pause and resume**, **unsubscribe and rejoin**, **detach and reattach**, **publisher stop and same-path republish**, and **late join**. The late joiner may first show the GOP from before the demand gap, but it must present - a frame within 5s of loading and then come within 1.5s of the fixture's - painted frame within 2s, both bounds about twice the worst seen in looped runs - under CPU load. + a frame within 5s of loading and then play, with the presented frame moving, + within 1.5s of the fixture's painted frame within 2s, both bounds about twice + the worst seen in looped runs under CPU load. A rejoin and a reattach cross + the same demand gap, so they must reach live the same way. - **resources return to baseline** - the page wraps `WebTransport`, `WebSocket`, `AudioContext`, and `Worker` to count live instances, so a detach that leaks a session is visible rather than merely invisible. @@ -201,8 +202,12 @@ median, and audio/video skew must stay within one 200ms tone step for 90% of samples. One step is the floor set by the analyser window straddling a step boundary and the canvas holding a frame up to one frame old. -The run ends with negative controls. Each injects a defect in the fixture and -names the assertion that has to catch it, and passes only by failing there: +Each window opens once the player's audio buffer has filled and plays. Until +then the player holds its first decoded frame, silent, for its sync delay, which +rises past 400ms under load; that is startup, not a gap in playback. + +The run ends with negative controls. Each injects a defect and names the +assertion that has to catch it, and passes only by failing there: | Control | Must fail | |---|---| @@ -210,6 +215,7 @@ names the assertion that has to catch it, and passes only by failing there: | picture frozen after the first frame | `video progress` | | tone table shifted 800ms ahead of the picture | `audio/video sync` | | the detached player's session never torn down | `resource baseline` | +| the latecomer's player delayed 3s behind live | `late join reaches live` | The leaked-session control waits for an extra `AudioContext` rather than an extra session: every player on one relay URL shares a transport, so a session count diff --git a/test/interop/clients/js/media.ts b/test/interop/clients/js/media.ts index 3570b6ea1b..de75fe6000 100644 --- a/test/interop/clients/js/media.ts +++ b/test/interop/clients/js/media.ts @@ -13,6 +13,7 @@ * * bun media.ts --url http://127.0.0.1:4443 [--timeout 30] [--cases pause,detach] * bun media.ts --url ... --fault silent-audio --cases none --expect-fail "audio tone" + * bun media.ts --url ... --lag --cases late-join --expect-fail "late join reaches live" * * @module */ @@ -64,6 +65,7 @@ const { values } = parseArgs({ fault: { type: "string", default: "none" }, cases: { type: "string" }, leak: { type: "boolean", default: false }, + lag: { type: "boolean", default: false }, "expect-fail": { type: "string" }, }, }); @@ -78,7 +80,7 @@ const selected = new Set( const unknown = [...selected].filter((name) => !CASES.some((c) => c === name)); if (!url || !Number.isFinite(timeoutMs) || timeoutMs <= 0 || !FAULTS.some((f) => f === fault) || unknown.length > 0) { console.error( - `usage: media.ts --url U [--timeout S>0] [--fault ${FAULTS.join("|")}] [--cases none|${CASES.join(",")}] [--leak] [--expect-fail TEXT]`, + `usage: media.ts --url U [--timeout S>0] [--fault ${FAULTS.join("|")}] [--cases none|${CASES.join(",")}] [--leak] [--lag] [--expect-fail TEXT]`, ); process.exit(2); } @@ -180,24 +182,35 @@ const LATE_START_MS = 5000; /** How long a latecomer may take to reach live after its first frame. Loaded runs take up to 0.3s. */ const LATE_CATCHUP_MS = 2000; +/** A player delay far enough behind {@link LIVE_LAG_FRAMES} that `--lag` must fail "late join reaches live". */ +const LAGGED_DELAY = "3s"; + const framesToMs = (frames: number) => Math.round((frames * 1000) / Pattern.FPS); /** - * Wait until the player presents a frame within {@link LIVE_LAG_FRAMES} of the one the fixture last + * Wait until the player is playing within {@link LIVE_LAG_FRAMES} of the frame the fixture last * painted, and report how far behind its first reading was. * * Both pages are read at once, in separate browsers, so the lag is what a viewer would see against - * the source. + * the source. After a demand gap the relay may hand over the GOP from before the gap, so the first + * frame can be stale; `assertion` names the check that playback then fast-forwards to live. + * + * Only a frame that moved since the last reading counts. The player paints the first frame it decodes + * as a preview and holds it until its sync delay comes up, so a held frame says nothing about where + * playback runs: a player delayed seconds behind live still shows a near-live preview first. */ async function waitForLive( publisher: Page, publisherErrors: BrowserErrors, player: Page, playerErrors: BrowserErrors, + assertion: string, ): Promise<{ first: number; lag: number; after: number }> { const since = Date.now(); let first: number | undefined; let lag: number | undefined; + let frame: number | undefined; + let moved = false; while (Date.now() < since + LATE_CATCHUP_MS) { throwPageErrors(publisherErrors); throwPageErrors(playerErrors); @@ -207,19 +220,39 @@ async function waitForLive( if (fixture && state?.frameId !== undefined) { lag = fixture.frameId - state.frameId; first ??= lag; - if (lag <= LIVE_LAG_FRAMES) return { first, lag, after: Date.now() - since }; + moved = frame !== undefined && state.frameId !== frame; + frame = state.frameId; + if (moved && lag <= LIVE_LAG_FRAMES) return { first, lag, after: Date.now() - since }; } await sleep(POLL_INTERVAL_MS); } throwPageErrors(publisherErrors); throwPageErrors(playerErrors); throw new Failure( - "late join reaches live", - `still ${lag === undefined ? "?" : framesToMs(lag)}ms behind the fixture ${LATE_CATCHUP_MS}ms after the first frame, ` + - `against a ${framesToMs(LIVE_LAG_FRAMES)}ms bound`, + assertion, + `${moved ? "still" : "held a frame"} ${lag === undefined ? "?" : framesToMs(lag)}ms behind the fixture ` + + `${LATE_CATCHUP_MS}ms after the first frame, against a ${framesToMs(LIVE_LAG_FRAMES)}ms bound for playback`, ); } +/** + * Measure one window of playback, opened once the player has filled its audio buffer and plays. + * + * A player shows its first frame as soon as it decodes, then holds that frame silent while it buffers + * up to its sync delay, which rises past 400ms under load. A window opened on that held frame counts + * the buffering as missing tone. Only the ring filling opens the window, never a tone, so silence + * still fails {@link assertMedia} rather than this wait. + */ +async function measurePlayback(player: Page, playerErrors: BrowserErrors, label: string): Promise { + await waitForState(player, playerErrors, { + deadline: Date.now() + SETTLE_MS, + assertion: "playback starts", + description: `${label}: the audio buffer to fill to the player's delay and play`, + predicate: (state) => state.audioContext === "running" && !state.audioStalled, + }); + assertMedia(await collect(player, playerErrors, WINDOW_MS), label); +} + // One sample as a line: elapsed time, the frame on the canvas, the tone step heard against the one // that frame belongs to, how far the tone stood above the noise floor, and whether audio was // arriving at all, which separates a silent player from a publisher that stopped sending. @@ -229,7 +262,8 @@ function traceLine(sample: PlayerState, start: number): string { return ( ` +${((sample.at - start) / 1000).toFixed(2)}s frame=${sample.frameId ?? "-"} ` + `step=${sample.toneStep ?? "-"}/${step} tone=${margin.toFixed(0)}dB ${sample.toneHz?.toFixed(0) ?? "-"}Hz ` + - `paused=${sample.paused} delay=${sample.delay}ms audio=${sample.audioBytes}B${sample.audioStalled ? " stalled" : ""}` + `rms=${sample.rms?.toFixed(3) ?? "-"} ats=${sample.audioTimestamp?.toFixed(0) ?? "-"} vts=${sample.videoTimestamp?.toFixed(0) ?? "-"} ` + + `paused=${sample.paused} delay=${sample.delay}ms audio=${sample.audioBytes}B${sample.audioStalled ? " stalled" : ""}` ); } @@ -393,21 +427,26 @@ async function browserFor(args: string[] = []): Promise { return browser; } +/** How a subscriber page is set up. */ +type SubscriberProps = { + muted?: boolean; + /** Start a Playwright trace. Defaults to true. */ + trace?: boolean; + /** The player's `delay` attribute, when not its adaptive default. */ + delay?: string; +}; + /** Open a subscriber page and wait for the player to start sampling. Never reloads. */ async function subscriber( broadcast: string, label: string, - muted = false, - trace = true, + { muted = false, trace = true, delay }: SubscriberProps = {}, ): Promise<[Page, BrowserErrors]> { - const [page, errors] = await open( - await browserFor(), - // visible="always" because the window is never frontmost in a headless run, and the default - // policy would stop downloading video and leave the canvas black. - pageUrl(server.origin, "subscribe", { url: relay, broadcast, visible: "always", muted: String(muted) }), - label, - trace, - ); + // visible="always" because the window is never frontmost in a headless run, and the default + // policy would stop downloading video and leave the canvas black. + const params: Record = { url: relay, broadcast, visible: "always", muted: String(muted) }; + if (delay !== undefined) params.delay = delay; + const [page, errors] = await open(await browserFor(), pageUrl(server.origin, "subscribe", params), label, trace); await waitForWatch(page); return [page, errors]; } @@ -428,7 +467,7 @@ async function readCapture(page: Page): Promise { /** A denied browser permission is visible, silent to discovery, and revives on a later grant. */ async function captureDenial(broadcast: string): Promise { console.error("=== capture denial and grant ==="); - const [viewer, viewerErrors] = await subscriber(broadcast, "capture viewer", true); + const [viewer, viewerErrors] = await subscriber(broadcast, "capture viewer", { muted: true }); const [publisher, publisherErrors] = await open( await browserFor(["--use-fake-device-for-media-stream"]), pageUrl(server.origin, "publish", { url: relay, broadcast }), @@ -536,7 +575,7 @@ try { console.error("=== cold start ==="); // No trace yet. DOM snapshots evaluate with a user gesture, and the player's graph is built // after the first of those, so Chromium would start it running and the gate below would fail. - let [player, playerErrors] = await subscriber(broadcast, "player", false, false); + let [player, playerErrors] = await subscriber(broadcast, "player", { trace: false }); // Video has to reach the canvas with no gesture at all: only audio is ever gated. const first = await waitForState(player, playerErrors, { @@ -573,7 +612,7 @@ try { predicate: (state) => state.audioContext === "running", }); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "cold start"); + await measurePlayback(player, playerErrors, "cold start"); // ── pause and resume ───────────────────────────────────────────────────── if (wants("pause")) { @@ -616,7 +655,7 @@ try { predicate: (state) => !state.paused && (state.frameId ?? 0) > paused, }); console.error(` resumed ${(resumed.frameId ?? 0) - paused} frames past the pause`); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after resume"); + await measurePlayback(player, playerErrors, "after resume"); } // ── disable and re-enable the video rendition ──────────────────────────── @@ -654,7 +693,7 @@ try { predicate: (state) => (state.frameId ?? 0) > (before.frameId ?? 0), }); console.error(` black while disabled, then resumed at frame ${resumed.frameId}`); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after enable"); + await measurePlayback(player, playerErrors, "after enable"); } // ── unsubscribe and rejoin ─────────────────────────────────────────────── @@ -675,7 +714,8 @@ try { description: `the presented frame to move past the ${left} it stopped on`, predicate: (state) => (state.frameId ?? 0) > left, }); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after rejoin"); + await waitForLive(publisher, publisherErrors, player, playerErrors, "rejoin reaches live"); + await measurePlayback(player, playerErrors, "after rejoin"); } // ── detach and reattach ────────────────────────────────────────────────── @@ -716,7 +756,8 @@ try { description: `the presented frame to move past the ${busy.frameId} showing before the detach`, predicate: (state) => (state.frameId ?? 0) > (busy.frameId ?? 0), }); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after reattach"); + await waitForLive(publisher, publisherErrors, player, playerErrors, "reattach reaches live"); + await measurePlayback(player, playerErrors, "after reattach"); } // ── publisher stop and same-path republish ─────────────────────────────── @@ -741,7 +782,7 @@ try { predicate: (state) => state.frameId !== undefined && state.frameId < (before.frameId ?? 0), }); console.error(` recovered at frame ${recovered.frameId}, restarted from ${before.frameId}`); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after republish"); + await measurePlayback(player, playerErrors, "after republish"); } // ── late join ──────────────────────────────────────────────────────────── @@ -751,7 +792,9 @@ try { if (wants("late-join")) { console.error("=== late join ==="); await player.close(); - [player, playerErrors] = await subscriber(broadcast, "latecomer"); + [player, playerErrors] = await subscriber(broadcast, "latecomer", { + delay: values.lag ? LAGGED_DELAY : undefined, + }); const joined = Date.now(); await gesture(player); @@ -763,12 +806,12 @@ try { }); const startMs = Date.now() - joined; - const live = await waitForLive(publisher, publisherErrors, player, playerErrors); + const live = await waitForLive(publisher, publisherErrors, player, playerErrors, "late join reaches live"); console.error( ` showed frame ${shown.frameId} after ${startMs}ms, ${framesToMs(live.first)}ms behind the fixture; ` + `live ${live.after}ms later, ${framesToMs(live.lag)}ms behind`, ); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "late join"); + await measurePlayback(player, playerErrors, "late join"); } if (wants("capture-denial")) await captureDenial(`${broadcast}-capture.hang`); diff --git a/test/interop/clients/js/src/setup.ts b/test/interop/clients/js/src/setup.ts index 46bc44b22f..eecdd38221 100644 --- a/test/interop/clients/js/src/setup.ts +++ b/test/interop/clients/js/src/setup.ts @@ -84,6 +84,10 @@ if (role === "publish") { const visible = params.get("visible"); if (visible) el.setAttribute("visible", visible); + // Only the late-join negative control passes this, to hold the player behind live. + const delay = params.get("delay"); + if (delay) el.setAttribute("delay", delay); + const player = document.createElement("moq-watch-ui"); player.appendChild(el); document.body.appendChild(player); diff --git a/test/interop/interop.sh b/test/interop/interop.sh index a6c0c93fde..497a778107 100755 --- a/test/interop/interop.sh +++ b/test/interop/interop.sh @@ -786,6 +786,7 @@ if [[ "$MEDIA" -eq 1 ]]; then run_media "control: silent audio" --fault silent-audio --cases none --expect-fail "audio tone" run_media "control: offset audio" --fault audio-offset --cases none --expect-fail "audio/video sync" run_media "control: leaked session" --leak --cases detach --expect-fail "resource baseline" + run_media "control: lagging latecomer" --lag --cases late-join --expect-fail "late join reaches live" fi elif [[ "$NEGATIVE" -eq 1 ]]; then # Negative control: no publisher. Every subscriber must FAIL (time out with