Files
dongarandClaude Opus 5.5 dd060566b2
CI / checks (push) Skipped
CI / checks (pull_request) Successful in 2m54s
CI / e2e (pull_request) Successful in 4m20s
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
2026-10-24 06:28:53 +00:00

377 lines
13 KiB
Python

"""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")