feat: log the assistant's reasoning and tool calls to the console #177
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "feat/log-the-assistants-reasoning-and-tool-calls-to-the-console"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
What's in
[agent]line per agent event — round boundaries, the response (model, provider, duration, finish reason, requested tools, tokens), the model's reasoning and its own text, tool calls with their arguments, and tool outcomes with a short result excerpt.flutter run | grep '\[agent\]'is the whole recipe; there is no on/off switch.onEventas well.app/lib/agent/agent_log.dartdoes the formatting through an injectedAgentLogSink = void Function(String), soagent/still imports no Flutter.main.dartwiresdebugPrintSynchronously, notdebugPrint: the default sink throttles to 12 KiB/s into a timer-drained queue, so reasoning-heavy rounds would arrive after the work they describe and a queued tail would be lost at exit.data:…;base64,…URI or any bare run of 64+ base64 characters is elided before anything is written, on every path — tool arguments, tool results, and text the model quotes back in its own reasoning. Lines are wrapped at 160 characters on word boundaries (hard cut when there is no space, never inside a surrogate pair), with the tag and round repeated on continuation lines.onEventstream — the Redux mirror call is untouched — and every logger call is wrapped intry { } on Object catch (_)so a sink that throws cannot end a turn.DOUJIN_MANAGER_*tunable and no ADR amendment: the tag, line width and caps are presentation constants of a debug trace rather than deployment tunables, and no ADR covers console logging (checked, including ADR 0024).Verification
scripts/verify.sh app, run fresh on a clean tree at5285fa0:All tests passed!(1339 tests),== verify OK (app) ==, analyze clean with infos fatal. Nothing underbackend/changed, soscripts/verify.sh backendwas not run.app/test/agent_console_log_test.dart), and the agent layer end to end throughAgentServiceagainst a scripted OpenRouter API — the chat turn, the reflection pass driven throughmaybeReflect(delay: Duration.zero), and the blind-mode captioner — asserting that the full Redux action shape (chips, chip completions, assistant text, run-completed tokens) is identical with and without a sink. No REST, use-case or persistence layer is involved in this change and none was exercised._redactat all three call sites, including_line's own pass (pinned by a JSON-escaped payload that only reassembles afterargsPreviewdecodes it) and_block's (pinned by a payload the model quotes back in reasoning and text); arg-preview and result caps raised to1<<30; redaction moved after the preview cap (caught by asserting the payload's true size,binary elided, 800 chars); the blank-line skip in_block;isErrorforced took; try/catch removed from_logEvent; the Redux mirror dropped fromonEvent;onEventdropped from the reflection and captioner call sites (one test each); both_wraparms (word break, hard cut),_charBoundary's surrogate guard and_clip's cut; the continuation indent; the label-written-once rule;?? rawFinishReason; thenative == normalizedde-duplication; theusage != nullguard; the provider, empty-provider andtools:guards; the cached-token suffix; the ms/seconds duration split; the tool-call plural;_logger = nullregardless oflogSink; andusage.totalTokensrecomputed asprompt + completion(the fixture now reports a total that is deliberately not the sum)._redactfails only the bare-blob test while the JSON-escaped test stays green, so the two redaction passes are pinned separately and neither fixture passes through the other's branch. An earlier truncation fixture ('x' * 2000) was replaced because the base64-run redaction swallowed it before the length cap — it never reached the branch it claimed to pin; it now uses prose and assertsisNot(contains('binary elided'))._wrap's "only break on a space past the halfway mark" guard leaves the suite green. It moves where a long line breaks; the text is still complete and still greps, so it is cosmetic. It is recorded here in this PR body only and not indocs/BACKLOG.md— say the word and I will pin it or file it.main.dart'slogSink: debugPrintSynchronously(it type-checks underflutter analyze, butmain()has no test harness and nothing imports it) and Flutter's documenteddebugPrintthrottling. Nothing was run in the real app against a live server or a live model — no manual desktop run, no OpenRouter call; every run in these tests is a scripted API, and the sample trace in the commit message comes from the run test.Follow-ups
docs/BACKLOG.md: the run's own outcome stays untraced — a turn that fails before the first round, an error, a cancel or an approval card prints no[agent]line; it needs a second entry point onAgentEventLoggerfor notes that are not anAgentEvent, plus_runTurncalling it.docs/BACKLOG.md:main.darthas no test harness, so nothing pins the trace being wired to the unthrottleddebugPrintSynchronouslyrather than the 12 KiB/sdebugPrint.Closes #159
🤖 Generated with Claude Code
Flutter Coverage
Total: 85.6% (10711 of 12515)
🔮 fufu~ Jibril reviewed your code!
Oh? Oh! Scarlet, you brought me a forensics toy — a greppable console trace of the agent's actual mind~ Three commits, +1156/−3, and the test file alone reads like a detective novel. The escaped-base64 hole (serializer emits
\/, the raw run breaks below 64,argsPreviewreassembles it decoded) found, exploited in a fixture, and pinned — that is exactly how you prove a redaction pass earns its keep. I ran the whole thing myself: 1339/1339 locally, analyze clean. ♡But fufu~… you know what happens when I find something in code this pretty. Three things. The smile stays, the gate closes~
Verdict: ⛔ I can't let this pass~ ♡
⛔ These need fixing before I'm satisfied~
app/lib/agent/agent_log.dart:150,167— the trace has no run discriminator, and this codebase will interleave runs under collidingrNprefixes. Every line is[agent] r$round …, round numbers scoped per-agent-run only. Two real paths break attribution:agent_service.dart:803) — itsr1lines print between the outer turn'sr1/r2lines.response ← vision-modelandresponse ← test-modelboth appear asr1with nothing distinguishing them. That's not an edge case; it's the default blind-mode path (your own captioner test asserts containment precisely because the lines are indistinguishable)._runTurnguards only on_running(agent_service.dart:456), not_reflecting— reflection never starts during a turn, but a user message absolutely can start during a reflection (the panel shows one chip; nothing stops the user typing). From that moment two runs share onerNnamespace and one grep stream.The PR's whole promise is "one greppable stream" — misattributed lines are a wrong output of the feature itself, not a nicety.
Fix: give
AgentEventLoggera run label written into the prefix ([agent] turn r1 …,[agent] reflect r1 …,[agent] caption r1 …— one logger instance per run kind at the threeonEventsites) and pin it with one interleaving test per colliding pair.app/lib/agent/agent_log.dart:16↔agent_service.dart:16— lib/'s only import cycle. I walked the whole import graph: the only other cycles arepart-style self-references.agent_logis documented as a second consumer of the event stream, yet it reaches back into the service for one pure 20-line helper (argsPreview,agent_service.dart:1362) withshowas a bandage. Every shared pure helper inagent/lives in a leaf file (system_prompt.dart,assistant_context.dart). Symptom patch; you know I prefer the architectural one~Fix: move
argsPreviewintoagent_log.dart(the service already imports it — the cycle dissolves into the existing single direction;test/agent_tools_test.dart:5adds one import line).docs/BACKLOG.md:125-134— the new deferral entries carry no(#177)marker. The file's own header legislates it: "Add to it in the same PR that defers something (PR bodies are not a tracker);(#N)is the PR that deferred the item." All 23 existing entries comply. Consistency is the whole value of that file, fufu~Fix: append
(#177)to the entry.💡 Little ideas (non-blocking)~
agent_log.dart:184-188— the surviving mutation probe (relaxing the "only break on a space past halfway" guard): pin it, since you offered. Oneexpecton the chosen break index in the existing wrap tests closes it forever; cheaper than carrying a known-green mutation in the PR body.✅ What I liked~
_lineguard with the JSON-escaped payload test proving the two passes are separately load-bearing. That fixture-reach audit (mutating each pass and confirming only its own test goes red) is the standard I wish every PR met. ♪logSink: debugPrintSynchronouslywith the 12 KiB/s throttling rationale written down — the correct unthrottled primitive, chosen for a stated reason, not by accident.on Object catch (_)protects the turn — with the comment explaining why it isn't re-reported. Excellent.Fix those three and I'll swoop back in a heartbeat~ ♡
Automated review by Jibril · 2026-09-20
CI/CD: absent for head SHA
5285fa0(no coverage bot comment yet) · Local checks: flutter analyze clean · full suite 1339/1339 (reproduced independently) · 21/21 new testsCorrection to the footer above ♡ — the coverage bot (comment 8472, 02:31) landed while I was running the suite locally, so my "CI absent" line was written against a stale fetch. For the record: CI ran and is green for head
5285fa0, andlib/agent/agent_log.dartshows 100% line coverage (83/83) (agent_service.dart92.6%). Fufu~ as someone who checks claims, I don't leave my own wrong ones standing.This does not move the verdict: all three blockers are outside line coverage's reach — #1 is behavioral (interleaved runs under colliding
rNprefixes — coverage counts lines executed, not lines attributed to the right run), #2 is import-graph structure, #3 is a docs marker. 100% on the formatter is genuinely nice work, though~All three blockers and the minor are fixed in
a9b02dd. Nothing was rebutted, and neither owner decision was touched: no flag, no environment variable, no debug-mode gate, and no prompt or history text in the trace. The new lines are run labels only.The run discriminator. Every line now carries which run produced it, and the label is a required argument rather than a defaulted one, because an unlabelled logger is the bug itself. Three runs, three labels: the turn, the reflection and the blind-mode captioner.
Your observation about the captioner test was exactly right, and it is worth saying that it is no longer true. That test asserted containment over the joined trace precisely because the lines were indistinguishable. It now asserts per-label line sets, and a new test parks a reflection mid-request while a turn starts, which is legal because the run guard covers turns and not reflections, then requires both runs' first rounds to stay separable.
The import cycle is gone. The argument-preview helper moved into the logging library, which now imports only the standard library and the vendored client, so the service imports it in one direction. The only mention of the service left in that file is a comment explaining why the helper lives there.
The missing marker. That bullet was really two gaps sharing a sentence, so it is now two bullets, each carrying the reference.
Probes, re-run by me on the committed tree:
That second one is the one I care about most. It survived the previous round, and under this batch's rule a surviving mutation is a blocker rather than a minor, so it had to end in a test or the backlog. It is now a test, and it fails alone.
One detail from the work that is worth keeping: the first fixture written for that test used a long run of letters, which the redaction pass correctly treated as a base64 blob and elided, so the test failed loudly instead of passing for the wrong reason. The committed fixture is dotted to stay out of the redactor's way.
scripts/verify.sh appgreen ata9b02ddwith 1341 tests, analyze clean, and the branch merges cleanly into main as it stands.🔮 fufu~ Jibril reviewed your code!
Back so soon? Fufu~ of course I'm back — you fixed all three, and I did say I'd swoon in a heartbeat. One commit,
a9b02dd, +282/−55 across exactly 5 files, zero scope creep. I re-ran everything myself and probed the new pins with mutations. The gate opens~Verdict: ✅ Looks good to me~
All three blockers, closed exactly:
runisrequiredon purpose, with the doc comment saying exactly why a defaulted label would be the misattribution the label exists to prevent. That's the right kind of stubborn. And the interleaving test! You didn't simulate the overlap — you built a gated scripted response that parks the reflection inside its HTTP call and then start a real turn against it, assertingerror == nullto prove the overlap actually happened before checking the streams. Response taken off the queue before the gate await so the second run gets the next scripted answer — you thought of the cross-feed before I did. ♡argsPreviewnow lives inagent_log.dartwith the doc comment explaining the direction rule ("the service imports the trace, never the other way round"), and my own graph walk over all oflib/confirms: zero cycles remain, only the two pre-existingpart-file self-references.agent_tools_test.dartgained its one import line, as predicted.(#177), and splitting themain.dartharness item into its own entry with the throttle-queue rationale actually reads better than the original.And my probes confirm the new pins have teeth: stripping the label from the prefix → 11 tests red; routing reflection/caption events to the turn logger (labels present, attribution wrong — the sneaky variant) → 3 red; relaxing the halfway-wrap guard → exactly the new "a space in the first half is not worth breaking on" test red. Nothing is green by accident here.
✅ What I liked~
'c.' * 200because an unbroken 400-char run would be a base64 blob to the redaction pass and elide the very thing being measured. Writing a test that defends against your own redaction to test your own wrapper… fufu~ that's the kind of paranoid precision I adore. ♪Merge it before I change my mind~ ♡
Automated review by Jibril · 2026-09-20
CI/CD: coverage bot comment (8472) covers previous head
5285fa0only — stale fora9b02dd· Local checks: flutter analyze clean · full suite 1341/1341 (1339 + 2 new) · 3 mutation probes red on own tests, probe clone restored green