fix(openworlds): slow-but-working DM turn no longer reads as broken (#399) - #400
Merged
Conversation
…399) 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.
📝 WalkthroughWalkthroughThe PR updates the live-session recovery logic for later beats (90s → 180s timeout), makes player echo logging idempotent to prevent duplicate retries, aligns user-facing wait-hint text with the longer content-rich beat timing, and adds comprehensive tests validating recovery window transitions and echo deduplication behavior. ChangesAdaptive Session Recovery and Echo Idempotency
Estimated code review effort🎯 3 (Moderate) | ⏱️ ~22 minutes Possibly related PRs
Poem
🚥 Pre-merge checks | ✅ 3 | ❌ 2❌ Failed checks (2 warnings)
✅ Passed checks (3 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing Touches📝 Generate docstrings
Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 2
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@viewer/openworlds/app.jsx`:
- Around line 235-244: recordPlayerEcho currently dedups by only comparing
against the very last entry in log, which ignores intervening narration stored
in chatBeats and therefore can suppress identical player actions that occur
across a narration beat; update recordPlayerEcho to scope deduping to the most
recent action entry since the last narration (or equivalent turn boundary)
rather than the absolute last log item: locate recordPlayerEcho and inspect
chatBeats/log to find the last narration beat (or maintain a turn/pending
marker), then compare the incoming (who, trimmed text) against the last action
entry after that narration boundary (using nextLogSeq as before) so identical
actions on a later turn are not suppressed; add a unit test that posts an
action, inserts a narration beat into chatBeats, then posts the same action
again and asserts it is appended (or alternatively correct the function comment
if you intentionally want current behavior).
In `@viewer/tests/test_recovery_timing.py`:
- Around line 207-210: Update the module docstring references that still say
"90s" to match the new later-beat constant of 180s: change the phrases
mentioning the snappy PENDING_RECOVERY_MS (~90s) and the LATER-beat branch
(snappy 90s) to 180s so the docstring aligns with the test assertions (see
PENDING_RECOVERY_MS and the assertions for recoveryMs/recoveryFirstMs/backstopMs
in test_recovery_timing.py).
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro Plus
Run ID: 3d2f35cc-d026-4112-8735-d2ecd5c09c17
📒 Files selected for processing (5)
viewer/openworlds/app.jsxviewer/openworlds/screen-table.jsxviewer/tests/test_cold_open_progress.pyviewer/tests/test_live_narration_stream.pyviewer/tests/test_recovery_timing.py
Comment on lines
235
to
244
| 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 | ||
| }); | ||
| }, []); |
There was a problem hiding this comment.
🧩 Analysis chain
🏁 Script executed:
#!/bin/bash
# Description: Check if tests verify that repeated actions separated by DM narration are preserved.
# Search for test assertions involving recordPlayerEcho, log state, and narration
rg -nC5 'recordPlayerEcho|idempotent.*echo' viewer/tests/test_live_narration_stream.py
# Check if tests assert distinct actions are preserved
rg -nC3 'distinct|legitimate.*repeat|separated.*narration' viewer/tests/Repository: electricsheephq/WorldOS
Length of output: 5678
🏁 Script executed:
#!/bin/bash
set -euo pipefail
FILE="viewer/tests/test_live_narration_stream.py"
python3 - <<'PY'
import itertools
path="viewer/tests/test_live_narration_stream.py"
start=430
end=490
with open(path,'r',encoding='utf-8') as f:
for i,line in enumerate(f,1):
if start<=i<=end:
print(f"{i:4d}:{line.rstrip()}")
PYRepository: electricsheephq/WorldOS
Length of output: 3032
🏁 Script executed:
#!/bin/bash
set -euo pipefail
FILE="viewer/tests/test_live_narration_stream.py"
rg -n "later turn|rephrase|different action|keep(s)? distinct|idempotent|Try again|chatBeats|narrat" "$FILE"
# Also locate all tests that call h.echo (player echo)
rg -n "h\.echo\(" "$FILE" | head -n 50Repository: electricsheephq/WorldOS
Length of output: 4531
🏁 Script executed:
#!/bin/bash
set -euo pipefail
FILE="viewer/tests/test_live_narration_stream.py"
python3 - <<'PY'
path="viewer/tests/test_live_narration_stream.py"
for start,end in [(360,430),(370,410),(380,420)]:
print("\n# --- lines",start,"-",end,"---")
with open(path,'r',encoding='utf-8') as f:
for i,line in enumerate(f,1):
if start<=i<=end:
print(f"{i:4d}:{line.rstrip()}")
PYRepository: electricsheephq/WorldOS
Length of output: 10256
🏁 Script executed:
#!/bin/bash
set -euo pipefail
FILE="viewer/tests/test_live_narration_stream.py"
rg -n "h\.echo\(" "$FILE"
# Show a wider context around each h.echo call
rg -n -C8 "h\.echo\(" "$FILE"Repository: electricsheephq/WorldOS
Length of output: 2334
🏁 Script executed:
#!/bin/bash
set -euo pipefail
FILE="viewer/openworlds/app.jsx"
python3 - <<'PY'
path="viewer/openworlds/app.jsx"
# Print the region around the snippet and the nearby comment that mentions narration beats.
for start,end in [(200,270),(270,340)]:
print(f"\n# --- {start}-{end} ---")
with open(path,'r',encoding='utf-8') as f:
for i,line in enumerate(f,1):
if start<=i<=end:
print(f"{i:4d}:{line.rstrip()}")
PYRepository: electricsheephq/WorldOS
Length of output: 9166
🏁 Script executed:
#!/bin/bash
set -euo pipefail
rg -n "recordPlayerEcho|setLog\(" viewer/openworlds/app.jsxRepository: electricsheephq/WorldOS
Length of output: 366
🏁 Script executed:
#!/bin/bash
set -euo pipefail
rg -n "recordPlayerEcho\(" viewer/openworldsRepository: electricsheephq/WorldOS
Length of output: 147
🏁 Script executed:
#!/bin/bash
set -euo pipefail
FILE="viewer/openworlds/screen-table.jsx"
start=360
end=430
python3 - <<PY
path="$FILE"
s=$start;e=$end
with open(path,'r',encoding='utf-8') as f:
for i,line in enumerate(f,1):
if s<=i<=e:
print(f"{i:4d}:{line.rstrip()}")
PYRepository: electricsheephq/WorldOS
Length of output: 3984
🏁 Script executed:
#!/bin/bash
set -euo pipefail
rg -n "setLog\\(" viewer/openworlds/app.jsxRepository: electricsheephq/WorldOS
Length of output: 111
🏁 Script executed:
#!/bin/bash
set -euo pipefail
rg -n "setLog\\(|log\\s*:\\s*\\(|\\.log\\(" viewer/openworlds
rg -n "setLog\\(" viewerRepository: electricsheephq/WorldOS
Length of output: 50381
🏁 Script executed:
#!/bin/bash
set -euo pipefail
FILE="viewer/tests/test_live_narration_stream.py"
python3 - <<'PY'
path="viewer/tests/test_live_narration_stream.py"
start=180
end=260
with open(path,'r',encoding='utf-8') as f:
for i,line in enumerate(f,1):
if start<=i<=end:
print(f"{i:4d}:{line.rstrip()}")
PYRepository: electricsheephq/WorldOS
Length of output: 4664
Dedup for recordPlayerEcho ignores narration beats; identical actions on a later turn can be suppressed.
viewer/openworlds/app.jsxrecordPlayerEchoonly checks the last entry inlog(samewho+ same trimmedtext); DM narration goes tochatBeats, notlog, so narration does not “separate” two identical actions for this dedup.- This contradicts the in-code claim that “two turns apart … is NOT deduped” based on a narration beat between them.
- Existing tests only cover: (1) immediate
Try againexact re-post idempotence and (2) different actions; there’s no test for “same action again on the next turn after narration.”
Suggested fix: either correct the comment to match current behavior, or change the dedup to be scoped to the same retry/pending turn (and add a test for the next-turn-after-narration repeat).
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@viewer/openworlds/app.jsx` around lines 235 - 244, recordPlayerEcho currently
dedups by only comparing against the very last entry in log, which ignores
intervening narration stored in chatBeats and therefore can suppress identical
player actions that occur across a narration beat; update recordPlayerEcho to
scope deduping to the most recent action entry since the last narration (or
equivalent turn boundary) rather than the absolute last log item: locate
recordPlayerEcho and inspect chatBeats/log to find the last narration beat (or
maintain a turn/pending marker), then compare the incoming (who, trimmed text)
against the last action entry after that narration boundary (using nextLogSeq as
before) so identical actions on a later turn are not suppressed; add a unit test
that posts an action, inserts a narration beat into chatBeats, then posts the
same action again and asserts it is appended (or alternatively correct the
function comment if you intentionally want current behavior).
Comment on lines
+207
to
210
| # 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) |
There was a problem hiding this comment.
Module docstring still documents the old 90s later-beat window.
The constant is now asserted at 180s here, but the docstring (Line 13: "the snappy PENDING_RECOVERY_MS (~90s)" and Line 24: "the LATER-beat branch (snappy 90s)") still says 90s, contradicting these assertions in the same file. Refresh both lines to 180s for consistency with #399.
📝 Suggested docstring updates (outside the changed range)
- • LATER beats (the ~35–60s norm): the snappy PENDING_RECOVERY_MS (~90s).
+ • LATER beats (the ~35–60s norm, but content-rich beats can run ~90–120s):
+ PENDING_RECOVERY_MS (~180s, `#399`; was 90s).- • the LATER-beat branch (snappy 90s) — preserved for a genuine mid-session stall;
+ • the LATER-beat branch (180s, `#399`) — preserved for a genuine mid-session stall;🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@viewer/tests/test_recovery_timing.py` around lines 207 - 210, Update the
module docstring references that still say "90s" to match the new later-beat
constant of 180s: change the phrases mentioning the snappy PENDING_RECOVERY_MS
(~90s) and the LATER-beat branch (snappy 90s) to 180s so the docstring aligns
with the test assertions (see PENDING_RECOVERY_MS and the assertions for
recoveryMs/recoveryFirstMs/backstopMs in test_recovery_timing.py).
This was referenced May 30, 2026
Merged
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The bug
A full-arc playtest abandoned the session on beats 2–4: the DM backend completed the turn (runbooks fired, the in-game clock advanced — proven by the backend log) but the turn ran longer than the viewer's 90s "stuck" window. The player saw "The Dungeon Master seems stuck — No reply came back in time", the action bar re-opened with Try Again, and clicking it duplicated the player's action in the chronicle. Two MAJOR timeout bugs + one MINOR duplication bug — the single blocker preventing a fresh player from finishing an 8-beat session.
Root cause (verified against the engine + DM skill, not just the static viewer code)
useLiveSession(app.jsx) already had, from #393, a live/eventsnarration stream and an adaptive stall-clock reset (notePendingProgress) that on paper means a long-but-streaming turn never tripsstuck. So fixes "raise the timeout adaptively" and "stream on turns 2+" looked already-done.But the streaming is inert on every shipped DM path. The DM beat cycle (
skills/dungeon-master/SKILL.mdstep 7) prescribes: write the player-facing prose FIRST, then persist the whole beat in ONEpersist_beatcall LAST (a latency optimization —servers/engine/server.py:persist_beatbatcheslog_event+remember+decision+advanceinto a single atomic write). The duo/human/native runners all go through this. So nothing is written tosessions/<sid>.jsonlmid-turn →/eventssurfaces a beat only at turn-END (same instant as the/chatturn-end line) →notePendingProgress()never fires during the turn → later beats run under the cold 90s wall-clock with no resets. The 90s was tuned for the~35–60snorm; a content-rich beat 2–4 runs90–120sand trips it on a working turn.The viewer streaming logic itself is correct for turns 2+ (the
/eventscursor +dmBeatCountRefreset per-run, not per-turn, so later turns keep tailing). It simply has nothing to stream today. So the honest fix is to size the wall-clock window for the real worst case and stop the retry from duplicating the action — both viewer-only.Changes (viewer-only — no Swift rebuild; engine sole-writer + wire contracts untouched)
stuckwindow 90s → 180s (PENDING_RECOVERY_MS, app.jsx) so a worst-case~120sturn completes without a falsestuck. First-beat window (4 min) + 12-min hard backstop unchanged.notePendingProgress()reset is kept (it's correct, and starts helping the day a DM path logs beats incrementally).recordPlayerEcho, app.jsx): the [playtest][P1] VALIDATE #343 completeness — veteran hit dead 'Try again' button + Table nav still blocked from Map/Journal #344 "Try again" re-POSTs the exact stalled move, which used to append a second identical chronicle action — the duplicated entry the playtester saw. Now a back-to-back identical(who, text)is suppressed; distinct moves (a rephrase, or a later turn separated by DM narration) are preserved.DmNarratingBeatalready shows a live ticking elapsed counter (0:07 → 0:42, updates every 1s) + a polite aria-live status — not a dead spinner.On streaming (task fix #2 — being explicit)
The live
/eventsstream is wired and verified correct on turns 2+ viewer-side (new test below). The reason it doesn't currently make a 120s turn visibly fill in is upstream: the DM persists its narration in one batched write at turn-end. Making the DM stream per-beat would mean splittingpersist_beat(log narration before the heavy persist) + adjustingSKILL.md— a backend/skill change, out of this viewer-only PR's scope. Flagged as an open item. The 180s window is the real protection until then.Verification
Real-JSX harness tests (
viewer/tests/, transpile the actual.jsxwith the bundled Babel-standalone + a deterministic React/clock/fetch stub — they track shipped behavior, not a reimplementation), run single-process:test_recovery_timing.py— later window now 180s; no falsestuckat 120s; first-beat + backstop + clearPending contracts preserved. (7/7)test_live_narration_stream.py— a resolved beat flips the next turn to a LATER beat (so the 180s window genuinely governs turns 2+, not the cold-open window); later window == 180s; player echo idempotent on a Try-again re-POST; distinct actions preserved; all [playtest][P0] Per-beat DM latency (~60-90s) with no streaming → impatient players give up mid-session #393 streaming/dedup behavior intact. (14/14, 4 new)test_cold_open_progress.py— stale later-beat comment refreshed; later-beat structure assertions unchanged. (6/6)Local full viewer suite: 195/196 pass. The 1 failure (
test_portrait_gen::test_null_default_returns_placeholder_no_network) is a pre-existing ambient-env issue — it spawns a bare-python3subprocess that needspydantic(present underuv, absent in ambient python); unrelated to this change (my diff touches only app.jsx + screen-table.jsx + 3 test files).python3 scripts/license_check.pygreen. Both JSX files transpile clean.Do NOT close on merge — verify on the next full-arc playtest.
Summary by CodeRabbit
Release Notes
Bug Fixes
Documentation
Tests