From f8d401029f12c4a9205c5a0cb90083ce79da74b3 Mon Sep 17 00:00:00 2001 From: JesseMarkowitz Date: Sun, 13 Sep 2026 20:21:21 -0400 Subject: [PATCH] Stop a turn locking out its own memory bank, and let the long run notice The first M01 trial with the memory bank on was 26 turns on a GPU host. It accepted every turn and reported "complete". It also wrote two memories and no summary, and logged 180 `database is locked` errors, while derived status still read `idle`. The cause was a single uncommitted UPDATE. Retrieval bumped each used memory's counter before the model call, and the turn commits only after the reply has streamed. SQLite has one writer, so the turn held the write lock for the whole reply. Every post-turn memory, summary and status write in that window waited out the five-second timeout and failed. Recording the failure needed a write as well, and without a rollback first it raised PendingRollbackError. The loss therefore reached the log and never reached the status the Insights panel reads, which F08 forbids. The draco run never hit this because the bank was off there. - `retrieve_memories` now only reads. `record_use` writes the counters in the turn's single commit, so a turn that never lands counts nothing. - The post-turn task's outer handler rolls back before it records a failure. The harness could not have caught any of this. It read three prompt sections under names the builder does not use: `memories` (really `used_memories`), `story_history` (really `history`/`recent_history`), and a `knowledge` prefix that matched the fixed instruction section instead of the imported passages. Memory tokens read 0 whatever the prompt held, and the in-history and in-memories recall checks could never come out true. The labels are now constants, pinned by a test against a prompt the real builder assembled. The harness also stops at the first sign of failed post-turn work. It checks /derived and new server.log lines after every turn, keeps its log position across --resume, and waits for background work to settle before its final checks. A run with no memories or no summaries now ends "failed", not "complete". Both new application tests fail on fec46f6: the lock probe sees `database is locked`, and memory status stays `idle`. The full backend suite passes (1392 passed, 17 skipped). A 26-turn re-run against the same host had 0 lock errors, wrote 7 memories and 2 summaries, and used them in the prompt from turn 8. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_0136VBTMUKWYeU6G9HgbDbND --- backend/app/memorybank.py | 55 ++++-- backend/app/routers/adventures/insights.py | 2 +- backend/app/routers/adventures/turns.py | 7 +- backend/tests/test_context_memory.py | 122 ++++++++++++- backend/tests/test_embedding_model_switch.py | 2 +- backend/tests/test_m11_long_run_memory.py | 87 +++++++++ backend/tests/test_memory_nodes.py | 2 +- backend/tests/test_memory_retrieval.py | 8 +- backend/tools/m11_long_run.py | 183 +++++++++++++++++-- 9 files changed, 431 insertions(+), 37 deletions(-) diff --git a/backend/app/memorybank.py b/backend/app/memorybank.py index 167f5aa..12f3a66 100644 --- a/backend/app/memorybank.py +++ b/backend/app/memorybank.py @@ -539,7 +539,6 @@ async def retrieve_memories( adventure: models.Adventure, settings: models.Settings, *, - update_stats: bool, exclude_action_id: int | None = None, ) -> dict | None: """Returns the memories to inject, or None when the bank is off. @@ -548,8 +547,9 @@ async def retrieve_memories( `{"used": [{id, text, similarity, pinned}], "error": str | None}`. It is None when the memory bank is disabled for this adventure. - Set `update_stats` to True to increment the use counters. Only real turns - should do this, not the dry runs that Insights performs. + This only reads. A turn counts the memories it used with `record_use`, just + before the commit that saves the turn; see that function for why the count + cannot be written here. `exclude_action_id` removes the action being retried from the similarity query, so that a discarded attempt cannot influence which memories are @@ -640,18 +640,6 @@ async def retrieve_memories( } texts = {memory_id: row.text for memory_id, row in detail.items()} - if update_stats: - # Pass `synchronize_session=False` because nothing in this request - # reads the counters back. Matching the UPDATE against loaded objects - # would require loading those objects, which is the cost this code path - # exists to avoid. - db.execute( - update(models.Memory) - .where(models.Memory.id.in_(used_ids)) - .values(use_count=models.Memory.use_count + 1, last_used_at=models.utcnow()) - .execution_options(synchronize_session=False) - ) - return { "used": [ { @@ -681,6 +669,38 @@ async def retrieve_memories( } +def record_use(db: Session, memory_bank: dict | None) -> None: + """Counts the memories a turn was given, as part of that turn's commit. + + Call this immediately before the commit that saves the turn, and never + before the model call. This counter used to be written during retrieval, and + the UPDATE opened a write transaction that stayed open for the whole reply, + because the turn commits only once the narration has streamed. SQLite has + one writer. Every post-turn memory, summary and status write that arrived + during the reply waited out the driver's five-second timeout and failed with + `database is locked`. Recording those failures also needs a write, so it + failed the same way, and derived status kept reporting `idle`. A 26-turn + run on a GPU host wrote two memories and no summary while every turn was + accepted. + + Only real turns count, never Insights' dry runs. A turn that fails before + its commit counts nothing, because nothing was used. + + Pass `synchronize_session=False` because nothing in this request reads the + counters back. Matching the UPDATE against loaded objects would require + loading those objects, which is the cost this code path exists to avoid. + """ + used_ids = [m["id"] for m in (memory_bank or {}).get("used") or []] + if not used_ids: + return + db.execute( + update(models.Memory) + .where(models.Memory.id.in_(used_ids)) + .values(use_count=models.Memory.use_count + 1, last_used_at=models.utcnow()) + .execution_options(synchronize_session=False) + ) + + # ---------- Post-turn background work ---------- def schedule_post_turn(adventure: models.Adventure) -> None: @@ -768,6 +788,11 @@ async def run_post_turn(adventure_id: int) -> None: # setup above, or in eviction. M2's lesson is that the one thing this # may not do is vanish. Re-raising would only feed an unobserved task. try: + # Roll back first. The failure is often a flush or commit that + # failed, which leaves the session unusable until it is rolled + # back, and the record then fails with `PendingRollbackError` + # instead of being written. `_guarded` already does this. + db.rollback() derived.failed(db, adventure_id, derived.MEMORY, exc) db.commit() except BaseException: # noqa: BLE001 - the recorder must not mask it diff --git a/backend/app/routers/adventures/insights.py b/backend/app/routers/adventures/insights.py index 3cc167c..e5ea665 100644 --- a/backend/app/routers/adventures/insights.py +++ b/backend/app/routers/adventures/insights.py @@ -25,7 +25,7 @@ async def dry_run_context( ): """Returns what the app would send to the AI if the player continued now.""" settings = get_settings(db, user) - memories = await memorybank.retrieve_memories(adventure, settings, update_stats=False) + memories = await memorybank.retrieve_memories(adventure, settings) # M7: retrieved here too, and by the same call the turn makes. A dry run # that skipped the library would show a prompt the next turn will not send, # which is the one thing this panel must never do. diff --git a/backend/app/routers/adventures/turns.py b/backend/app/routers/adventures/turns.py index 8ffb7f4..575cc48 100644 --- a/backend/app/routers/adventures/turns.py +++ b/backend/app/routers/adventures/turns.py @@ -193,8 +193,12 @@ async def _generate_turn( # context. Otherwise the model reads the attempt it is replacing as # established story and writes a sequel to it. replacing_id = retry_of.id if retry_of is not None else None + # Retrieval only reads. The use counters are written by `record_use` in + # the turn's single commit below. Writing them here would hold SQLite's + # write lock for the whole model call, and would lock out every post-turn + # write that ran during the reply. memories = await memorybank.retrieve_memories( - adventure, settings, update_stats=True, exclude_action_id=replacing_id + adventure, settings, exclude_action_id=replacing_id ) # M7: the imported library, retrieved for the position being read. Excluding # the attempt being replaced matters here for the same reason it does for @@ -372,6 +376,7 @@ async def _generate_turn( "summary": narrative.apply.diff(before_state, new_state), } attempts.snapshot_outcome(adventure, ai_action) + memorybank.record_use(db, memories) adventure.updated_at = models.utcnow() db.commit() db.refresh(ai_action) diff --git a/backend/tests/test_context_memory.py b/backend/tests/test_context_memory.py index 046c53e..0ec83df 100644 --- a/backend/tests/test_context_memory.py +++ b/backend/tests/test_context_memory.py @@ -18,6 +18,7 @@ Two things are asserted throughout rather than assumed: """ import asyncio +import sqlite3 import pytest from fastapi import Depends @@ -26,12 +27,14 @@ from sqlalchemy import select from app import auth, derived, limits, memorybank, models, summaries from app.context import builder, lineage -from app.database import Base, SessionLocal, engine, get_db +from app.database import DB_PATH, Base, SessionLocal, engine, get_db +from app.knowledge import classes from app.main import app from app.providers import ProviderError from app.routers import adventures from fakes import ScriptedProvider, state_block +from tools import m11_long_run class StubEmbedder: @@ -835,3 +838,120 @@ def test_e03_a_summary_generated_after_divergence_carries_no_abandoned_content(c assert old[0]["eligible"] is False finally: mb.summary_provider, mb.embedding_provider = real_summary, real_embed + + +# ------------------------------------------- M11: post-turn work and the write lock +# +# Found by the first 26-turn M01 trial on a GPU host. Every turn was accepted, +# and the run reported "complete" with two memories, no summary and 180 +# `database is locked` errors. A turn that used a memory wrote its use counter +# before the model call and committed only after the reply. That held SQLite's +# single write lock for the whole reply. Post-turn memory and summary writes +# timed out behind it, and the record of each failure timed out the same way. + + +class LockProbe(ScriptedProvider): + """A narrator that checks, mid-reply, whether any other writer could get in.""" + + seen: list = [] + + async def generate(self, parts, *, temperature, max_tokens): + # Its own connection, as a post-turn task's session would have. The + # short timeout turns "would wait five seconds and fail" into an + # immediate answer. + probe = sqlite3.connect(DB_PATH, timeout=0.1) + try: + probe.execute("BEGIN IMMEDIATE") + probe.rollback() + LockProbe.seen.append("free") + except sqlite3.OperationalError as exc: + LockProbe.seen.append(str(exc)) + finally: + probe.close() + async for item in super().generate(parts, temperature=temperature, + max_tokens=max_tokens): + yield item + + +def test_no_write_lock_is_held_while_the_narrator_is_talking(client, monkeypatch): + play(client, "begin", prose="Aldric sets the key down.") + memory_id = plant_memory(client, "Aldric hid the ledger beneath the third flagstone.") + LockProbe.seen = [] + monkeypatch.setattr(adventures.turns, "OpenAICompatibleProvider", LockProbe) + + play(client, "I lift the flagstone and look for the ledger.") + + with SessionLocal() as db: + # The premise. A turn that retrieved no memory never took the lock, so + # the probe below would pass for the wrong reason. + assert db.get(models.Memory, memory_id).use_count == 1, ( + "the turn did not use the planted memory, so this proves nothing") + assert LockProbe.seen == ["free"], ( + "a write transaction was open during the model call, so every " + f"post-turn write in that window is locked out: {LockProbe.seen}") + + +def test_a_failed_turn_counts_no_memory_as_used(client, monkeypatch): + """The counter is written with the turn now, so a turn that never landed + used nothing.""" + play(client, "begin", prose="Aldric sets the key down.") + memory_id = plant_memory(client, "Aldric hid the ledger beneath the third flagstone.") + ScriptedProvider.replies = [ProviderError("the narrator is gone")] + r = client.post(f"/api/adventures/{client.adv_id}/actions", + json={"type": "do", "text": "I look for the ledger."}) + assert '"error"' in r.text + + with SessionLocal() as db: + assert db.get(models.Memory, memory_id).use_count == 0 + + +def test_a_failure_that_breaks_the_session_is_still_recorded(client, monkeypatch): + """Recording a failure needs a working session. Without a rollback first, + the recorder raised `PendingRollbackError`, the failure went only to the + log, and derived status kept reporting a healthy bank.""" + play(client, "begin", prose="Aldric sets the key down.") + existing = plant_memory(client, "Aldric hid the ledger beneath the third flagstone.") + + def collide(adventure, settings, db): + # A primary key that already exists: the flush fails and leaves the + # session needing a rollback, which is the state a lock timeout on + # commit leaves it in. + db.add(models.Memory(id=existing, adventure_id=client.adv_id, + text="a second row with the same key")) + db.flush() + + monkeypatch.setattr(memorybank, "_evict_over_capacity", collide) + asyncio.run(memorybank.run_post_turn(client.adv_id)) + + with SessionLocal() as db: + rows = {row["kind"]: row for row in derived.report(db, client.adv_id)} + assert rows[derived.MEMORY]["status"] == "failed", rows.get(derived.MEMORY) + assert "PendingRollbackError" not in rows[derived.MEMORY]["detail"] + + +def test_the_long_run_harness_reads_sections_by_their_real_names(client): + """`tools/m11_long_run.py` finds prompt sections by label, and a wrong label + is silent: it measured 0 memory tokens and could never find the clue in + history or in memories. These are the names the real builder uses.""" + with SessionLocal() as db: + adventure = db.get(models.Adventure, client.adv_id) + adventure.authors_note = "Keep the rain in every scene." + db.commit() + play(client, "begin", prose="Aldric sets the key down.", + events=[{"type": "create_entity", "entity": "aldric", + "entity_type": "character", "name": "Aldric"}]) + for step in range(6): + play(client, f"walk on {step}") + plant_memory(client, "Aldric hid the ledger beneath the third flagstone.") + with SessionLocal() as db: + adventure = db.get(models.Adventure, client.adv_id) + summaries.record(db, adventure, "The party reached the Crooked Lantern.") + db.commit() + play(client, "I look for the ledger.") + + labels = {s["label"] for s in context_report(client)["sections"]} + for label in (m11_long_run.MEMORIES_LABEL, m11_long_run.SUMMARY_LABEL, + m11_long_run.STATE_LABEL, *m11_long_run.HISTORY_LABELS): + assert label in labels, f"the harness reads {label!r}; the prompt has {sorted(labels)}" + assert set(m11_long_run.IMPORTED_KNOWLEDGE_LABELS) == { + classes.SECTION_ALWAYS_CANON, *classes.CLASS_SECTIONS.values()} diff --git a/backend/tests/test_embedding_model_switch.py b/backend/tests/test_embedding_model_switch.py index a5a8e75..ac3a06a 100644 --- a/backend/tests/test_embedding_model_switch.py +++ b/backend/tests/test_embedding_model_switch.py @@ -138,7 +138,7 @@ def test_retrieval_uses_no_stale_vector_after_the_switch(client, monkeypatch): adventure = db.get(models.Adventure, client.adv_id) settings = db.query(models.Settings).first() result = asyncio.run( - memorybank.retrieve_memories(adventure, settings, update_stats=False) + memorybank.retrieve_memories(adventure, settings) ) assert result["used"] == [] finally: diff --git a/backend/tests/test_m11_long_run_memory.py b/backend/tests/test_m11_long_run_memory.py index bc2cca7..11de5e5 100644 --- a/backend/tests/test_m11_long_run_memory.py +++ b/backend/tests/test_m11_long_run_memory.py @@ -13,6 +13,8 @@ sending it. What they cannot prove is that a hundred turns then fill the bank that is what the run itself proves, and `memories_in_bank` in its timeline is where it shows. """ +import json + import pytest from fastapi import Depends from fastapi.testclient import TestClient @@ -182,3 +184,88 @@ def test_a_count_that_cannot_be_read_is_minus_one_not_an_exception(run_for): run = run_for(Down()) run.adv = 7 assert run.bank_size() == -1 + + +# ----------------------------------------------- failed post-turn work stops a run + +class Reports: + """A server whose derived status, summaries and log say what the test sets.""" + + starts = 1 + + def __init__(self, log_path, *, status=None, summaries=0, memories=0): + self.log_path = log_path + self.status = status or [] + self.summaries = summaries + self.memories = memories + + def call(self, method, path, payload=None, timeout=600): + if path.endswith("/derived"): + return {"status": self.status, + "failing": [r["kind"] for r in self.status if r["status"] == "failed"], + "summaries": [{"id": i} for i in range(self.summaries)]} + if path.endswith("/memories"): + return [{"id": i} for i in range(self.memories)] + return {} + + +def test_a_failed_pass_in_derived_status_stops_the_run(run_for, tmp_path): + server = Reports(tmp_path / "server.log", status=[ + {"kind": "summary", "status": "failed", "detail": "ProviderError: gone"}, + {"kind": "memory", "status": "idle", "detail": ""}, + ]) + run = run_for(server) + run.adv = 1 + found = run.background_failures() + assert found == ["summary: ProviderError: gone"] + + +def test_a_failure_the_application_could_not_record_is_found_in_the_log_once(run_for, tmp_path): + """The failure that hid the first GPU trial: derived status said `idle` and + the only record was in the server log.""" + log = tmp_path / "server.log" + log.write_text("INFO: 200 OK\nERROR:app.memorybank:could not record derived-work failure for 1\n") + run = run_for(Reports(log)) + run.adv = 1 + + assert len(run.background_failures()) == 1 + assert run.background_failures() == [], "the same line was reported twice" + + with log.open("a") as handle: + handle.write("ERROR:app.derived:derived summary work failed for adventure 1\n") + assert len(run.background_failures()) == 1 + + +def test_healthy_status_and_a_quiet_log_find_nothing(run_for, tmp_path): + log = tmp_path / "server.log" + log.write_text('INFO: "POST /api/adventures/1/actions HTTP/1.1" 200 OK\n') + run = run_for(Reports(log, status=[{"kind": "memory", "status": "ok", "detail": ""}])) + run.adv = 1 + assert run.background_failures() == [] + + +def test_the_log_position_survives_a_resume(run_for, tmp_path): + """Otherwise a resumed run would find the failure that stopped it again, and + stop again, however healthy the application now is.""" + first = run_for(Reports(tmp_path / "server.log")) + first.adv, first.log_offset = 1, 4096 + first.save_resume() + + second = run_for(Reports(tmp_path / "server.log")) + second.adopt(json.loads((tmp_path / lr.RESUME_FILE).read_text())) + assert second.log_offset == 4096 + + +def test_a_run_with_no_summary_or_no_memory_is_not_complete(run_for, tmp_path): + log = tmp_path / "server.log" + assert "summaries=0" in lr._activation_shortfall( + _with_adv(run_for(Reports(log, memories=3, summaries=0)))) + assert "memories_in_bank=0" in lr._activation_shortfall( + _with_adv(run_for(Reports(log, memories=0, summaries=2)))) + assert lr._activation_shortfall( + _with_adv(run_for(Reports(log, memories=3, summaries=1)))) is None + + +def _with_adv(run): + run.adv = 1 + return run diff --git a/backend/tests/test_memory_nodes.py b/backend/tests/test_memory_nodes.py index 2fe3e1d..eebefb8 100644 --- a/backend/tests/test_memory_nodes.py +++ b/backend/tests/test_memory_nodes.py @@ -196,7 +196,7 @@ def restore_embedding_provider(): def retrieved(adventure, settings) -> set[str]: memorybank.embedding_provider = lambda s: StubEmbedder() result = asyncio.run( - memorybank.retrieve_memories(adventure, settings, update_stats=False) + memorybank.retrieve_memories(adventure, settings) ) assert result["error"] is None, result["error"] return {m["text"] for m in result["used"]} diff --git a/backend/tests/test_memory_retrieval.py b/backend/tests/test_memory_retrieval.py index 4b41d2c..60d0ba1 100644 --- a/backend/tests/test_memory_retrieval.py +++ b/backend/tests/test_memory_retrieval.py @@ -121,7 +121,6 @@ def bank(db, adventure): def retrieve(adventure, settings, embedder, **kwargs): memorybank.embedding_provider = lambda s: embedder - kwargs.setdefault("update_stats", False) return asyncio.run(memorybank.retrieve_memories(adventure, settings, **kwargs)) @@ -185,10 +184,11 @@ def test_missing_embedding_model_is_reported(db, adventure, settings, bank): assert result["used"] == [] and "embedding model" in result["error"] -def test_update_stats_bumps_only_the_used(db, adventure, settings, bank): +def test_record_use_bumps_only_the_used(db, adventure, settings, bank): settings.memory_top_k = 1 db.commit() - retrieve(adventure, settings, StubEmbedder((1.0, 0.0, 0.0)), update_stats=True) + used = retrieve(adventure, settings, StubEmbedder((1.0, 0.0, 0.0))) + memorybank.record_use(db, used) db.commit() db.expire_all() @@ -200,7 +200,7 @@ def test_update_stats_bumps_only_the_used(db, adventure, settings, bank): def test_dry_runs_do_not_bump_the_counters(db, adventure, settings, bank): """Insights assembles a context without spending a turn. It must not look like the memories were used.""" - retrieve(adventure, settings, StubEmbedder(), update_stats=False) + retrieve(adventure, settings, StubEmbedder()) db.commit() db.expire_all() assert all(db.get(models.Memory, m.id).use_count == 0 for m in bank.values()) diff --git a/backend/tools/m11_long_run.py b/backend/tools/m11_long_run.py index bf628ac..c43fc2f 100644 --- a/backend/tools/m11_long_run.py +++ b/backend/tools/m11_long_run.py @@ -37,6 +37,17 @@ never asked. `setup` now turns both on and proves it, and `measure` records how many memories and summaries exist so that "the bank stayed empty" is a number in the evidence rather than an absence nobody looked for. +Turning both switches on did not make them work. The first run with them on +was a 26-turn trial on a GPU host. It accepted every turn and reported +"complete" with two memories, no summary and 180 `database is locked` errors in +`server.log`. Two defects hid that result. The application lost its own +post-turn writes and then could not record the loss. The harness read three +prompt sections under names the builder does not use, so it measured 0 memory +tokens whatever was in the prompt. The harness now checks derived status and +`server.log` after every turn and stops at the first sign of failed background +work. A run with no memories or no summaries at the end is reported as +`failed`, not `complete`. + ## What it records A JSON line per turn (`timeline.jsonl`) carrying the context measurements M03 @@ -123,6 +134,35 @@ DEFAULT_MAX_CONSECUTIVE_FAILURES = 5 #: Operational state, not evidence. Its presence means an unfinished run. RESUME_FILE = "resume.json" +#: The prompt sections this harness reads, spelled the way +#: `app/context/builder.py` and `app/knowledge/classes.py` spell them. A wrong +#: label raises no error. `.get` returns 0 and a membership check returns +#: False, so each misspelling becomes a check that can never pass. Three of +#: them did: `memories`, `story_history`, and a `knowledge` prefix that matched +#: the fixed instruction section instead of the retrieved passages. +#: `test_context_memory.py` pins these names against a prompt the real builder +#: assembled. They are copied rather than imported, because importing `app` +#: here would build a database engine in the harness process. +HISTORY_LABELS = ("history", "recent_history") +SUMMARY_LABEL = "story_summary" +MEMORIES_LABEL = "used_memories" +STATE_LABEL = "narrative_state" +CANON_LABEL = "campaign_canon" +IMPORTED_KNOWLEDGE_LABELS = ( + "imported_canon_always", "imported_canon", "imported_reference", + "imported_inspiration", +) + +#: Lines `app/derived.py` and `app/memorybank.py` log when post-turn work fails. +#: The second one means the failure could not be written to derived status at +#: all. Status alone therefore cannot prove the work is healthy: in the first +#: 26-turn GPU trial, 20 failures were logged this way and the status still read +#: `idle`. +LOG_FAILURE_MARKERS = ( + "work failed for adventure", + "could not record derived-work failure", +) + #: The planted clue. Distinctive enough that its presence anywhere is #: unambiguous, and phrased as something a story would actually establish. CLUE = "the silver key opens the crypt beneath the Old Abbey" @@ -318,6 +358,9 @@ class Run: self.resumed = False self.elapsed_before = 0.0 self.session_started = time.monotonic() + #: How far `background_failures` has read `server.log`. Carried across a + #: resume, so a failure is reported once, not again every session. + self.log_offset = 0 # ------------------------------------------------------------ recording @@ -344,6 +387,7 @@ class Run: "server_starts": self.server.starts, "elapsed_seconds": self.elapsed(), "turns_target": self.turns_target, + "log_offset": self.log_offset, "written": datetime.now().isoformat(timespec="seconds"), } tmp = self.out / (RESUME_FILE + ".tmp") @@ -363,6 +407,7 @@ class Run: self.beat = prior.get("beat", 0) self.completed_steps = set(prior.get("completed_steps") or []) self.elapsed_before = prior.get("elapsed_seconds", 0) + self.log_offset = prior.get("log_offset", 0) self.resumed = True def reattach(self) -> None: @@ -542,12 +587,12 @@ class Run: "output_reserve": tokens["output_reserve"], "protected": tokens["protected"], "available_for_history": tokens["available_for_history"], - "summary_tokens": sections.get("story_summary", 0), - "memory_tokens": sections.get("memories", 0), + "summary_tokens": sections.get(SUMMARY_LABEL, 0), + "memory_tokens": sections.get(MEMORIES_LABEL, 0), "knowledge_tokens": sum( - v for k, v in sections.items() if k.startswith("knowledge")), - "state_tokens": sections.get("narrative_state", 0), - "canon_tokens": sections.get("campaign_canon", 0), + sections.get(label, 0) for label in IMPORTED_KNOWLEDGE_LABELS), + "state_tokens": sections.get(STATE_LABEL, 0), + "canon_tokens": sections.get(CANON_LABEL, 0), "window_verified": window.get("verified"), "window_tokens": window.get("tokens"), # Whether the *planted clue* is still visible anywhere in the @@ -569,6 +614,66 @@ class Run: except Exception: # noqa: BLE001 return -1 + def summary_count(self) -> int: + """How many summaries the campaign has written, on any branch. Never + raises, and -1 means unreadable, as for `bank_size`.""" + try: + derived = self.server.call("GET", f"/adventures/{self.adv}/derived") or {} + return len(derived.get("summaries") or []) + except Exception: # noqa: BLE001 + return -1 + + def background_failures(self) -> list[str]: + """Every sign since the last call that post-turn work failed. + + Two sources, because neither is enough alone. Derived status is what the + application says. The server log also catches a failure the application + could not record, which is the failure that made the first GPU trial + report `idle` over 180 `database is locked` errors. Log lines are read + from where the last call stopped, so each failure is reported once. + """ + found: list[str] = [] + try: + derived = self.server.call("GET", f"/adventures/{self.adv}/derived") or {} + for row in derived.get("status") or []: + if row.get("status") == "failed": + found.append(f"{row.get('kind')}: {(row.get('detail') or '')[:200]}") + except Exception as exc: # noqa: BLE001 - an unreadable status is noted, not a failure + self.note("derived_unreadable", error=f"{type(exc).__name__}: {exc}"[:200]) + log = getattr(self.server, "log_path", None) + if log is not None and Path(log).exists(): + with open(log, "rb") as handle: + handle.seek(self.log_offset) + fresh = handle.read() + self.log_offset = handle.tell() + for line in fresh.decode(errors="replace").splitlines(): + if any(marker in line for marker in LOG_FAILURE_MARKERS): + found.append(f"server.log: {line.strip()[:200]}") + return found + + def settle(self, *, quiet_seconds: int = 30, limit_seconds: int = 900) -> None: + """Waits for post-turn work to stop changing derived status. + + Used before the final checks. The last turn's memory and summary passes + run after that turn returns, and a check taken before they finish can + miss their failure or their output. No endpoint reports running work, so + "settled" means derived status unchanged for `quiet_seconds`.""" + deadline = time.monotonic() + limit_seconds + last, since = None, time.monotonic() + while time.monotonic() < deadline: + try: + now = json.dumps(self.server.call( + "GET", f"/adventures/{self.adv}/derived"), sort_keys=True) + except Exception: # noqa: BLE001 + now = None + if now is not None and now == last: + if time.monotonic() - since >= quiet_seconds: + return + else: + last, since = now, time.monotonic() + time.sleep(2) + self.note("settle_timeout", limit_seconds=limit_seconds) + def state(self) -> dict: return self.server.call("GET", f"/adventures/{self.adv}/state") @@ -693,6 +798,21 @@ def main() -> int: accepted_turns=run.accepted) run.save_resume() break + # Checked on every turn, not only at the end. A memory or summary + # pass that fails is lost M01 evidence from that turn onward. A run + # that carries on would report "complete" over a bank that stopped + # filling, which is what the first GPU trial did. + failures = run.background_failures() + if failures: + aborted = ( + f"post-turn memory/summary work failed ({len(failures)} " + "signs, first: " + failures[0] + "). Stopping with the " + "evidence written; see server.log." + ) + run.note("run_aborted", reason=aborted, failures=failures[:20], + accepted_turns=run.accepted) + run.save_resume() + break run.save_resume() # ---- M04: the recall check, with controls. ---- @@ -716,9 +836,29 @@ def main() -> int: except Exception as exc: # noqa: BLE001 run.note("export_failed", error=f"{type(exc).__name__}: {exc}"[:300]) + # Every turn was accepted, but that does not complete M01. Its + # summary/memory clause needs a bank that filled and a summary that was + # written, and the recall turn's own post-turn work has to have + # finished without failing. Otherwise the run is "failed", not + # "complete". + failed_reason = None + if aborted is None: + run.settle() + late = run.background_failures() + if late: + failed_reason = (f"post-turn work failed after the last turn " + f"({len(late)} signs, first: {late[0]})") + else: + failed_reason = _activation_shortfall(run) + if failed_reason: + run.note("run_failed", reason=failed_reason) + summary = { - "status": "aborted" if aborted else "complete", + "status": ("aborted" if aborted + else "failed" if failed_reason else "complete"), "aborted_reason": aborted, + "failed_reason": failed_reason, + "summaries": _or_none(run.summary_count), "accepted_turns": run.accepted, "turns_requested": args.turns, "restarts": server.starts - 1, @@ -742,13 +882,30 @@ def main() -> int: # A finished run has nothing to resume, and the file's absence is # what lets a later run use this directory. resume_path.unlink(missing_ok=True) - return 0 + return 1 if failed_reason else 0 return 1 finally: server.stop() run.timeline.close() +def _activation_shortfall(run) -> str | None: + """Why M01's summary/memory clause was not exercised, or None if it was. + + A count of -1 means the count could not be read. It counts as a shortfall, + because an unreadable bank does not show that the bank filled.""" + memories, summaries = run.bank_size(), run.summary_count() + missing = [] + if memories <= 0: + missing.append(f"memories_in_bank={memories}") + if summaries <= 0: + missing.append(f"summaries={summaries}") + if not missing: + return None + return ("M01's summary/memory clause was not exercised: " + + ", ".join(missing)) + + def _or_none(read): """A summary field worth having when it can be read, and worth skipping when it cannot. An aborted run still reports the fields that do answer.""" @@ -957,7 +1114,7 @@ def _recall(run: Run) -> dict: # 1. Is the clue outside the recent-history window? (Precondition, not result.) report = server.call("GET", f"/adventures/{adv}/context") history_text = " ".join( - s["text"] for s in report["sections"] if s["label"] == "story_history") + s["text"] for s in report["sections"] if s["label"] in HISTORY_LABELS) in_history = CLUE_SENTINEL in history_text # 2. Ask about the subject, and see what the application assembles. @@ -973,12 +1130,12 @@ def _recall(run: Run) -> dict: return { "clue_in_recent_history_window": in_history, "clue_in_prompt": CLUE_SENTINEL in whole_prompt, - "in_state_section": CLUE_SENTINEL in sections.get("narrative_state", ""), - "in_summary_section": CLUE_SENTINEL in sections.get("story_summary", ""), - "in_memories_section": CLUE_SENTINEL in sections.get("memories", ""), + "in_state_section": CLUE_SENTINEL in sections.get(STATE_LABEL, ""), + "in_summary_section": CLUE_SENTINEL in sections.get(SUMMARY_LABEL, ""), + "in_memories_section": CLUE_SENTINEL in sections.get(MEMORIES_LABEL, ""), "in_knowledge_sections": any( - CLUE_SENTINEL in text for label, text in sections.items() - if label.startswith("knowledge")), + CLUE_SENTINEL in sections.get(label, "") + for label in IMPORTED_KNOWLEDGE_LABELS), "fact_still_in_state": fact_present, "history_included": after["history"]["included"], "history_total": after["history"]["total"],