From a9ac9aba2a3160d0a91d3817d54d3ed94be4884f Mon Sep 17 00:00:00 2001 From: Eva Date: Sat, 30 May 2026 09:31:06 +0700 Subject: [PATCH] fix(openworlds): adaptive 'stuck' recovery so a slow Act-opening isn't pre-empted (Closes #348) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The #324 narrative persona hit "The Dungeon Master seems stuck — No reply came back in time" with NO narration at a cliffhanger: the #342 recovery fired at a fixed 90s from submit, but the DM's legit cold-open (Act-opening) can take SEVERAL minutes (a blind newbie run saw 5–8 min and succeed). The 90s wall-clock false-fired 'stuck' mid-opening → the still-coming narration + momentum were lost. Finding (STEP 1): the DM beat lands ALL-AT-ONCE — no streaming/partial/heartbeat. Both the duo runner (qa/run_duo.sh) and the human runner (qa/play_human.sh) capture the DM turn via `claude -p --output-format stream-json > out`, then extract only the final `result` text AFTER the turn completes and append ONE {"role":"dm",...} line to .chat.jsonl. The /chat poll therefore returns zero new items for the entire turn, then the complete beat — there is NO in-flight progress to reset on. So the fix is a THRESHOLD-RAISE, not progress-aware (a progress-aware reset would require a wire change, which is out of scope). Fix (viewer-only, no engine/wire change): - The recovery 'stuck' window is now turn-position-aware (recoveryWindowMs): • FIRST beat of a session (cold-open): 4 min (PENDING_RECOVERY_FIRST_MS) • LATER beats (~35–60s norm): 90s (PENDING_RECOVERY_MS, unchanged) "first beat?" = no DM narration has arrived this session yet (dmBeatCountRef === 0, already reset to 0 on every run change). - The 12-min hard backstop (#338) is UNCHANGED — a turn that blows even the first-beat window still gets force-cleared. - The "DM is narrating…" affordance is now HONEST: the first beat reads "Setting the opening scene — the first beat of a session can take a few minutes"; later beats keep "up to a minute". (#336 animation/elapsed/reduced-motion fully intact.) Preserved invariants: - #340 — the /chat poll still clearPending()s on ANY narration beat, so a beat that lands after 'stuck' still renders into the log + clears the indicator (untouched path). - #344 — armPending/clearPending signatures + retryStuck/lastMoveRef unchanged; timers disarm cleanly so 'Try again' re-arms. - #336 — DmNarratingBeat dots/elapsed/reduced-motion preserved; firstBeat defaults falsy (older pending objects show the original copy) — additive-by-default. Tests: viewer/tests/test_recovery_timing.py transpiles the REAL app.jsx with the bundled Babel and drives useLiveSession under Node with a deterministic clock + fake timers (mirrors test_sanitize_narration.py). Proves: first beat is NOT stuck at 91s (the bug) yet still recovers after 4 min; later-beat window stays 90s; the 12-min backstop still force-clears; clearPending disarms timers. axe = 0 across all 17 screens; both JSX files transpile. --- viewer/openworlds/app.jsx | 49 ++++- viewer/openworlds/screen-table.jsx | 14 +- viewer/tests/test_recovery_timing.py | 270 +++++++++++++++++++++++++++ 3 files changed, 324 insertions(+), 9 deletions(-) create mode 100644 viewer/tests/test_recovery_timing.py diff --git a/viewer/openworlds/app.jsx b/viewer/openworlds/app.jsx index 6894141a..667706b1 100644 --- a/viewer/openworlds/app.jsx +++ b/viewer/openworlds/app.jsx @@ -79,8 +79,29 @@ window.neutralizeMarkup = window.neutralizeMarkup || function neutralizeMarkup(r // // The poll is best-effort and a no-op unless a LIVE campaign is bound (mirrors the server's // /chat gating: empty items when no chat is configured / the view isn't the live run). -const PENDING_RECOVERY_MS = 90 * 1000; // #342: re-enable the bar if the DM stalls this long… -const PENDING_BACKSTOP_MS = 12 * 60 * 1000; // …with the original hard backstop as a final net. +// #348: the recovery 'stuck' timeout is ADAPTIVE by turn position, because the DM beat lands +// all-at-once (the /chat tail carries NO streaming/partial/heartbeat signal — the duo+human +// runners append ONE {"role":"dm",...} line only after the whole turn's `result` is in, so the +// poll sees zero new items for the entire turn then the complete beat). With no in-flight +// progress to reset on, a fixed wall-clock from submit was the only lever — and at 90s it +// PRE-EMPTED the legit Act-opening (the #324 narrative persona saw the cold-open take several +// minutes and still succeed → false 'stuck', narration lost at a cliffhanger, #348). +// • FIRST beat of a session (the cold-open / Act-opening) gets a generous window — the engine +// is building the world + setting the scene; a blind newbie run saw this take 5–8 min. +// • LATER beats are quick (the old 90s was tuned for these); keep them snappy so a genuine +// mid-session stall still recovers fast. +// The 12-min hard backstop is UNCHANGED — a turn that blows even the first-beat window still +// gets force-cleared. "first beat?" = no DM narration has arrived this session yet (the hook's +// dmBeatCountRef, reset to 0 on every run change). +const PENDING_RECOVERY_MS = 90 * 1000; // #342: later-beat stall window (DM turns are ~35–60s). +const PENDING_RECOVERY_FIRST_MS = 4 * 60 * 1000; // #348: first-beat (Act-opening) window — fits the multi-minute cold open. +const PENDING_BACKSTOP_MS = 12 * 60 * 1000; // …with the original hard backstop as a final net. +// #348: the single source of truth for the recovery window, by turn position. Pure + exported +// (window.__PENDING_TIMING__ below) so the timing contract is unit-testable without reaching into +// the hook's internal beat counter. firstBeat ⇒ the longer cold-open window; else the snappy one. +function recoveryWindowMs(firstBeat) { + return firstBeat ? PENDING_RECOVERY_FIRST_MS : PENDING_RECOVERY_MS; +} function useLiveSession(state) { const campaigns = Array.isArray(state?.campaigns) ? state.campaigns : []; const activeCampaign = @@ -109,15 +130,23 @@ function useLiveSession(state) { const clearPending = React.useCallback(() => { clearTimers(); setPending(null); }, [clearTimers]); - // #342: arm the narrating indicator + a SHORT recovery timeout. If a DM beat doesn't arrive within - // PENDING_RECOVERY_MS the turn is flagged `stuck` (the bar re-enables with a "try again" hint) + // #342 + #348: arm the narrating indicator + a recovery timeout. If a DM beat doesn't arrive within + // the recovery window the turn is flagged `stuck` (the bar re-enables with a "try again" hint) // instead of staying frozen until the 12-minute backstop. A real beat (below) clears it outright. + // #348: the window is turn-position-aware — the FIRST beat of a session (the cold-open, which the + // engine spends minutes building) gets PENDING_RECOVERY_FIRST_MS so a slow-but-valid opening is no + // longer falsely declared stuck; later beats keep the snappy PENDING_RECOVERY_MS. `firstBeat` is + // recorded on the pending object so the narrating affordance can set an honest expectation, and so + // a beat that lands AFTER 'stuck' still renders (the #340 path is unchanged — clearPending on any + // real narration beat regardless of this flag). const armPending = React.useCallback((text) => { clearTimers(); - setPending({ text, since: Date.now(), stuck: false }); + const firstBeat = dmBeatCountRef.current === 0; + const recoveryMs = recoveryWindowMs(firstBeat); + setPending({ text, since: Date.now(), stuck: false, firstBeat }); recoveryTimer.current = window.setTimeout(() => { setPending((p) => (p ? { ...p, stuck: true } : p)); - }, PENDING_RECOVERY_MS); + }, recoveryMs); backstopTimer.current = window.setTimeout(() => setPending(null), PENDING_BACKSTOP_MS); }, [clearTimers]); @@ -186,6 +215,14 @@ function useLiveSession(state) { return { chatBeats, log, pending, armPending, clearPending, recordPlayerEcho }; } 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.__PENDING_TIMING__ = { + recoveryMs: PENDING_RECOVERY_MS, + recoveryFirstMs: PENDING_RECOVERY_FIRST_MS, + backstopMs: PENDING_BACKSTOP_MS, +}; function App() { const [state, setState] = React.useState(window.INITIAL_STATE || {}); diff --git a/viewer/openworlds/screen-table.jsx b/viewer/openworlds/screen-table.jsx index e9d41df4..b6e103c5 100644 --- a/viewer/openworlds/screen-table.jsx +++ b/viewer/openworlds/screen-table.jsx @@ -510,7 +510,7 @@ function ScreenTable({ onNavigate, state, setState, liveSession }) { {visibleLog.length ? visibleLog.map((entry, i) => ( )) :
No moves yet
} - {pendingActive && } + {pendingActive && } {pendingStuck && } @@ -798,7 +798,12 @@ function LogEntry({ entry }) { // elapsed counter and the dots are aria-hidden so a screen reader isn't spammed every tick. // Reduced-motion: the pulsing dots + shimmer are disabled (CSS below + the global token); the // elapsed text and hint remain, so the "is it busy?" question is still answered without motion. -function DmNarratingBeat({ since }) { +// #348: `firstBeat` makes the expectation HONEST. The DM beat lands all-at-once (no streaming), +// and the FIRST beat — the cold-open/Act-opening the engine spends minutes building — legitimately +// takes several minutes. Telling a first-timer "up to a minute" then re-opening the bar at 90s was +// the #348 false-stuck trap. For the opening we say "a few minutes"; later beats keep "up to a +// minute" (they really are ~35–60s). This copy mirrors the adaptive recovery window in app.jsx. +function DmNarratingBeat({ since, firstBeat }) { const start = typeof since === "number" ? since : Date.now(); const [now, setNow] = React.useState(() => Date.now()); React.useEffect(() => { @@ -809,6 +814,9 @@ function DmNarratingBeat({ since }) { const mm = Math.floor(secs / 60); const ss = String(secs % 60).padStart(2, "0"); const elapsedLabel = `${mm}:${ss}`; + const waitHint = firstBeat + ? "Setting the opening scene — the first beat of a session can take a few minutes." + : "Weaving the next beat — this can take up to a minute."; return (
@@ -828,7 +836,7 @@ function DmNarratingBeat({ since }) {
- Weaving the next beat — this can take up to a minute. + {waitHint}
diff --git a/viewer/tests/test_recovery_timing.py b/viewer/tests/test_recovery_timing.py new file mode 100644 index 00000000..508017b8 --- /dev/null +++ b/viewer/tests/test_recovery_timing.py @@ -0,0 +1,270 @@ +"""Behavior tests for the #348 adaptive 'stuck' recovery window in `useLiveSession`. + +`useLiveSession` (viewer/openworlds/app.jsx) owns the "DM is narrating…" pending +state and the recovery/backstop timers. Because the DM beat lands ALL-AT-ONCE (the +/chat tail carries no streaming/partial/heartbeat signal — the duo + human runners +append ONE {"role":"dm",...} line only after the whole turn's `result` is in), the +recovery is a wall-clock from submit. #342 fixed it at 90s, which PRE-EMPTED the +legit multi-minute Act-opening → false 'stuck', narration lost at a cliffhanger +(#348). #348 makes the window turn-position-aware: + + • FIRST beat of a session (the cold-open the engine spends minutes building): + a generous PENDING_RECOVERY_FIRST_MS (~4 min) — no longer falsely stuck. + • LATER beats (the ~35–60s norm): the snappy PENDING_RECOVERY_MS (~90s). + • The 12-min hard backstop is unchanged. + +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 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 #344 contract (`armPending`/`clearPending` shape the retry path relies on). +""" + +import json +import shutil +import subprocess +import unittest +from pathlib import Path + + +_OPENWORLDS = Path(__file__).resolve().parents[1] / "openworlds" +_APP = _OPENWORLDS / "app.jsx" +_SCREEN_TABLE = _OPENWORLDS / "screen-table.jsx" +_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. +# +# `script` is a JS expression evaluated with `h`/`win` in scope; its value → JSON on stdout. +_HARNESS = r""" +const fs = require('fs'); +const vm = require('vm'); +const Babel = require(%(babel)s); + +// ---- deterministic clock + one-shot timer queue ---------------------------- +let NOW = 1000000; +const timers = []; +let nextId = 1; +function setTimeoutStub(fn, ms) { + const id = nextId++; + timers.push({ id, at: NOW + (ms || 0), fn, cleared: false }); + return id; +} +function clearTimeoutStub(id) { + const t = timers.find((t) => t.id === id); + if (t) t.cleared = true; +} +// Advance the clock by `ms`, firing each un-cleared timer whose deadline we cross, in +// deadline order — exactly the browser's behavior. +function advance(ms) { + const target = NOW + ms; + while (true) { + const due = timers.filter((t) => !t.cleared && t.at <= target).sort((a, b) => a.at - b.at)[0]; + if (!due) break; + NOW = due.at; + due.cleared = true; // setTimeout is one-shot + due.fn(); + } + NOW = target; +} + +// ---- a minimal real React: hook cells persist across re-renders ------------ +function makeReact() { + const cells = []; + let idx = 0; + let renderFn = null; + let result = null; + 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(); }; + return [cell.v, set]; + } + function useRef(init) { + const i = idx++; + if (cells[i] === undefined) cells[i] = { current: init }; + return cells[i]; + } + // 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 }; +} + +const reactHost = makeReact(); +const sandbox = { + React: reactHost.React, + // app.jsx ends with ReactDOM.createRoot(...).render(); stub it to a no-op so module load + // doesn't try to mount the whole app — we drive useLiveSession ourselves (defined above that line). + ReactDOM: { createRoot: () => ({ render() {} }) }, + // getElementById returns truthy so screen-table.jsx's ensureDmNarrateStyle() IIFE early-returns + // (it injects a