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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0136VBTMUKWYeU6G9HgbDbND
This commit is contained in:
co-authored by
Claude Opus 5
parent
fec46f66bb
commit
f8d401029f
+40
-15
@@ -539,7 +539,6 @@ async def retrieve_memories(
|
|||||||
adventure: models.Adventure,
|
adventure: models.Adventure,
|
||||||
settings: models.Settings,
|
settings: models.Settings,
|
||||||
*,
|
*,
|
||||||
update_stats: bool,
|
|
||||||
exclude_action_id: int | None = None,
|
exclude_action_id: int | None = None,
|
||||||
) -> dict | None:
|
) -> dict | None:
|
||||||
"""Returns the memories to inject, or None when the bank is off.
|
"""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
|
`{"used": [{id, text, similarity, pinned}], "error": str | None}`. It is
|
||||||
None when the memory bank is disabled for this adventure.
|
None when the memory bank is disabled for this adventure.
|
||||||
|
|
||||||
Set `update_stats` to True to increment the use counters. Only real turns
|
This only reads. A turn counts the memories it used with `record_use`, just
|
||||||
should do this, not the dry runs that Insights performs.
|
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
|
`exclude_action_id` removes the action being retried from the similarity
|
||||||
query, so that a discarded attempt cannot influence which memories are
|
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()}
|
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 {
|
return {
|
||||||
"used": [
|
"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 ----------
|
# ---------- Post-turn background work ----------
|
||||||
|
|
||||||
def schedule_post_turn(adventure: models.Adventure) -> None:
|
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
|
# 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.
|
# may not do is vanish. Re-raising would only feed an unobserved task.
|
||||||
try:
|
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)
|
derived.failed(db, adventure_id, derived.MEMORY, exc)
|
||||||
db.commit()
|
db.commit()
|
||||||
except BaseException: # noqa: BLE001 - the recorder must not mask it
|
except BaseException: # noqa: BLE001 - the recorder must not mask it
|
||||||
|
|||||||
@@ -25,7 +25,7 @@ async def dry_run_context(
|
|||||||
):
|
):
|
||||||
"""Returns what the app would send to the AI if the player continued now."""
|
"""Returns what the app would send to the AI if the player continued now."""
|
||||||
settings = get_settings(db, user)
|
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
|
# 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,
|
# that skipped the library would show a prompt the next turn will not send,
|
||||||
# which is the one thing this panel must never do.
|
# which is the one thing this panel must never do.
|
||||||
|
|||||||
@@ -193,8 +193,12 @@ async def _generate_turn(
|
|||||||
# context. Otherwise the model reads the attempt it is replacing as
|
# context. Otherwise the model reads the attempt it is replacing as
|
||||||
# established story and writes a sequel to it.
|
# established story and writes a sequel to it.
|
||||||
replacing_id = retry_of.id if retry_of is not None else None
|
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(
|
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
|
# M7: the imported library, retrieved for the position being read. Excluding
|
||||||
# the attempt being replaced matters here for the same reason it does for
|
# 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),
|
"summary": narrative.apply.diff(before_state, new_state),
|
||||||
}
|
}
|
||||||
attempts.snapshot_outcome(adventure, ai_action)
|
attempts.snapshot_outcome(adventure, ai_action)
|
||||||
|
memorybank.record_use(db, memories)
|
||||||
adventure.updated_at = models.utcnow()
|
adventure.updated_at = models.utcnow()
|
||||||
db.commit()
|
db.commit()
|
||||||
db.refresh(ai_action)
|
db.refresh(ai_action)
|
||||||
|
|||||||
@@ -18,6 +18,7 @@ Two things are asserted throughout rather than assumed:
|
|||||||
"""
|
"""
|
||||||
|
|
||||||
import asyncio
|
import asyncio
|
||||||
|
import sqlite3
|
||||||
|
|
||||||
import pytest
|
import pytest
|
||||||
from fastapi import Depends
|
from fastapi import Depends
|
||||||
@@ -26,12 +27,14 @@ from sqlalchemy import select
|
|||||||
|
|
||||||
from app import auth, derived, limits, memorybank, models, summaries
|
from app import auth, derived, limits, memorybank, models, summaries
|
||||||
from app.context import builder, lineage
|
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.main import app
|
||||||
from app.providers import ProviderError
|
from app.providers import ProviderError
|
||||||
from app.routers import adventures
|
from app.routers import adventures
|
||||||
|
|
||||||
from fakes import ScriptedProvider, state_block
|
from fakes import ScriptedProvider, state_block
|
||||||
|
from tools import m11_long_run
|
||||||
|
|
||||||
|
|
||||||
class StubEmbedder:
|
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
|
assert old[0]["eligible"] is False
|
||||||
finally:
|
finally:
|
||||||
mb.summary_provider, mb.embedding_provider = real_summary, real_embed
|
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()}
|
||||||
|
|||||||
@@ -138,7 +138,7 @@ def test_retrieval_uses_no_stale_vector_after_the_switch(client, monkeypatch):
|
|||||||
adventure = db.get(models.Adventure, client.adv_id)
|
adventure = db.get(models.Adventure, client.adv_id)
|
||||||
settings = db.query(models.Settings).first()
|
settings = db.query(models.Settings).first()
|
||||||
result = asyncio.run(
|
result = asyncio.run(
|
||||||
memorybank.retrieve_memories(adventure, settings, update_stats=False)
|
memorybank.retrieve_memories(adventure, settings)
|
||||||
)
|
)
|
||||||
assert result["used"] == []
|
assert result["used"] == []
|
||||||
finally:
|
finally:
|
||||||
|
|||||||
@@ -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
|
that is what the run itself proves, and `memories_in_bank` in its timeline is
|
||||||
where it shows.
|
where it shows.
|
||||||
"""
|
"""
|
||||||
|
import json
|
||||||
|
|
||||||
import pytest
|
import pytest
|
||||||
from fastapi import Depends
|
from fastapi import Depends
|
||||||
from fastapi.testclient import TestClient
|
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 = run_for(Down())
|
||||||
run.adv = 7
|
run.adv = 7
|
||||||
assert run.bank_size() == -1
|
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
|
||||||
|
|||||||
@@ -196,7 +196,7 @@ def restore_embedding_provider():
|
|||||||
def retrieved(adventure, settings) -> set[str]:
|
def retrieved(adventure, settings) -> set[str]:
|
||||||
memorybank.embedding_provider = lambda s: StubEmbedder()
|
memorybank.embedding_provider = lambda s: StubEmbedder()
|
||||||
result = asyncio.run(
|
result = asyncio.run(
|
||||||
memorybank.retrieve_memories(adventure, settings, update_stats=False)
|
memorybank.retrieve_memories(adventure, settings)
|
||||||
)
|
)
|
||||||
assert result["error"] is None, result["error"]
|
assert result["error"] is None, result["error"]
|
||||||
return {m["text"] for m in result["used"]}
|
return {m["text"] for m in result["used"]}
|
||||||
|
|||||||
@@ -121,7 +121,6 @@ def bank(db, adventure):
|
|||||||
|
|
||||||
def retrieve(adventure, settings, embedder, **kwargs):
|
def retrieve(adventure, settings, embedder, **kwargs):
|
||||||
memorybank.embedding_provider = lambda s: embedder
|
memorybank.embedding_provider = lambda s: embedder
|
||||||
kwargs.setdefault("update_stats", False)
|
|
||||||
return asyncio.run(memorybank.retrieve_memories(adventure, settings, **kwargs))
|
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"]
|
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
|
settings.memory_top_k = 1
|
||||||
db.commit()
|
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.commit()
|
||||||
db.expire_all()
|
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):
|
def test_dry_runs_do_not_bump_the_counters(db, adventure, settings, bank):
|
||||||
"""Insights assembles a context without spending a turn. It must not
|
"""Insights assembles a context without spending a turn. It must not
|
||||||
look like the memories were used."""
|
look like the memories were used."""
|
||||||
retrieve(adventure, settings, StubEmbedder(), update_stats=False)
|
retrieve(adventure, settings, StubEmbedder())
|
||||||
db.commit()
|
db.commit()
|
||||||
db.expire_all()
|
db.expire_all()
|
||||||
assert all(db.get(models.Memory, m.id).use_count == 0 for m in bank.values())
|
assert all(db.get(models.Memory, m.id).use_count == 0 for m in bank.values())
|
||||||
|
|||||||
+170
-13
@@ -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
|
many memories and summaries exist so that "the bank stayed empty" is a number in
|
||||||
the evidence rather than an absence nobody looked for.
|
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
|
## What it records
|
||||||
|
|
||||||
A JSON line per turn (`timeline.jsonl`) carrying the context measurements M03
|
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.
|
#: Operational state, not evidence. Its presence means an unfinished run.
|
||||||
RESUME_FILE = "resume.json"
|
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
|
#: The planted clue. Distinctive enough that its presence anywhere is
|
||||||
#: unambiguous, and phrased as something a story would actually establish.
|
#: unambiguous, and phrased as something a story would actually establish.
|
||||||
CLUE = "the silver key opens the crypt beneath the Old Abbey"
|
CLUE = "the silver key opens the crypt beneath the Old Abbey"
|
||||||
@@ -318,6 +358,9 @@ class Run:
|
|||||||
self.resumed = False
|
self.resumed = False
|
||||||
self.elapsed_before = 0.0
|
self.elapsed_before = 0.0
|
||||||
self.session_started = time.monotonic()
|
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
|
# ------------------------------------------------------------ recording
|
||||||
|
|
||||||
@@ -344,6 +387,7 @@ class Run:
|
|||||||
"server_starts": self.server.starts,
|
"server_starts": self.server.starts,
|
||||||
"elapsed_seconds": self.elapsed(),
|
"elapsed_seconds": self.elapsed(),
|
||||||
"turns_target": self.turns_target,
|
"turns_target": self.turns_target,
|
||||||
|
"log_offset": self.log_offset,
|
||||||
"written": datetime.now().isoformat(timespec="seconds"),
|
"written": datetime.now().isoformat(timespec="seconds"),
|
||||||
}
|
}
|
||||||
tmp = self.out / (RESUME_FILE + ".tmp")
|
tmp = self.out / (RESUME_FILE + ".tmp")
|
||||||
@@ -363,6 +407,7 @@ class Run:
|
|||||||
self.beat = prior.get("beat", 0)
|
self.beat = prior.get("beat", 0)
|
||||||
self.completed_steps = set(prior.get("completed_steps") or [])
|
self.completed_steps = set(prior.get("completed_steps") or [])
|
||||||
self.elapsed_before = prior.get("elapsed_seconds", 0)
|
self.elapsed_before = prior.get("elapsed_seconds", 0)
|
||||||
|
self.log_offset = prior.get("log_offset", 0)
|
||||||
self.resumed = True
|
self.resumed = True
|
||||||
|
|
||||||
def reattach(self) -> None:
|
def reattach(self) -> None:
|
||||||
@@ -542,12 +587,12 @@ class Run:
|
|||||||
"output_reserve": tokens["output_reserve"],
|
"output_reserve": tokens["output_reserve"],
|
||||||
"protected": tokens["protected"],
|
"protected": tokens["protected"],
|
||||||
"available_for_history": tokens["available_for_history"],
|
"available_for_history": tokens["available_for_history"],
|
||||||
"summary_tokens": sections.get("story_summary", 0),
|
"summary_tokens": sections.get(SUMMARY_LABEL, 0),
|
||||||
"memory_tokens": sections.get("memories", 0),
|
"memory_tokens": sections.get(MEMORIES_LABEL, 0),
|
||||||
"knowledge_tokens": sum(
|
"knowledge_tokens": sum(
|
||||||
v for k, v in sections.items() if k.startswith("knowledge")),
|
sections.get(label, 0) for label in IMPORTED_KNOWLEDGE_LABELS),
|
||||||
"state_tokens": sections.get("narrative_state", 0),
|
"state_tokens": sections.get(STATE_LABEL, 0),
|
||||||
"canon_tokens": sections.get("campaign_canon", 0),
|
"canon_tokens": sections.get(CANON_LABEL, 0),
|
||||||
"window_verified": window.get("verified"),
|
"window_verified": window.get("verified"),
|
||||||
"window_tokens": window.get("tokens"),
|
"window_tokens": window.get("tokens"),
|
||||||
# Whether the *planted clue* is still visible anywhere in the
|
# Whether the *planted clue* is still visible anywhere in the
|
||||||
@@ -569,6 +614,66 @@ class Run:
|
|||||||
except Exception: # noqa: BLE001
|
except Exception: # noqa: BLE001
|
||||||
return -1
|
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:
|
def state(self) -> dict:
|
||||||
return self.server.call("GET", f"/adventures/{self.adv}/state")
|
return self.server.call("GET", f"/adventures/{self.adv}/state")
|
||||||
|
|
||||||
@@ -693,6 +798,21 @@ def main() -> int:
|
|||||||
accepted_turns=run.accepted)
|
accepted_turns=run.accepted)
|
||||||
run.save_resume()
|
run.save_resume()
|
||||||
break
|
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()
|
run.save_resume()
|
||||||
|
|
||||||
# ---- M04: the recall check, with controls. ----
|
# ---- M04: the recall check, with controls. ----
|
||||||
@@ -716,9 +836,29 @@ def main() -> int:
|
|||||||
except Exception as exc: # noqa: BLE001
|
except Exception as exc: # noqa: BLE001
|
||||||
run.note("export_failed", error=f"{type(exc).__name__}: {exc}"[:300])
|
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 = {
|
summary = {
|
||||||
"status": "aborted" if aborted else "complete",
|
"status": ("aborted" if aborted
|
||||||
|
else "failed" if failed_reason else "complete"),
|
||||||
"aborted_reason": aborted,
|
"aborted_reason": aborted,
|
||||||
|
"failed_reason": failed_reason,
|
||||||
|
"summaries": _or_none(run.summary_count),
|
||||||
"accepted_turns": run.accepted,
|
"accepted_turns": run.accepted,
|
||||||
"turns_requested": args.turns,
|
"turns_requested": args.turns,
|
||||||
"restarts": server.starts - 1,
|
"restarts": server.starts - 1,
|
||||||
@@ -742,13 +882,30 @@ def main() -> int:
|
|||||||
# A finished run has nothing to resume, and the file's absence is
|
# A finished run has nothing to resume, and the file's absence is
|
||||||
# what lets a later run use this directory.
|
# what lets a later run use this directory.
|
||||||
resume_path.unlink(missing_ok=True)
|
resume_path.unlink(missing_ok=True)
|
||||||
return 0
|
return 1 if failed_reason else 0
|
||||||
return 1
|
return 1
|
||||||
finally:
|
finally:
|
||||||
server.stop()
|
server.stop()
|
||||||
run.timeline.close()
|
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):
|
def _or_none(read):
|
||||||
"""A summary field worth having when it can be read, and worth skipping when
|
"""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."""
|
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.)
|
# 1. Is the clue outside the recent-history window? (Precondition, not result.)
|
||||||
report = server.call("GET", f"/adventures/{adv}/context")
|
report = server.call("GET", f"/adventures/{adv}/context")
|
||||||
history_text = " ".join(
|
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
|
in_history = CLUE_SENTINEL in history_text
|
||||||
|
|
||||||
# 2. Ask about the subject, and see what the application assembles.
|
# 2. Ask about the subject, and see what the application assembles.
|
||||||
@@ -973,12 +1130,12 @@ def _recall(run: Run) -> dict:
|
|||||||
return {
|
return {
|
||||||
"clue_in_recent_history_window": in_history,
|
"clue_in_recent_history_window": in_history,
|
||||||
"clue_in_prompt": CLUE_SENTINEL in whole_prompt,
|
"clue_in_prompt": CLUE_SENTINEL in whole_prompt,
|
||||||
"in_state_section": CLUE_SENTINEL in sections.get("narrative_state", ""),
|
"in_state_section": CLUE_SENTINEL in sections.get(STATE_LABEL, ""),
|
||||||
"in_summary_section": CLUE_SENTINEL in sections.get("story_summary", ""),
|
"in_summary_section": CLUE_SENTINEL in sections.get(SUMMARY_LABEL, ""),
|
||||||
"in_memories_section": CLUE_SENTINEL in sections.get("memories", ""),
|
"in_memories_section": CLUE_SENTINEL in sections.get(MEMORIES_LABEL, ""),
|
||||||
"in_knowledge_sections": any(
|
"in_knowledge_sections": any(
|
||||||
CLUE_SENTINEL in text for label, text in sections.items()
|
CLUE_SENTINEL in sections.get(label, "")
|
||||||
if label.startswith("knowledge")),
|
for label in IMPORTED_KNOWLEDGE_LABELS),
|
||||||
"fact_still_in_state": fact_present,
|
"fact_still_in_state": fact_present,
|
||||||
"history_included": after["history"]["included"],
|
"history_included": after["history"]["included"],
|
||||||
"history_total": after["history"]["total"],
|
"history_total": after["history"]["total"],
|
||||||
|
|||||||
Reference in New Issue
Block a user