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"],