fix(accounting): carry the background review's tokens across the persistence boundary

[gtyler]

Rewritten. The first version of this PR gave the review fork the parent's session_db outright. That was wrong: it collided head-on with the _persist_disabled isolation added in 71435fa0e/#54937, and would have reintroduced the curator-takeover bug. This version keeps that isolation completely intact and carries only the counters across it. Force-pushed onto current main.

The bug

The background memory/skill review forks an AIAgent that shares the parent's session_id for prompt-cache warmth, and is deliberately persistence-isolated:

review_agent._persist_disabled = True
review_agent._session_db = None
review_agent._session_json_enabled = False

That is right for messages — writing the harness turn into the user's real session is exactly the bug that isolation exists to stop.

It is wrong for counters. The provider bills the review's calls and the observability backend files them under that same session_id, so leaving them out of state.db makes the session's own cost read low. Nothing errors; the number is just quietly short.

How short

Measured per call against OpenAI's own GET /v1/responses/{id} usage — ground truth, not an estimate — on a scheduled workload. The review is the trailing 4-9 API calls of every pass, and the session row came up short by exactly those calls: fresh input, cached input, output and reasoning all four matching to the token.

model	provider calls / api_call_count	real cost	recorded	short by
gpt-5.4-mini	31 / 27	$0.32134	$0.28913	10.0%
gpt-5.4-mini	28 / 22	$0.47550	$0.40507	14.8%
claude-sonnet-4-6	27 / 18	$1.07062	$0.78134	27.0%
claude-sonnet-4-6	31 / 20	$1.02278	$0.72405	29.2%

Over 9 days on one workload: −11.09%, 54 of 56 passes affected, 257 of 1,740 calls never recorded. The share is largest where the foreground turn is short, because the review re-sends the full conversation — each of its calls re-bills the whole prompt.

The fix — counters only, across the boundary

_token_accounting_db / _token_accounting_session_id: a narrow channel set on the fork in addition to the isolation, never instead of it.

review_agent._persist_disabled = True                          # unchanged
review_agent._session_db = None                                # unchanged
review_agent._token_accounting_db = agent._session_db          # counters only
review_agent._token_accounting_session_id = agent.session_id

conversation_loop accounts there when set, and only the owner of a store may create its row (_acct_owned) — a borrowed store is written to, never created on. _persist_disabled still hard-stops _flush_messages_to_session_db, _ensure_db_session and _get_session_db_for_recall, so no message path is re-armed. tests/test_background_review_session_isolation.py passes unchanged, and the new tests assert the isolation attributes right next to the accounting ones so the two cannot drift apart silently.

Second half: the store is closed while the review is still writing

Even with the channel wired, the writes died — on a deployment they surfaced as:

Token persistence failed (session=cron_..., tokens=76750):
  'NoneType' object has no attribute 'execute'

cron/scheduler.py closes the shared SessionDB in its finally, right after end_session(). The review is spawned when the turn ends and keeps writing for another 40-100s, so close() sets _conn = None underneath a live thread. Caught per-call and logged at debug — invisible, so the only symptom was the under-count.

• _spawn_background_review keeps the thread handle; wait_for_background_review() joins it with a bound so a wedged review cannot hang a scheduler. _background_review_agent can interrupt a review but gives no way to join one, and cancelling is the wrong move where its writes are wanted — the two compose: cancel for live sessions, wait for batch ones.
• The cron runner waits before titling/ending/closing, so ended_at covers the whole pass and close() — which drains the token queue — is genuinely the last write. A timed-out wait warns and proceeds.
• logger.debug("Token persistence failed…") → logger.warning. Its own comment already said "silent loss here is the root cause of undercounted analytics" — right about the consequence, wrong about the level.

Verified on a live cron

	before	after
provider calls / api_call_count	28 / 22	47 / 47
real cost	$0.47550	$0.69394
cost from state.db tokens	$0.40507	$0.693937
gap	−14.81%	−0.0004%

Same cron, eight hours apart. Downstream agrees too: the three rows the pass writes sum to $0.69394 on 3,636,830 tokens — exactly state.db.

(That deployment runs an older build without _persist_disabled, so the shape verified there is the earlier one. The redesign here is verified by test, including upstream's own isolation suite; the measurements and the closed-store failure mode are unchanged by the reshaping.)

Tests

tests/run_agent/test_background_review_token_accounting.py — the fork accounts on the parent's store and session id (read off a real fork, not asserted against source text); the channel is not a back door into the message log; the handle exists and the wait is bounded. Each asserts the isolation attributes alongside the accounting ones.

Green: my tests + tests/test_background_review_session_isolation.py + tests/run_agent/test_background_review.py = 19 passed. tests/cron failure set byte-identical to main (6 pre-existing, 581 passed).

On the broad sweep (tests/run_agent + tests/agent + hermes_state, -p no:randomly) this venv has a lot of pre-existing environmental noise, so the number alone is meaningless — what matters is the comparison against a pristine main worktree with the identical command:

	failed	passed
main	224	5,942
this branch	222	5,950

Zero failures unique to this branch; the two extras on main are concurrency/timing flakes.

Note for other owners of per-run state

Anything that disposes of shared state at turn end has this race, not just cron — the review outlives the turn by design. wait_for_background_review() is the handle for it.

🤖 Generated with Claude Code

[gtyler]

Pushed a second commit — the first one was necessary but not sufficient, and the way it failed is worth recording.

With only session_db passed in, the fork's writes reached hermes_state and died there:

Token persistence failed (session=cron_..., tokens=76750):
  'NoneType' object has no attribute 'execute'

cron/scheduler.py closes the shared SessionDB in its finally block, right after end_session(). The background review is spawned when the turn ends and keeps calling the model — and writing — for another 40-100s, so close() sets _conn = None underneath a thread that is still running. Every review write raised, and conversation_loop swallowed it at logger.debug.

That combination is why this was invisible for weeks: the writes failed on every run, loudly enough to log and quietly enough that nobody saw it.

The second commit:

• _spawn_background_review keeps the thread handle; wait_for_background_review() joins it with a bound so a wedged review cannot hang a scheduler.
• The cron runner waits before titling/ending/closing — so ended_at now covers the whole pass and close() is genuinely the last write. A timed-out wait logs a warning and proceeds.
• logger.debug("Token persistence failed…") → logger.warning. Its own comment already said "silent loss here is the root cause of undercounted analytics" — right about the consequence, wrong about the level.

Diagnosed by temporarily raising that log on a live deployment and reading one cron pass: fork built: parent_db=SessionDB fork_db=SessionDB (part 1 working), persist? ctx=background_review ×2 (reached), then two Token persistence failed (the close).

Anyone else closing per-run state at turn end has the same race — that is the general form of this bug, and wait_for_background_review() is the handle for it.

Verification on a live cron is still in progress; I will follow up with the post-fix numbers rather than leave this claiming a result it has not shown.

[spfcraze]

This was generated by AI during triage.

Summary:
A routed background-review fork (auxiliary.background_review on a different model) rebuilds its own system prompt and writes it over the parent's stored row via update_system_prompt (conversation_loop.py:370) — so the parent's next turn reads a stale Model/Provider and misses its prefix cache.

Problems:

• agent/background_review.py:712 inherits the parent's cached prompt only under if not _routed; a routed fork leaves _cached_system_prompt None, yet still pins review_agent.session_id = agent.session_id (line 722) and now receives session_db=getattr(agent, "_session_db", None) (line 666).
• With a None cached prompt, agent/turn_context.py:314 calls _restore_or_build_system_prompt; it reads the parent's stored prompt (non-empty conversation_history, shared _session_db), finds Model/Provider stale for the routed model via _stored_prompt_matches_runtime (conversation_loop.py:380), rebuilds with _build_system_prompt, then conversation_loop.py:370 calls update_system_prompt(agent.session_id, ...) — writing the routed model's prompt into the parent's row.
• The body's invariant that "token accounting is the only thing shared" holds only for the non-routed fork: _skip_session_db_message_flush (run_agent.py:1643) guards _flush_messages_to_session_db but not the update_system_prompt write at conversation_loop.py:370.

Solution:
Also skip the update_system_prompt write for the fork (check the same _skip_session_db_message_flush flag inside _restore_or_build_system_prompt), so a routed fork's prompt rebuild cannot clobber the parent's stored prompt and force a prefix-cache miss on the parent's next turn.

Evidence

no deterministic fact backs this claim — model belief, not executed or read evidence

---

Checked against 04f2924 — the PR head when this was written — and f51aa6a, main at the same moment.

[gtyler]

Verified on a live cron, as promised above — first pass with both commits loaded:

	before	after
provider calls / state.db api_call_count	28 / 22	47 / 47
real cost	$0.47550	$0.69394
cost from state.db tokens	$0.40507	$0.693937
gap	−14.81%	−0.0004%

Same cron, eight hours apart. Downstream consumers agree too: the three run rows the pass writes sum to $0.69394 on 3,636,830 tokens — exactly state.db.

Over 9 days of the same workload the writes that were being dropped came to $2.56 of $23.11 (−11.09%), 54 of 56 passes affected, 257 of 1,740 calls never recorded.

One note for reviewers on the second commit's ordering: the cron runner now waits before end_session(), so ended_at covers the review too. That is deliberate — it makes ended_at mean "the pass stopped spending", which is what every downstream cost consumer already assumed it meant.

[gtyler]

Force-pushed a rewrite, and the earlier version of this PR was wrong — flagging that explicitly rather than letting it disappear into the diff.

It gave the review fork the parent's session_db outright. That collides head-on with the _persist_disabled isolation from 71435fa0e / #54937: two lines after my kwarg set it, review_agent._session_db = None unset it, so on current main the change was inert — and had it worked, it would have reintroduced the curator-takeover bug that isolation exists to prevent.

The cause was mundane and worth naming: I branched from a main that was six weeks stale because my initial fetch timed out and I proceeded on the stale ref instead of insisting on a current one. Everything upstream had learned about this fork in the meantime was invisible to me.

The rewrite keeps the isolation completely intact and carries only counters across it, via _token_accounting_db / _token_accounting_session_id. _persist_disabled still hard-stops every message and lazy-open path; tests/test_background_review_session_isolation.py passes unchanged; and the new tests assert the isolation attributes next to the accounting ones so the two can't drift apart silently. Only the owner of a store may create its row, so a borrowed store is written to but never created on.

Also worth stating plainly about the "verified on a live cron" numbers in my earlier comment: that deployment runs an older build with no _persist_disabled, so what it verifies is the diagnosis and the closed-store failure mode — not this exact code shape. The reshaping is covered by tests. I'd rather scope the claim than let the table imply more than it earned.

The second half of the fix (thread handle, waiting before the cron tears down the store, and promoting that swallowed logger.debug to warning) is unchanged in substance and rebased onto the current spawn site, which now wraps the target in propagate_context_to_thread.

One note on how it composes with 71435fa0e: that cancels an in-flight review at the start of a new turn on the same agent. A cron builds a fresh agent per run and never takes a second turn, so it can't cancel a review the cron path is waiting on. Cancel for live sessions, wait for batch ones — the two are complementary, and _active_children deliberately gives no way to join, which is what the batch case needs.

[Enough1122]

AI code review — automated review for reference, author can ignore or act on any point.

fix(accounting): carry the background review's tokens across the persistence boundary

1. _background_review_thread is a single attribute overwritten on every spawn — it holds only the last spawned thread. The review path looks single-flight (_background_review_agent + _background_review_lock), but if any path can spawn a new review while an older one is still running (e.g. an auto post-turn review racing a /refine), wait_for_background_review() returns as soon as the newest thread finishes while the older thread keeps writing — the cron close race this fixes would persist for that older thread. Either refuse concurrent spawns explicitly or track a set of live handles.
2. wait_for_background_review(timeout=180.0) blocks the cron heartbeat thread for up to 3 minutes if a review wedges. It's bounded and warned, but it stalls every subsequent job check on that ticker; a shorter default or a per-job config knob would contain the blast radius.
3. The logger.debug → logger.warning bump applies to all sessions, not just forks — a session store closing during a normal agent's shutdown now emits a warning for its last in-flight call. The justification in the comment is sound; just be aware this raises log noise on every path, not only the accounting channel.