The call record: every model call, for the operator's study (M6.6a)

nisse-core records each model call of every agent into a file beside its
state store (<state>.calls.db), for the status page (L7, X6):

- the request body exactly as sent (never headers), the raw response with
  its reasoning, the model asked and the one that answered, time, tokens
  and llama-server's own prompt reuse (timings.cache_n);
- its work item, role, run and purpose: Driver.run and nisse-dev's
  delegation loop open runs, nested; compaction, expert consults, the
  classifier and the go-ahead reader label their calls;
- provenance, worked out in BudgetedClient by comparing the events at
  each stage: each event sent with its log id and content as sent, which
  a compaction replaced, which fitting shortened (by how much) and
  dropped.

Content is stored once by hash, compressed. It is diagnostic only: the
agent never reads it, a failed write is logged once and recording stops
while the call goes on, and the file is deleted when the agent starts,
so its layout never migrates; CallReader refuses a layout it doesn't
know. While recording, the system prompt ends with one sentence saying
so. `call_record: false` in either agent's YAML turns it off.

The benchmark records each run beside that run's own state store, and
`--keep-runs DIR` keeps both for the page.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01J5Utyfzw7gF7UhjRDEtjTk

nisse-core/tests/test_calls.py

@@ -0,0 +1,376 @@
+"""The call record (architecture L7): every model call, as sent and answered,
+with where its request came from, for the operator's study."""
+
+import io
+import json
+import sqlite3
+import zlib
+from pathlib import Path
+from typing import Any
+
+import httpx
+import pytest
+
+from nisse_core.log.canonical import (
+    AssistantText,
+    CanonicalEvent,
+    Compaction,
+    StoredEvent,
+    ToolCall,
+    ToolResult,
+    UserMessage,
+)
+from nisse_core.loop.driver import Driver
+from nisse_core.loop.tools import tool
+from nisse_core.models import calls
+from nisse_core.models.context import BudgetedClient, ContextOverflow
+from nisse_core.models.llm import LiteLLMClient, LLMError
+from nisse_core.oplog import OpLog
+from nisse_core.state.store import StateStore
+
+TOKEN = "sk-secret-litellm-token"
+FINISH = tool("finish", "finish the work", summary="what was done")
+
+
+def stored(events: list[CanonicalEvent], start: int = 1) -> list[StoredEvent]:
+    return [
+        StoredEvent(id=start + i, ts="t", event=e, work_item="w", actor="driver")
+        for i, e in enumerate(events)
+    ]
+
+
+def reply(
+    content: str = "",
+    *,
+    tool_call: str | None = None,
+    reasoning: str = "",
+    timings: dict[str, int] | None = None,
+) -> dict[str, Any]:
+    message: dict[str, Any] = {"role": "assistant", "content": content}
+    if reasoning:
+        message["reasoning_content"] = reasoning
+    if tool_call:
+        message["tool_calls"] = [
+            {
+                "id": "x",
+                "type": "function",
+                "function": {"name": tool_call, "arguments": '{"summary": "done"}'},
+            }
+        ]
+    data: dict[str, Any] = {
+        "model": "local",
+        "choices": [{"message": message, "finish_reason": "stop"}],
+        "usage": {"prompt_tokens": 120, "completion_tokens": 7},
+    }
+    if timings is not None:
+        data["timings"] = timings
+    return data
+
+
+class Server:
+    """A fake LiteLLM: answers each request in turn and keeps what it got."""
+
+    def __init__(self, *answers: tuple[int, dict[str, Any]]) -> None:
+        self.answers = list(answers)
+        self.bodies: list[dict[str, Any]] = []
+
+    def __call__(self, request: httpx.Request) -> httpx.Response:
+        self.bodies.append(json.loads(request.content))
+        status, data = self.answers.pop(0) if self.answers else (200, reply("ok"))
+        return httpx.Response(status, json=data)
+
+
+def budgeted(
+    server: Server, recorder: calls.CallRecorder | None, window: int = 32768
+) -> BudgetedClient:
+    inner = LiteLLMClient(
+        "https://litellm.test", TOKEN, transport=httpx.MockTransport(server)
+    )
+    return BudgetedClient(inner, lambda m: (window, 1024), call_recorder=recorder)
+
+
+@pytest.fixture
+def recorder(tmp_path: Path) -> calls.CallRecorder:
+    return calls.CallRecorder(tmp_path / "state.calls.db")
+
+
+def read(recorder: calls.CallRecorder) -> calls.CallReader:
+    return calls.CallReader(recorder.path)
+
+
+# --- what each call was --------------------------------------------------------
+
+
+def test_a_call_is_recorded_exactly_as_sent_with_its_reasoning(
+    recorder: calls.CallRecorder,
+) -> None:
+    server = Server(
+        (
+            200,
+            reply(
+                "Finishing.",
+                tool_call="finish",
+                reasoning="The tests pass, so the work is done.",
+                timings={"cache_n": 90, "prompt_n": 30},
+            ),
+        )
+    )
+    client = budgeted(server, recorder)
+    client.complete(
+        stored([UserMessage(text="go", source="t")]), [FINISH], "local", system="sys"
+    )
+
+    reader = read(recorder)
+    [call] = reader.calls()
+    # The request rebuilt from the record is the body the server got.
+    assert reader.request(call) == server.bodies[0]
+    response = reader.response(call)
+    assert (
+        response["choices"][0]["message"]["reasoning_content"]
+        == "The tests pass, so the work is done."
+    )
+    assert call["outcome"] == "answered"
+    assert (call["tokens_in"], call["tokens_out"]) == (120, 7)
+    assert (call["cache_n"], call["prompt_n"]) == (90, 30)
+    assert call["route"] == "chat" and call["status"] == 200
+
+
+def test_the_token_is_nowhere_in_the_record(recorder: calls.CallRecorder) -> None:
+    client = budgeted(Server(), recorder)
+    client.complete(stored([UserMessage(text="go", source="t")]), None, "local")
+    recorder.close()
+
+    raw = recorder.path.read_bytes()
+    conn = sqlite3.connect(recorder.path)
+    blobs = b"".join(
+        zlib.decompress(d) for (d,) in conn.execute("SELECT data FROM blobs")
+    )
+    rows = json.dumps(conn.execute("SELECT * FROM calls").fetchall()).encode()
+    conn.close()
+    assert TOKEN.encode() not in raw + blobs + rows
+
+
+def test_a_failed_call_is_recorded_with_its_error(recorder: calls.CallRecorder) -> None:
+    server = Server((400, {"error": {"message": "bad request: no such model"}}))
+    client = budgeted(server, recorder)
+    with pytest.raises(LLMError):
+        client.complete(stored([UserMessage(text="go", source="t")]), None, "local")
+
+    reader = read(recorder)
+    [call] = reader.calls()
+    assert call["outcome"] == "failed"
+    assert "LLMError" in call["error"]
+    assert call["status"] == 400
+    assert reader.request(call) == server.bodies[0]
+    assert reader.response(call) == {"error": {"message": "bad request: no such model"}}
+
+
+def test_a_request_too_big_to_send_is_recorded_without_one(
+    recorder: calls.CallRecorder,
+) -> None:
+    server = Server()
+    client = budgeted(server, recorder, window=4096)
+    with pytest.raises(ContextOverflow):
+        client.complete(
+            stored([UserMessage(text="go", source="t")]),
+            None,
+            "local",
+            system="s" * 20_000,
+        )
+
+    [call] = read(recorder).calls()
+    assert server.bodies == []
+    assert call["outcome"] == "failed" and "ContextOverflow" in call["error"]
+    assert call["request"] is None
+
+
+def test_a_growing_conversation_is_stored_once(recorder: calls.CallRecorder) -> None:
+    client = budgeted(Server(), recorder)
+    events: list[CanonicalEvent] = [
+        UserMessage(text="message 0 " + "x" * 2000, source="t")
+    ]
+    for n in range(1, 6):
+        client.complete(stored(events), None, "local")
+        events.append(AssistantText(text=f"reply {n} " + "y" * 2000, model="local"))
+        events.append(UserMessage(text=f"message {n} " + "z" * 2000, source="t"))
+
+    conn = sqlite3.connect(recorder.path)
+    stored_chars = sum(
+        len(zlib.decompress(d)) for (d,) in conn.execute("SELECT data FROM blobs")
+    )
+    conn.close()
+    # Five calls resend 1 + 3 + 5 + 7 + 9 messages of about 2 kB; stored
+    # once each, that's 9 messages (as sent, and as events), not 25.
+    assert stored_chars < 2 * 9 * 2100 + 20_000
+
+
+# --- where each request came from ---------------------------------------------
+
+
+def test_compaction_shortening_and_dropping_are_recorded(
+    recorder: calls.CallRecorder,
+) -> None:
+    long = "line\n" * 2000
+    events = stored(
+        [
+            UserMessage(text="start", source="t"),  # 1
+            AssistantText(text="old thinking", model="m"),  # 2, compacted
+            AssistantText(text="more old thinking", model="m"),  # 3, compacted
+            Compaction(summary="notes so far", model="m", replaces=[2, 3]),  # 4
+        ]
+    )
+    for n in range(8):  # turns 5.. : a command and its long output each
+        events += stored(
+            [
+                ToolCall(
+                    call_id=f"c{n}", tool="run_command", arguments={"command": "make"}
+                ),
+                ToolResult(call_id=f"c{n}", result=long, success=True),
+            ],
+            start=len(events) + 1,
+        )
+    client = BudgetedClient(
+        LiteLLMClient(
+            "https://litellm.test", TOKEN, transport=httpx.MockTransport(Server())
+        ),
+        lambda m: (12_000, 1024),
+        keep_recent_turns=2,
+        call_recorder=recorder,
+    )
+    client.complete(events, None, "local")
+
+    [call] = read(recorder).calls()
+    assert call["compacted"] == {"2": 4, "3": 4}
+    assert call["shortened"], "older results were cut to fit"
+    assert all(cut > 0 for cut in call["shortened"].values())
+    sent_ids = [entry[0] for entry in call["sent"]]
+    assert 4 in sent_ids and 2 not in sent_ids
+    assert set(map(int, call["shortened"])) <= set(sent_ids)
+    assert not set(call["dropped"]) & set(sent_ids)
+
+
+def test_runs_nest_and_label_their_calls(recorder: calls.CallRecorder) -> None:
+    client = budgeted(Server(), recorder)
+    events = stored([UserMessage(text="go", source="t")])
+    with calls.run(recorder, work_item="w", role="driver") as outer:
+        client.complete(events, None, "local")
+        with calls.purpose("consult", role="expert"):
+            client.complete(events, None, "local")
+        with calls.run(
+            recorder, work_item="w", role="helper", kind="delegation"
+        ) as inner:
+            client.complete(events, None, "local")
+            inner.end("handback", "done")
+        outer.end("wait", "")
+
+    reader = read(recorder)
+    runs = {r["kind"]: r for r in reader.runs()}
+    assert runs["delegation"]["parent"] == runs["run"]["id"]
+    assert runs["run"]["outcome"] == "wait" and runs["run"]["ended_at"]
+    assert runs["delegation"]["outcome"] == "handback"
+    turn, consult, helped = reader.calls()
+    assert (turn["run"], turn["role"], turn["purpose"]) == (
+        runs["run"]["id"],
+        "driver",
+        None,
+    )
+    assert (consult["role"], consult["purpose"]) == ("expert", "consult")
+    assert (helped["run"], helped["role"]) == (runs["delegation"]["id"], "helper")
+    assert {c["work_item"] for c in (turn, consult, helped)} == {"w"}
+
+
+def test_a_driver_run_is_recorded_with_how_it_ended(
+    tmp_path: Path, recorder: calls.CallRecorder
+) -> None:
+    store = StateStore(tmp_path / "state.db", oplog=OpLog("t", io.StringIO()))
+    store.open_work_item("w", title="t", position="RUNNING", cause="test")
+    store.transcript("w", "operator").append(UserMessage(text="go", source="t"))
+    client = budgeted(Server((200, reply(tool_call="finish"))), recorder)
+
+    outcome = Driver(client, "local").run(
+        store.transcript("w", "driver"),
+        system="sys",
+        tools=[FINISH],
+        waiting=("finish",),
+        workspace=None,
+    )
+
+    reader = read(recorder)
+    [run] = reader.runs()
+    assert outcome.kind == "wait"
+    assert (run["work_item"], run["role"], run["outcome"]) == ("w", "driver", "wait")
+    [call] = reader.calls(run=run["id"])
+    # Each event sent is the log's, by id, so the page can read it against
+    # the state store.
+    assert [entry[:3] for entry in call["sent"]] == [[1, "operator", "user_message"]]
+
+
+# --- the agent is told, and nothing depends on the record ----------------------
+
+
+def test_the_agent_is_told_exactly_while_it_is_recorded(tmp_path: Path) -> None:
+    on, off = Server(), Server()
+    budgeted(on, calls.CallRecorder(tmp_path / "a.calls.db")).complete(
+        stored([UserMessage(text="go", source="t")]), None, "local", system="sys"
+    )
+    budgeted(off, None).complete(
+        stored([UserMessage(text="go", source="t")]), None, "local", system="sys"
+    )
+    assert on.bodies[0]["messages"][0]["content"] == f"sys\n\n{calls.NOTICE}"
+    assert off.bodies[0]["messages"][0]["content"] == "sys"
+
+
+def test_a_recorder_that_fails_never_fails_the_call(tmp_path: Path) -> None:
+    out = io.StringIO()
+    recorder = calls.CallRecorder(tmp_path / "state.calls.db", oplog=OpLog("t", out))
+    recorder._conn.close()  # the disk went away, say
+    client = budgeted(Server(), recorder)
+
+    first = client.complete(stored([UserMessage(text="go", source="t")]), None, "local")
+    second = client.complete(
+        stored([UserMessage(text="go", source="t")]), None, "local"
+    )
+
+    assert [e.text for e in first + second] == ["ok", "ok"]  # type: ignore[union-attr]
+    assert not recorder.active
+    logged = [json.loads(line) for line in out.getvalue().splitlines()]
+    assert [e["event"] for e in logged].count("calls.record_failed") == 1
+
+
+def test_the_record_is_new_each_start(tmp_path: Path) -> None:
+    path = tmp_path / "state.calls.db"
+    path.write_bytes(b"an older layout, or not a database at all")
+    Path(f"{path}-wal").write_bytes(b"stale")
+    recorder = calls.CallRecorder(path)
+    budgeted(Server(), recorder).complete(
+        stored([UserMessage(text="go", source="t")]), None, "local"
+    )
+    assert recorder.active
+    assert len(read(recorder).calls()) == 1
+
+    again = calls.CallRecorder(path)
+    assert again.active and read(again).calls() == []
+
+
+def test_off_means_no_file(tmp_path: Path) -> None:
+    assert calls.recorder_for(tmp_path / "state.db", False) is None
+    assert not list(tmp_path.iterdir())
+    recorder = calls.recorder_for(tmp_path / "state.db", True)
+    assert recorder is not None and recorder.path == tmp_path / "state.calls.db"
+
+
+def test_a_reader_refuses_a_layout_it_does_not_know(
+    recorder: calls.CallRecorder,
+) -> None:
+    recorder._conn.execute("UPDATE meta SET value = '99' WHERE key = 'layout_version'")
+    with pytest.raises(calls.UnknownLayout, match="layout 99"):
+        read(recorder)
+
+
+def test_the_reader_never_writes(recorder: calls.CallRecorder) -> None:
+    budgeted(Server(), recorder).complete(
+        stored([UserMessage(text="go", source="t")]), None, "local"
+    )
+    reader = read(recorder)
+    with pytest.raises(sqlite3.OperationalError, match="readonly"):
+        reader._conn.execute("DELETE FROM calls")