From 41f7324e0443ed0f3f55e22c9fcc9f44bfbd3cd4 Mon Sep 17 00:00:00 2001 From: Eva Date: Sat, 30 May 2026 22:26:04 +0700 Subject: [PATCH] fix(openworlds): slow-but-working DM turn no longer reads as broken (#399) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A full-arc playtest gave up on beats 2–4: the DM turn COMPLETED (runbooks fired, the in-game clock advanced) but exceeded the viewer's 90s "stuck" window, so the player saw "The Dungeon Master seems stuck — No reply came back in time", the bar re-opened with "Try again", and retrying DUPLICATED the player's action in the chronicle. Two MAJOR timeout bugs + one MINOR dup bug — the single blocker to a fresh player finishing an 8-beat session. Root cause (verified against the engine + DM skill, not just the static code): #393 shipped a viewer-side live /events stream + a stall-clock reset (notePendingProgress), which on paper makes a long turn never trip 'stuck'. But EVERY shipped DM path (duo / human / native) persists a turn's narration in ONE batched write at turn-END (SKILL.md step 7 → persist_beat — prose FIRST, persist LAST, for latency). So nothing is written to the per-session log mid-turn → /events surfaces a beat only at turn-end → the reset never fires DURING the turn → later beats run under the COLD 90s wall-clock. The 90s window was tuned for the ~35–60s norm; a content-rich beat 2–4 runs 90–120s and tripped it on a working turn. The streaming code is correct viewer-side (turns 2+ tail fine); it just has nothing to stream today. Viewer-only fixes (no swift rebuild; engine sole-writer + wire contracts untouched): - Raise the later-beat 'stuck' window 90s → 180s (PENDING_RECOVERY_MS) so a worst-case ~120s turn finishes without a false 'stuck'. First-beat (4 min) + 12-min backstop unchanged. The notePendingProgress reset is KEPT (correct, and starts helping the day a DM path logs beats incrementally). - Make the player echo idempotent (recordPlayerEcho): a 'Try again' re-POST of the exact stalled move no longer appends a duplicate chronicle action. Only a back-to-back identical (who, text) is suppressed; distinct moves are kept. - Honest later-beat wait copy ("a minute or two") matching the 180s window. Tests (viewer/tests, real-JSX Babel-transpile harness, single-process): - test_recovery_timing.py: later window now 180s; no false 'stuck' at 120s. - test_live_narration_stream.py: a resolved beat flips the next turn to a LATER beat (so the 180s window governs turns 2+); later window == 180s; player echo idempotent on retry; distinct actions preserved. - test_cold_open_progress.py: stale later-beat comment refreshed. Local: 195/196 viewer tests pass (the 1 failure is a pre-existing ambient-env pydantic import in test_portrait_gen, unrelated to this change). license_check green. --- viewer/openworlds/app.jsx | 40 ++++++++++--- viewer/openworlds/screen-table.jsx | 9 ++- viewer/tests/test_cold_open_progress.py | 4 +- viewer/tests/test_live_narration_stream.py | 66 ++++++++++++++++++++++ viewer/tests/test_recovery_timing.py | 24 +++++++- 5 files changed, 128 insertions(+), 15 deletions(-) diff --git a/viewer/openworlds/app.jsx b/viewer/openworlds/app.jsx index 243750ad..276acd09 100644 --- a/viewer/openworlds/app.jsx +++ b/viewer/openworlds/app.jsx @@ -82,18 +82,29 @@ window.neutralizeMarkup = window.neutralizeMarkup || function neutralizeMarkup(r // #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). +// poll sees zero new items for the entire turn then the complete beat). #393 added a live /events +// tail, BUT every shipped DM path persists a turn's narration in ONE batched write at turn-END +// (SKILL.md step 7 → persist_beat) — so the /events stream ALSO surfaces a beat only at turn-end +// today, and notePendingProgress() has nothing to reset on MID-turn. So a wall-clock from submit +// is still the operative lever for later beats, and at 90s it PRE-EMPTED both the legit Act-opening +// (#348) AND a content-rich beat 2–4 that legitimately ran 90–120s (#399 — the playtester's give-up). // • 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. +// • LATER beats: #399 raises the window 90s → 180s to cover the worst-case ~120s turn with +// margin while still recovering a genuine mid-session stall within ~3 min. // 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). +// #399: later-beat stall window raised 90s → 180s. The duo/human/native DM paths ALL persist a +// turn's narration in ONE batched write at turn-END (SKILL.md step 7 → persist_beat), so NOTHING is +// written to the session log mid-turn — meaning the #393 /events stream surfaces a beat only at +// turn-end and notePendingProgress() can't reset this clock DURING the turn. With no mid-turn reset +// to lean on, the 90s window (tuned for the ~35–60s norm) pre-empted a content-rich beat 2–4 that +// legitimately ran 90–120s → a false 'stuck' on a working turn (the give-up the playtester filed). +// 180s covers the worst-case ~120s turn with margin while still recovering a GENUINE mid-session +// stall within ~3 min. (The adaptive reset below is KEPT — it's correct and starts helping the day a +// DM path does log beats incrementally; today it just rarely has anything to reset on mid-turn.) +const PENDING_RECOVERY_MS = 180 * 1000; // #399: later-beat stall window (worst-case DM turns run ~90–120s; was 90s/#342). 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 @@ -215,8 +226,21 @@ function useLiveSession(state) { if (p.stuck) setPendingState((q) => (q ? { ...q, stuck: false } : q)); }, [clearTimers, setPendingState]); + // #399: idempotent player echo. The #344 'Try again' recovery re-POSTs the EXACT stalled move + // (postMove → recordPlayerEcho again), which used to append a SECOND identical action row — the + // duplicated "Rolan—" the playtester saw in the chronicle. Skip the append when the last entry is + // already an identical action (same `who` + same trimmed text) so a retry never doubles the line. + // Only a back-to-back exact repeat is suppressed; a genuine "do X" then "do X again" two turns + // apart is separated by the DM's narration beat between them, so it is NOT deduped. const recordPlayerEcho = React.useCallback((who, text) => { - setLog((l) => [...l, { kind: "action", who, text, at: nextLogSeq() }]); // #274: creation-order stamp + setLog((l) => { + const last = l[l.length - 1]; + if (last && last.kind === "action" && last.who === who + && String(last.text || "").trim() === String(text || "").trim()) { + return l; // identical to the row already showing (a Try-again re-POST) — no duplicate. + } + return [...l, { kind: "action", who, text, at: nextLogSeq() }]; // #274: creation-order stamp + }); }, []); React.useEffect(() => clearTimers, [clearTimers]); diff --git a/viewer/openworlds/screen-table.jsx b/viewer/openworlds/screen-table.jsx index 4130e0b0..9522e999 100644 --- a/viewer/openworlds/screen-table.jsx +++ b/viewer/openworlds/screen-table.jsx @@ -825,8 +825,9 @@ function LogEntry({ entry }) { // #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. +// the #348 false-stuck trap. For the opening we say "a few minutes"; later beats say "a minute or +// two" (the ~35–60s norm, but a content-rich beat 2–4 runs 90–120s — #399). This copy mirrors the +// adaptive recovery window in app.jsx (later-beat window raised 90s → 180s in #399). // #385: the rotating "the world is being made" flavor lines for the COLD-OPEN only. The first beat // legitimately takes minutes (the engine builds the world + sets the scene; no streaming), and the // old single static line ("Setting the opening scene — …") read as FROZEN: it never changed, the @@ -862,7 +863,9 @@ function DmNarratingBeat({ since, firstBeat }) { : "The Dungeon Master is narrating"; const waitHint = firstBeat ? "The first beat of a session can take a few minutes — hang tight, your story is on its way." - : "Weaving the next beat — this can take up to a minute."; + // #399: a content-rich beat can run up to ~two minutes (the window is 180s); say "a minute or + // two" so a 90–120s wait reads as expected, not as the app having stalled. + : "Weaving the next beat — this can take a minute or two."; // #385: a11y model for the cold-open. The frozen-app illusion came from the live region being the // ONLY accessible text AND it never changing (the dots/shimmer/elapsed were all aria-hidden). Fix: // • The visible label + elapsed are NO LONGER aria-hidden for the first beat, so they appear in diff --git a/viewer/tests/test_cold_open_progress.py b/viewer/tests/test_cold_open_progress.py index 2a8e5ce9..4cec97e5 100644 --- a/viewer/tests/test_cold_open_progress.py +++ b/viewer/tests/test_cold_open_progress.py @@ -19,7 +19,9 @@ • the per-second-changing text lives OUTSIDE the aria-live region (a separate visually-hidden role="status" announces a STABLE reassurance ONCE) so a screen reader isn't spammed every tick. -Later beats (the ~35–60s norm) keep the original #336 treatment unchanged. +Later beats keep the original #336 STRUCTURE (steady "narrating" label + aria-hidden ticking +elapsed); #399 only adjusted the later-beat wait-hint wording ("a minute or two") + raised the +recovery window to 180s (a content-rich beat 2–4 runs ~90–120s) — neither is asserted here. These tests exercise the REAL component by transpiling the actual `screen-table.jsx` with the SAME bundled Babel-standalone the browser uses and rendering `DmNarratingBeat` under a tiny diff --git a/viewer/tests/test_live_narration_stream.py b/viewer/tests/test_live_narration_stream.py index 4f4d6dc8..61ff3963 100644 --- a/viewer/tests/test_live_narration_stream.py +++ b/viewer/tests/test_live_narration_stream.py @@ -221,6 +221,12 @@ // arm the "DM is narrating…" indicator exactly as a posted player move does (armPending is on // the hook's returned api). Used to prove a streamed paragraph CLEARS it (the give-up fix). arm: (text) => reactHost.api().armPending(text || 'open the scene'), + // #399: the hook's public player-echo append (the chronicle's optimistic "You: …" row). Idempotent + // so a #344 'Try again' re-POST of the exact stalled move doesn't double the line. + echo: (who, text) => reactHost.api().recordPlayerEcho(who, text), + log: () => (reactHost.api().log || []).map((e) => ({ kind: e.kind, who: e.who, text: e.text })), + // #399: the recovery-window selector by turn position (firstBeat ⇒ cold-open window, else later). + recoveryWindowMs: (firstBeat) => sandbox.window.recoveryWindowMs(firstBeat), drain, }; @@ -404,6 +410,66 @@ def test_new_run_resets_dedup(self): self.assertEqual(out["run2"], ["A familiar refrain."], "a new run must reset the dedup set so identical prose isn't wrongly suppressed across runs") + # --- #399: a resolved DM beat makes the NEXT turn a LATER beat (firstBeat=false) ----------- + # The recovery window is turn-position-aware: the cold-open gets the generous 4-min window, but + # turns 2+ get the (now 180s, #399) later window. This proves the firstBeat flip happens after a + # real beat resolves on /chat — so the later-beat window genuinely governs beats 2–4 (the slow- + # but-working turns the playtester gave up on), NOT the cold-open window. + def test_resolved_beat_makes_next_turn_a_later_beat(self): + out = self._run( + # Turn 1: arm, then resolve it with a turn-END /chat DM line (bumps the internal beat count). + "h.arm('open the scene');" + "h.enqueue('/chat', { items: [{ role: 'dm', text: 'You stand at the gates of Baldur\\u2019s Gate.' }], next: 1 });" + "await h.tick();" + "var afterTurn1 = h.pending();" # JS string; afterTurn1 should be null (turn resolved) + # Turn 2: arm again — this pending must be a LATER beat (firstBeat:false). + "h.arm('walk through the gate');" + "var turn2 = h.pending();" + "return ({ turn1_resolved: afterTurn1 === null, turn2_firstBeat: !!(turn2 && turn2.firstBeat), turn2_active: !!(turn2 && !turn2.stuck) });" + ) + self.assertTrue(out["turn1_resolved"], "the turn-END /chat line should resolve turn 1") + self.assertTrue(out["turn2_active"], "turn 2 should arm a fresh narrating indicator") + self.assertFalse(out["turn2_firstBeat"], + "turn 2 must be a LATER beat (firstBeat=false) → it uses the 180s later-beat window, not the cold-open window") + + # --- #399: the later-beat recovery window is 180s (covers the worst-case ~120s turn) ------- + def test_later_beat_window_is_180s(self): + out = self._run( + "return ({ first: h.recoveryWindowMs(true), later: h.recoveryWindowMs(false) });" + ) + self.assertEqual(out["later"], 180 * 1000, + "the later-beat window must be 180s so a content-rich 90–120s beat 2–4 isn't falsely declared stuck (#399)") + self.assertEqual(out["first"], 4 * 60 * 1000, "the cold-open window is unchanged (4 min)") + + # --- #399: the player echo is IDEMPOTENT (the 'Try again' re-POST doesn't duplicate) ------- + # The #344 stuck-recovery re-POSTs the EXACT stalled move (postMove → recordPlayerEcho again), + # which used to append a SECOND identical action row — the duplicated "Rolan—" the playtester + # filed. A back-to-back identical (who, text) must NOT double the chronicle line. + def test_player_echo_is_idempotent_on_retry(self): + out = self._run( + "await h.drain();" + "h.echo('Rolan', 'Rolan\\u2014 hold the line');" # original submit + "var afterFirst = h.log();" + "h.echo('Rolan', 'Rolan\\u2014 hold the line');" # 'Try again' re-POST (exact same move) + "var afterRetry = h.log();" + "return ({ afterFirst: afterFirst, afterRetry: afterRetry });" + ) + self.assertEqual(len(out["afterFirst"]), 1, "the first submit records one action row") + self.assertEqual(len(out["afterRetry"]), 1, + "a 'Try again' re-POST of the exact same move must NOT duplicate the chronicle action (#399)") + self.assertEqual(out["afterRetry"][0]["text"], "Rolan— hold the line") + + # --- #399: a DIFFERENT action (a rephrase, or a later turn) is NOT deduped ----------------- + def test_player_echo_keeps_distinct_actions(self): + out = self._run( + "await h.drain();" + "h.echo('Rolan', 'hold the line');" + "h.echo('Rolan', 'fall back to the bridge');" # a genuinely different move + "return ({ log: h.log() });" + ) + self.assertEqual(len(out["log"]), 2, + "two distinct actions must both appear (idempotence only suppresses a back-to-back exact repeat)") + if __name__ == "__main__": unittest.main() diff --git a/viewer/tests/test_recovery_timing.py b/viewer/tests/test_recovery_timing.py index 508017b8..29a91634 100644 --- a/viewer/tests/test_recovery_timing.py +++ b/viewer/tests/test_recovery_timing.py @@ -204,8 +204,8 @@ def test_constants_exported_and_ordered(self): # and still strictly inside the hard backstop. This is the whole shape of the #348 fix. self.assertLess(c["recoveryMs"], c["recoveryFirstMs"]) self.assertLess(c["recoveryFirstMs"], c["backstopMs"]) - # Concretely: later = 90s, first = 4 min, backstop = 12 min. - self.assertEqual(c["recoveryMs"], 90 * 1000) + # Concretely: later = 180s (#399, was 90s), first = 4 min, backstop = 12 min. + self.assertEqual(c["recoveryMs"], 180 * 1000) self.assertEqual(c["recoveryFirstMs"], 4 * 60 * 1000) self.assertEqual(c["backstopMs"], 12 * 60 * 1000) @@ -213,7 +213,25 @@ def test_constants_exported_and_ordered(self): def test_recovery_window_selector_both_branches(self): out = self._run("({ first: h.recoveryWindowMs(true), later: h.recoveryWindowMs(false) })") self.assertEqual(out["first"], 4 * 60 * 1000) - self.assertEqual(out["later"], 90 * 1000) + self.assertEqual(out["later"], 180 * 1000) # #399: was 90s + + # --- #399 CORE: the FIRST-beat window covers a 120s turn without going stuck -------------- + # The first beat already gets the generous 4-min window, so a 120s turn is comfortably inside it. + # (The LATER-beat 180s window can't be exercised in THIS harness — flipping firstBeat=false needs + # a real DM beat to arrive via the /chat poll, which is stubbed here; that path is covered in + # test_live_narration_stream.py::test_resolved_beat_makes_next_turn_a_later_beat. Here we lock + # that NEITHER window trips at 120s, the worst-case content-rich turn the playtester gave up on.) + def test_no_false_stuck_at_120s(self): + out = self._run( + "h.arm('open the scene');" + # 120s in — the OLD later-beat window (90s) would already be 'stuck'. The first-beat + # window (and the new 180s later window) must NOT be. + "h.advance(120 * 1000);" + "var p1 = h.pending();" + "({ stuck_at_120s: !!(p1 && p1.stuck), active_at_120s: !!(p1 && !p1.stuck) })" + ) + self.assertFalse(out["stuck_at_120s"], "a 120s turn must not be falsely declared stuck (#399)") + self.assertTrue(out["active_at_120s"], "a 120s turn should still be narrating (pending, not stuck)") # --- #348 CORE: the FIRST beat is NOT falsely declared stuck at 90s ------- def test_first_beat_survives_past_the_old_90s_threshold(self):