From 3c1a62864b951ed346ef2d59ebb91c44e92eb37c Mon Sep 17 00:00:00 2001 From: Eva Date: Wed, 10 Jun 2026 13:59:34 +0700 Subject: [PATCH] =?UTF-8?q?fix(viewer):=20budget-aware=20stuck-backstop=20?= =?UTF-8?q?=E2=80=94=20stop=20false-firing=20'stuck'=20on=20healthy=20slow?= =?UTF-8?q?=20turns=20(refs=20#745,=20follow-up=20to=20#746)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The #746 hard stuck ceiling (PENDING_STUCK_BACKSTOP_MS) was a flat 5 min, armed once at submit and not firstBeat-aware — but the system's own HEALTHY turn budgets exceed it: the cold open measures ~300s with a 400-500s deadline (qa/lib_beat_driver.sh clawdnd_dm_timeout, 500s for Opus), and a continuing beat can legitimately run ~400s (scripts/play.sh CLAWDND_BEAT_TIMEOUT=200s + ONE retry). When the ceiling fired mid-flight on a working turn: pendingActive flipped false (action bar re-opened, screen-table.jsx), the "DM seems stuck" toast fired, and retryStuck re-POSTed the move - the SAME intent resolved TWICE once the in-flight beat landed. Fix (minimal, option (a) of the audit): make the ceiling budget-aware by turn position via a pure stuckBackstopMs(firstBeat) selector (mirrors recoveryWindowMs): firstBeat => 9 min (>= the 500s cold-open budget), later beats => 7 min (>= the ~400s timeout+retry budget). Both stay strictly under the 12-min null-backstop, so the #745 ordering holds: position recovery (resettable) < stuck ceiling (hard, recoverable) < null-backstop. Tests (red-first against main): the recovery-timing harness now runs real effects + a scripted /chat poll (ported from test_live_narration_stream.py), so a test can RESOLVE a turn - flipping firstBeat - and exercise the later-beat ceiling branch of the real hook. New: the missing-band first-beat test (healthy stream, resolves ~430s - false-fired at exactly 300s on main), the later-beat ~380s retry-budget test, the budget-aware ordering/selector contract; updated: progress-does-not-defer-the-ceiling at the new 9-min value; retained: trickle-then-freeze still recovers to recoverable stuck (the #745 protection). --- viewer/openworlds/app.jsx | 39 ++- viewer/tests/test_recovery_timing.py | 407 +++++++++++++++++++-------- 2 files changed, 326 insertions(+), 120 deletions(-) diff --git a/viewer/openworlds/app.jsx b/viewer/openworlds/app.jsx index 834ced18..dae8266f 100644 --- a/viewer/openworlds/app.jsx +++ b/viewer/openworlds/app.jsx @@ -238,12 +238,23 @@ const PENDING_BACKSTOP_MS = 12 * 60 * 1000; // …with the original hard b // CLEARS pending to null (a plain re-enabled bar, NO "Try again", the partial narration stranded). That is // the ~12–15-min lockout the newbie gave up on. This ceiling bounds TOTAL stall from submit regardless of // how many partials trickle in (progress does not reset it), and resolves to the SAME recoverable `stuck` -// state (the bar re-opens as "Try again"). It is generous enough to clear a worst-case HEALTHY beat (which -// RESOLVES on /chat → clearPending cancels every timer long before this fires), so it never false-positives -// on a slow-but-alive turn; it only ever fires on a genuine freeze. Strictly between the position windows -// and the 12-min null-backstop, so the ordering is: position recovery (resettable) < stuck-backstop (hard, -// recoverable) < null-backstop (hard, last-resort clear). -const PENDING_STUCK_BACKSTOP_MS = 5 * 60 * 1000; // #745: hard stuck ceiling from submit (progress does NOT reset it). +// state (the bar re-opens as "Try again"). It must be generous enough to clear a worst-case HEALTHY beat +// (which RESOLVES on /chat → clearPending cancels every timer long before this fires), so it never +// false-positives on a slow-but-alive turn; it only ever fires on a genuine freeze. Strictly between the +// position windows and the 12-min null-backstop, so the ordering is: position recovery (resettable) < +// stuck-backstop (hard, recoverable) < null-backstop (hard, last-resort clear). +// #746: the ceiling is BUDGET-AWARE by turn position, because the original flat 5-min value sat BELOW the +// system's own healthy turn budgets and false-fired `stuck` on healthy slow turns: the cold open measures +// ~300s with a 400–500s deadline (qa/lib_beat_driver.sh clawdnd_dm_timeout — 500s for Opus), and a healthy +// CONTINUING beat can legitimately run ~400s (scripts/play.sh CLAWDND_BEAT_TIMEOUT=200s + ONE retry). When +// the flat ceiling fired mid-flight on a working turn, pendingActive flipped false (the action bar +// re-opened, screen-table.jsx), the "DM seems stuck" toast fired, and retryStuck re-POSTed the move — so +// the SAME intent resolved TWICE once the in-flight beat landed. The fix: firstBeat (the cold open) ⇒ +// 9 min (≥ the 500s cold-open budget); later beats ⇒ 7 min (≥ the ~400s timeout+retry budget). Both stay +// strictly under the 12-min null-backstop, preserving the #745 ordering above — a genuine +// trickle-then-freeze still surfaces the recoverable `stuck` affordance well before the silent null clear. +const PENDING_STUCK_BACKSTOP_MS = 7 * 60 * 1000; // #745/#746: later-beat hard stuck ceiling from submit (progress does NOT reset it). +const PENDING_STUCK_BACKSTOP_FIRST_MS = 9 * 60 * 1000; // #746: first-beat (cold-open) hard stuck ceiling — clears the 400–500s cold-open budget. // #648: a JUST-armed narrating turn is protected from a SPURIOUS same-tick clear (the immediate // post-armPending surface poll, a /chat cursor-reset re-reading the prior resolved turn's line as a // fresh resolution, or a transient campaignId flip tripping the per-run reset) for this long — so the @@ -259,6 +270,12 @@ const PENDING_ARM_GRACE_MS = 10 * 1000; function recoveryWindowMs(firstBeat) { return firstBeat ? PENDING_RECOVERY_FIRST_MS : PENDING_RECOVERY_MS; } +// #746: the hard stuck-backstop ceiling by turn position, mirroring recoveryWindowMs — the single +// source of truth armPending arms. Pure + exported (window.stuckBackstopMs below) so the +// budget-aware ceiling contract is unit-testable without reaching into the hook's internals. +function stuckBackstopMs(firstBeat) { + return firstBeat ? PENDING_STUCK_BACKSTOP_FIRST_MS : PENDING_STUCK_BACKSTOP_MS; +} // #402: BOUND the live tail. `chatBeats` (every streamed/turn-end DM narration + dialogue beat) and // `log` (every optimistic player echo) accumulated for the WHOLE session with no cap — so a long @@ -456,9 +473,13 @@ function useLiveSession(state) { // null-backstop (which strands the partial narration behind a plain re-enabled bar). It is generous // enough that a healthy turn always RESOLVES (clearPending → clearTimers) first, so it never trips a // slow-but-alive beat. Fires only when nothing has resolved by its deadline. + // #746: the ceiling is budget-aware by turn position (stuckBackstopMs): the cold open gets 9 min + // (its healthy budget is 400–500s), later beats 7 min (a healthy timeout+retry beat runs ~400s) — + // a flat 5 min sat INSIDE those budgets and false-fired on healthy slow turns (bar re-opened + + // "DM seems stuck" toast + retryStuck double-resolution while the beat was still in flight). stuckBackstopTimer.current = window.setTimeout(() => { setPendingState((p) => (p ? { ...p, stuck: true } : p)); - }, PENDING_STUCK_BACKSTOP_MS); + }, stuckBackstopMs(firstBeat)); backstopTimer.current = window.setTimeout(() => setPendingState(null), PENDING_BACKSTOP_MS); }, [clearTimers, setPendingState]); @@ -727,12 +748,14 @@ window.useLiveSession = useLiveSession; // #348: expose the recovery-timing contract for tests (and devtools introspection). Purely // additive — nothing in the running app reads these off window; the hook uses the locals above. window.recoveryWindowMs = recoveryWindowMs; +window.stuckBackstopMs = stuckBackstopMs; // #746: the budget-aware hard-ceiling selector (pure) window.__PENDING_TIMING__ = { recoveryMs: PENDING_RECOVERY_MS, recoveryFirstMs: PENDING_RECOVERY_FIRST_MS, backstopMs: PENDING_BACKSTOP_MS, armGraceMs: PENDING_ARM_GRACE_MS, // #648: the just-armed-turn protection window - stuckBackstopMs: PENDING_STUCK_BACKSTOP_MS, // #745: hard stuck ceiling from submit (progress does NOT reset it) + stuckBackstopMs: PENDING_STUCK_BACKSTOP_MS, // #745/#746: later-beat hard stuck ceiling from submit (progress does NOT reset it) + stuckBackstopFirstMs: PENDING_STUCK_BACKSTOP_FIRST_MS, // #746: first-beat (cold-open) hard stuck ceiling }; // #402: expose the live-tail bound for tests/devtools introspection (purely additive — the hook // closes over the consts directly; nothing in the running app reads these off window). diff --git a/viewer/tests/test_recovery_timing.py b/viewer/tests/test_recovery_timing.py index cec3c97d..7bd36bc1 100644 --- a/viewer/tests/test_recovery_timing.py +++ b/viewer/tests/test_recovery_timing.py @@ -13,15 +13,26 @@ • LATER beats (the ~35–60s norm): the snappy PENDING_RECOVERY_MS (~90s). • The 12-min hard backstop is unchanged. +#745 added a HARD stuck ceiling from submit (progress does NOT reset it) so a +mid-stream trickle-then-freeze still recovers to the `stuck` 'Try again' affordance. +#746 made that ceiling BUDGET-AWARE by turn position: the original flat 5-min value +sat BELOW the system's own healthy turn budgets (cold open ~300s measured with a +400–500s deadline; a continuing beat can run ~400s via play.sh's 200s timeout + ONE +retry), so it false-fired `stuck` on healthy slow turns — re-opening the action bar, +toasting "DM seems stuck", and letting a retry re-POST resolve the same intent TWICE. + These tests exercise the REAL code by transpiling the actual `.jsx` with the SAME bundled Babel-standalone the browser uses and running it under Node with a deterministic React + fake-timer stub, so the test tracks the shipped behavior rather than a reimplementation (mirrors test_sanitize_narration.py). They cover: - • the timing CONTRACT (`recoveryWindowMs` for both branches + the constants); + • the timing CONTRACT (`recoveryWindowMs` + `stuckBackstopMs` for both branches + + the constants and their strict ordering); • the hook's observable FIRST-beat behavior (no false stuck at 91s; recovers after the long window; the 12-min backstop still force-clears) — the #348 fix; - • the LATER-beat branch (snappy 90s) — preserved for a genuine mid-session stall; + • the LATER-beat branch — the harness's /chat poll is LIVE, so a test can resolve + a turn (flipping firstBeat) and exercise the later-beat ceiling for real; + • the #745 mid-stream-stall ceiling + the #746 budget-aware false-fire fix; • the #344 contract (`armPending`/`clearPending` shape the retry path relies on). """ @@ -38,14 +49,18 @@ _BABEL = _OPENWORLDS / "vendor" / "babel-standalone-7.29.0.min.js" -# A self-contained Node harness: a minimal-but-real React stub (storing state, refs, -# callbacks per render so setState re-renders the hook) plus a controllable clock + timer -# queue. It transpiles screen-table.jsx (defines sanitizeNarration onto window, used by -# app.jsx) then app.jsx with the bundled Babel, mounts useLiveSession over a live campaign, -# and exposes a tiny scripting surface (`h`) so each test can arm/clear pending, advance the -# fake clock, and read pending state — plus the pure `recoveryWindowMs` + constants. +# A self-contained Node harness: a real-enough React stub (state/refs/callbacks/effects persist +# across renders; useEffect bodies RUN, so the /chat + /events polls are live) plus a controllable +# clock + one-shot timer queue AND a scripted fetch (a per-URL queue of JSON responses) with a +# manual interval pump. The live /chat poll matters here (#746): resolving a turn — a {"role":"dm"} +# line landing on /chat — is the ONLY thing that flips the hook's firstBeat off, and the later-beat +# stuck-backstop branch can't be exercised without it. It transpiles screen-table.jsx (defines +# sanitizeNarration onto window, used by app.jsx) then app.jsx with the bundled Babel, mounts +# useLiveSession over a live campaign, and exposes a tiny scripting surface (`h`) so each test can +# arm/clear pending, stream progress, RESOLVE turns, advance the fake clock, and read pending state +# — plus the pure `recoveryWindowMs`/`stuckBackstopMs` + constants. # -# `script` is a JS expression evaluated with `h`/`win` in scope; its value → JSON on stdout. +# `script` is an async JS body evaluated with `h`/`win` in scope; its `return` value → JSON on stdout. _HARNESS = r""" const fs = require('fs'); const vm = require('vm'); @@ -78,33 +93,103 @@ NOW = target; } -// ---- a minimal real React: hook cells persist across re-renders ------------ +// ---- a real-enough React (ported from test_live_narration_stream.py) ------- +// Hook cells + effects persist across renders; useEffect bodies actually RUN so the /chat poll is +// live and a test can RESOLVE a turn — flipping firstBeat — before arming the next one (#746 needs +// the later-beat branch of the hook, which an effect-less stub cannot reach). KEY contract +// (mirrors React's actual model): rendering and EFFECT-FLUSHING are decoupled — a setState only +// recomputes the render output; effects run in a separate re-entrancy-guarded committed pass, so a +// setState fired from inside an effect schedules (not recursively runs) the next flush. function makeReact() { - const cells = []; - let idx = 0; + const stateCells = []; + const refCells = []; + const cbCells = []; // memoized { fn, deps } per useCallback slot + const effects = []; // { deps, cleanup } per useEffect slot, in mount order + let sIdx = 0, rIdx = 0, cIdx = 0, eIdx = 0; let renderFn = null; let result = null; + const pendingEffects = []; // effect bodies queued this render, drained by flushEffects() + let flushing = false; // re-entrancy guard: a setState during a flush re-renders only + function useState(init) { - const i = idx++; - if (cells[i] === undefined) cells[i] = { v: typeof init === 'function' ? init() : init }; - const cell = cells[i]; - const set = (next) => { cell.v = (typeof next === 'function') ? next(cell.v) : next; rerender(); }; + const i = sIdx++; + if (stateCells[i] === undefined) stateCells[i] = { v: typeof init === 'function' ? init() : init }; + const cell = stateCells[i]; + const set = (next) => { cell.v = (typeof next === 'function') ? next(cell.v) : next; render(); }; return [cell.v, set]; } function useRef(init) { - const i = idx++; - if (cells[i] === undefined) cells[i] = { current: init }; - return cells[i]; + const i = rIdx++; + if (refCells[i] === undefined) refCells[i] = { current: init }; + return refCells[i]; + } + function depsEqual(a, b) { + if (!a || !b || a.length !== b.length) return false; + for (let i = 0; i < a.length; i++) if (a[i] !== b[i]) return false; + return true; + } + // useCallback MUST memoize by deps (same identity when deps are unchanged) — a naive passthrough + // returns a fresh fn every render → every effect whose deps include a callback re-queues every + // render → an effect's setState re-renders → infinite loop at mount. + function useCallback(fn, deps) { + const i = cIdx++; + const prev = cbCells[i]; + if (prev === undefined || !depsEqual(prev.deps, deps)) { + cbCells[i] = { fn, deps }; + return fn; + } + return prev.fn; + } + function useEffect(fn, deps) { + const i = eIdx++; + const prev = effects[i]; + const changed = !prev || !depsEqual(prev.deps, deps); + if (changed) { + pendingEffects.push(() => { + if (prev && typeof prev.cleanup === 'function') prev.cleanup(); + const cleanup = fn(); + effects[i] = { deps, cleanup: typeof cleanup === 'function' ? cleanup : null }; + }); + if (!prev) effects[i] = { deps, cleanup: null }; // seed so the slot exists + else effects[i].deps = deps; + } + } + function render() { + sIdx = 0; rIdx = 0; cIdx = 0; eIdx = 0; + result = renderFn(); + } + function flushEffects() { + if (flushing) return; + flushing = true; + try { while (pendingEffects.length) pendingEffects.shift()(); } + finally { flushing = false; } } - // The /chat poll + clearTimers effects are NOT exercised here (we drive arm/clear + the - // clock directly), so useEffect/useCallback can be lightweight: callbacks pass through, - // effects are skipped (their cleanup-only/interval bodies aren't under test). - function useCallback(fn) { return fn; } - function useEffect() {} - function rerender() { idx = 0; result = renderFn(); } const React = { useState, useRef, useCallback, useEffect, createElement: () => null, Fragment: 'F' }; - function mount(fn) { renderFn = fn; rerender(); } - return { React, mount }; + function mount(fn) { renderFn = fn; render(); flushEffects(); } + function commit() { flushEffects(); } + function api() { return result; } + return { React, mount, commit, api }; +} + +// ---- a SCRIPTED fetch + manual interval pump (ported from test_live_narration_stream.py) ---- +const responses = { '/events': [], '/chat': [] }; +function enqueue(path, payload) { responses[path].push(payload); } +function pathOf(url) { return String(url).split('?')[0]; } +function fetchStub(url) { + const p = pathOf(url); + const q = responses[p]; + const payload = (q && q.length) ? q.shift() : {}; // empty when nothing scripted + return Promise.resolve({ ok: true, json: () => Promise.resolve(payload) }); +} +const intervals = []; +function setIntervalStub(fn) { intervals.push(fn); return intervals.length; } +function clearIntervalStub() {} +// Fire every registered poll once AND await the async chain each returns (the polls do +// `await fetch().json()` then setState), so a test reads fully-settled state afterward. +async function tickAll() { + const ps = intervals.slice().map((fn) => { try { return fn(); } catch (_e) { return undefined; } }); + await Promise.all(ps.map((p) => Promise.resolve(p))); + await new Promise((r) => setImmediate(r)); } const reactHost = makeReact(); @@ -115,12 +200,15 @@ ReactDOM: { createRoot: () => ({ render() {} }) }, // getElementById returns truthy so screen-table.jsx's ensureDmNarrateStyle() IIFE early-returns // (it injects a