9657334b5e
The machinery landed last commit; these are the events. What a routed request
now leaves behind, at info:
route id=r9116d9 cat=coding_refactor tier=2 ctx=500 src=classifier
tools=0 latency=interactive cand=8 pick=deepseek-v4-flash
est_usd=0.00016296 prof=1 ms=1868
dispatch id=r9116d9 model=deepseek-v4-flash rid=chatcmpl-... sess=c090d751
p_tok=59511 c_tok=415 kwh=4.8e-05 usd=0.000783 verdict=unverifiable
upstream_ms=3980 total_ms=5692
`rid` and `sess` are columns in energy_observations, so a journal line pivots
to its database row and back with a --grep. That is why no schema change was
needed to get traceability.
At debug it also says why, which is the half that was never recorded anywhere:
classify id=r9116d9 cat=coding_refactor tier=2 ctx=500 confidence=0.95 ms=1863
filter id=r9116d9 model=gemma-4-31b reason=tier(1<2)
filter id=r9116d9 model=glm-5.2-short reason=access_level(preview)
filter id=r9116d9 model=kimi-k3-flex reason=latency_class(flex)
rank id=r9116d9 pos=0 model=deepseek-v4-flash prof=1 est_usd=0.00016296
Those reasons come from routing.rejection_reason, which is is_eligible turned
inside out: it returns the failing filter and its numbers instead of False, and
is_eligible is now a one-line wrapper over it. One copy of the rules, so the
log cannot drift from the decision it describes.
log_decision is called by the ENDPOINTS, not by route(). chat_completions
routes twice whenever the measured conversation exceeds the classifier's
estimate -- with opencode sending ~32K of system prompt, essentially always --
and logging inside route() would double every line for no new information.
Two things the tests caught that reasoning had not:
The streaming path could not use the ContextVar. starlette resumes the
generator through a threadpool and every next() gets a fresh COPY of the
caller's context, so a trace id set inside is gone by the finally block that
logs the dispatch line. It logged id=- until the id was carried explicitly by
logs.bind() -- on the path all agent traffic takes.
$JOURNAL_STREAM is inherited. A foreground uvicorn started from a
systemd-managed session, output redirected to a file, put a literal <7> on
every line: the variable was set, but described a stream that was no longer
ours. It is now compared against the actual fd's device:inode, which is what
systemd documents.
A test asserts no conversation text reaches the log at any level, prompt or
answer. Prompts here run 60k-150k tokens and the journal is on disk.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WSkcSD2Jzkxo1Kw27ecfXJ
9.4 KiB
9.4 KiB