fix(acp): eliminate end_turn latency from blocking token-cost fallback

[Million-mo]

Problem

On turn completion, ACP servers delay sending end_turn by several seconds. Root cause: TokenCost.from_usage runs before the StreamCompleteEvent is emitted (cost must be attached to the turn-final event). For models absent from the local genai_prices pricing snapshot (e.g. MiniMax-H3 raising LookupError), the tokonomics fallback performs a blocking, untimed download of the ~1 MB LiteLLM pricing table from GitHub. Measured 3.657s stall when the host is unreachable, and the failure was never cached — every subsequent turn retried the download.

Fix

• Startup prefetch — BaseServer.start now launches prefetch_token_cost_cache in the background, seeding the process-wide tokonomics pricing cache once at startup so runtime lookups are memory hits.
• Fallback guard — the runtime fallback is wrapped in asyncio.timeout(0.2); failed models are negatively cached (module-level _COST_FALLBACK_FAILED), degrading cost to 0 instead of blocking end_turn. Worst case adds at most 0.2s to a single turn.
• Tests — tests/messaging/test_token_cost_fallback.py covers the fast path, failure negative-caching (call count == 1), timeout guard, prefetch seeding, and prefetch error suppression.

Verification

• pytest tests/messaging/test_token_cost_fallback.py -v — 5 passed
• Regression: test_runusage_corrections.py + test_acp_turn_hooks.py — 12 passed
• ruff check — clean; mypy --strict — clean; pre-commit (ruff-format, ruff, ty, commitizen) — passed

[github-actions]

Review: PR #387 — fix(acp): eliminate end_turn latency from blocking token-cost fallback

I read the diff, the surrounding source, and verified the external API behavior (tokonomics 1.2.18 and anyenv/httpx internals). The root-cause diagnosis is sound and the latency bound is real, but there are several concerns — two of them structural.

MAJOR

1. The prefetch does not seed the cache keys the runtime actually looks up, so the first turn still downloads — and the 0.2s guard permanently zeroes the model.
agent.model_name emits colon-prefixed IDs (f"{system}:{model_name}", agent.py:829), and turn.py:572 passes that full string to TokenCost.from_usage. The fallback calls tokonomics.calculate_token_cost(model, ...) with that colon-prefixed string (messages.py:167). tokonomics keys its in-memory _cost_cache per model as f"{model_name}_costs" (core.py:92) — i.e. anthropic:claude-haiku-4-5_costs. The prefetch (messages.py:199) only seeds keys derived from the LiteLLM table's own bare/slash names (claude-haiku-4-5_costs, anthropic/claude-haiku-4-5_costs). So the runtime colon-form key is a miss, and get_model_costs performs another full download on the first fallback turn — it only happens to be fast when anyenv's hishel disk cache is already warm.

In the exact scenario this PR targets (host unreachable at startup → prefetch fails), the first runtime fallback is the first network attempt. It exceeds the 0.2s timeout → TimeoutError → the model is negatively cached → cost is permanently reported as $0 for the whole process lifetime, even though it is in the LiteLLM table and the network may recover. The "runtime lookups are memory hits" claim in the changelog does not hold for the standard colon-prefixed model format.

Suggested fix: seed the prefetch with the colon-form strings the runtime actually emits (or derive them from the pool's models), and/or have the fallback pass model_ref (already computed at messages.py:151-156) to calculate_token_cost so the bare table keys are hit.

2. The prefetch task is untimed and will delay server shutdown by up to ~5s.
BaseServer.start spawns prefetch_token_cost_cache via self._task_group.start_soon(...) (base.py:108). _safe_close_task_group() → ManagedTaskGroup.close() → anyio TaskGroup.__aexit__(None, None, None). On a normal (non-exception) exit, anyio does not cancel remaining child tasks — it waits for all of them to complete (_asyncio.py TaskGroup __aexit__). prefetch_token_cost_cache has no timeout of its own, and the underlying anyenv.get_json passes timeout=None to httpx, yielding httpx's 5s default. A hung prefetch therefore stalls close() in start()'s finally — a startup error or fast start→stop cycle can block shutdown for up to ~5s on every protocol server (ACP, OpenCode, AG-UI, OpenAI, MCP, A2A all go through BaseServer.start). Consider wrapping the prefetch body in asyncio.timeout(...) (e.g. 2–5s) so both startup and shutdown stay bounded.

MINOR

3. The negative cache never expires and conflates "transient timeout" with "not found".
_COST_FALLBACK_FAILED is a plain set[str] (messages.py:60) with no TTL and no retry, populated on any exception including the 0.2s timeout (messages.py:175-179). A single transient blip (or the finding-#1 timeout) permanently degrades a model to $0 with no recovery path. The changelog doesn't disclose this permanence. Prefer dict[str, float] with a bounded TTL, and only negative-cache definitive results (model absent from a successfully downloaded table) rather than timeouts.

4. Telemetry rule violation — background task with no span.
prefetch_token_cost_cache has no @logfire.instrument / with logfire.span(...), and BaseServer.start is uninstrumented, so the start_soon task runs outside any active span. Per docs/explanation/telemetry.md rule 3 and its background-task call-site pattern (e.g. subagent_tools.py), wrap the prefetch body in with logfire.span(...) and add the site to the table in telemetry.md.

5. Check-then-act race on the negative cache.
Two concurrent turns for the same model can both pass the if model in _COST_FALLBACK_FAILED check before either .add()s (parallel teams / concurrent ACP sessions). Both do the fallback (bounded to 0.2s each, so no unbounded cost), but the outcome is inconsistent — one turn may get a real cost while all future turns get $0. A per-model single-flight lock would fix it.

6. The two prefetch probes are redundant/misleading.
get_model_costs("gpt-4o") already seeds _cost_cache for every model in the table (core.py:108-137), so the probes at messages.py:204-205 add nothing the first call didn't — and, per finding #1, they don't seed the colon-form keys the runtime needs either. The comment and the test_prefetch_helper_seeds_cache assertion bake in this redundancy; consider dropping them or replacing them with colon-form runtime model strings.

7. The prefetch adds a real-network dependency to every server start, including spawned test servers.
start_soon runs in every BaseServer.start(). E2E subprocess servers inherit PYTEST_CURRENT_TEST from the test environment, which makes tokonomics disable its disk cache (_is_testing()), so each spawned server performs a real download from raw.githubusercontent.com on startup. ALLOW_MODEL_REQUESTS = False does not gate this. In offline CI this is a multi-second hang per spawn. Consider gating the prefetch behind a config/env flag (or a test hook) and covering it with a VCR cassette.

NITS

• Changelog file is missing a trailing newline (\ No newline at end of file).
• docs/reference/core-concepts/messages.md describes TokenCost/cost_info but not the new degradation contract (bounded 0.2s fallback, negative-cache → cost 0). A sentence would keep user docs accurate.
• src/wolfharness/AGENTS.md "Where to Look" lists messaging/ components but not messaging/messages.py, which now hosts the module-level _COST_FALLBACK_FAILED state — exactly the kind of gotcha a table row surfaces.

Positive

• Correct diagnosis and a real, well-bounded fix for the end_turn stall; asyncio.timeout correctly lets CancelledError (a BaseException) propagate rather than swallowing turn cancellation.
• Tests are well-structured L1 unit tests (autouse reset fixture, monkeypatched tokonomics, no network), and test_slow_fallback_is_bounded_by_timeout is a valid reproducer for the bug.
• mypy/ruff clean; the deferred import in base.py:106 correctly avoids the wolfharness_server → wolfharness.messaging cycle.
• Changelog entry follows changelog/README.md conventions, and skipping OpenSpec is appropriate for a self-contained fix.

[github-actions]

Review posted to #387 (comment).

Summary of the review:

MAJOR

1. Prefetch seeds the wrong cache keys — runtime lookups use colon-prefixed model names (agent.py:829 → tokonomics.calculate_token_cost), but the prefetch only seeds bare/slash LiteLLM table keys. The first turn still downloads; in the PR's own target scenario (unreachable host) the 0.2s timeout fires and permanently zeroes cost for that model.
2. Untimed prefetch delays shutdown — anyio TaskGroup.__aexit__ waits for children on normal exit; the prefetch has no timeout (httpx default 5s), so close() in start()'s finally can stall shutdown up to ~5s on all six protocol servers.

MINOR — negative cache never expires and conflates timeout with not-found; background task violates the telemetry span rule; check-then-act race on the negative cache; redundant/misleading prefetch probes; prefetch adds a real-network dependency to every server start (incl. spawned e2e servers).

Nits — changelog trailing newline; messages.py docs gaps.

Verified independently: tokonomics 1.2.18 cache internals, anyio task-group exit semantics, agent.model_name format, and the new tests/lint (ruff passes; one subagent claim of an import-order failure was disproven and excluded).

opencode session  |  github run