#480 chore: instrument Aoide main loop with dev-only debug logging

[hoblin]

Summary

Wires up dev-only debug logging into Events::Subscribers::LLMResponseHandler so we can pin down whether spurious from_* tool calls (e.g. from_melete_goal, from_zero-width-sleuth → Tools::UnknownToolError) originate from the LLM (hallucination) or from somewhere inside Anima (internal leak).

This is the research-spike data-gathering step of #480 — not a fix. The decision (hallucination vs internal leak) and the follow-up implementation issue come after a session that exhibits the bug is run against the new logs.

What's logged (at the point the API response enters the main loop)

1. Raw Anthropic API response payload — full structure, encoded as TOON, debug level. Captured before normalize_tool_uses runs.
2. Raw tool_use blocks — debug level, TOON-encoded, shown pre-normalization so missing ids look missing. If a from_melete_goal block is here, the LLM produced it; if it's only in the dispatched list, something else synthesized it.
3. Each dispatched tool execution — info level, one line per call, with name + id.

Plus a one-line info summary at session boundary (response received (N block(s), M tool_use)) so a reader can scan the timeline without --debug.

Payloads are encoded with Toon.encode (already used by lib/tui/screens/chat.rb and the tool decorators) — same project convention, ~30% fewer lines than JSON.pretty_generate, lossless round-trip.

Where it lives

• lib/aoide.rb — new module-level logger, mirrors Melete.logger / Mneme.logger byte-for-byte: dev-only Logger.new("log/aoide.log"), returns Logger.new(File::NULL) outside Rails.env.development? so call sites stay unconditional.
• lib/events/subscribers/llm_response_handler.rb — three log points: log_raw_response at the top of #emit, info line in dispatch_tool_executions, plus def log = Aoide.logger.
• CLAUDE.md — adds tail -f log/aoide.log next to the existing Melete tip.

How to use the logs

After this lands, run a session in dev that's likely to surface the bug (it tends to happen when sub-agents are messaging in or skills/goals are being injected). Then:

tail -f log/aoide.log | grep -E "raw tool_use blocks|dispatching"

If a dispatching tool=from_* line appears whose tool name is also present in the matching raw tool_use blocks: payload, the LLM hallucinated it. If the from_* name is absent from the raw blocks but appears in dispatch, something inside Anima is synthesizing the tool_use after the API response.

Architectural prior

The codebase review for this spike (PR #445 + drain-principles note + PendingMessage#promote_as_phantom_pair!) already favours the hallucination hypothesis: phantom from_* pairs are assembled inbound by PendingMessage#promote! as message-array entries, and the outgoing tool registry (Tools::Registry.tool_classes_for) is built exclusively from real Tool subclasses — none of which start with from_. So an internal leak is architecturally implausible under the current design. The logging confirms or refutes that without us having to assume.

Smoke test (against dev brain on 42135)

Restarted the brain after this branch was on disk, said hi, read log/aoide.log — got:

[10:38:34.813] INFO  session=15 — response received (1 block(s), 0 tool_use)
[10:38:34.814] DEBUG  session=15 raw response:
model: claude-opus-4-6
id: msg_01DGMeXArS2ZQMNagL4HH4AU
type: message
role: assistant
content[1]{type,text}:
  text,"…"
…
[10:38:34.814] DEBUG  session=15 raw tool_use blocks:
[0]:

Three signals firing as designed; TOON encoding reads cleanly.

Boy Scout

While in the handler, factored session.id, tool_use["id"], and tool_use["name"] reads in dispatch_tool_executions and persist_tool_call to local variables — reek was flagging the duplicate method calls.

Test plan

• bundle exec rspec spec/lib/events/subscribers/llm_response_handler_spec.rb — 13 examples, 0 failures (5 new, all asserting the logger receives the right calls)
• bundle exec rspec spec/jobs/drain_job_spec.rb — 11 examples, 0 failures (sanity check on the upstream emitter)
• bundle exec standardrb — clean on changed files
• bundle exec reek lib/events/subscribers/llm_response_handler.rb — only 2 pre-existing FeatureEnvy warnings remain (inherent iteration shape; not introduced by this PR and not obviously improved by extraction)
• Manual: dev brain smoke test (above) — log/aoide.log populates correctly on a benign greeting.
• Real-session: wait for a session that exhibits the from_* bug, read the logs, decide hallucination vs internal leak, record on Research spike: source of from_* tool calls in the main loop #480, open follow-up implementation issue.

Acceptance criteria from #480

• After a session that exhibits the bug, the logs contain enough information to determine whether the from_* tool_use block was present in the API response or synthesized later. (structurally yes — verified by spec + smoke test, awaiting real-session confirmation)
• Decision recorded on Research spike: source of from_* tool calls in the main loop #480: hallucination vs internal leak. (blocked on a real session with the new logs)
• Follow-up implementation issue opened with the appropriate fix. (blocked on the decision above)

Refs #480

[bonk-moltbot]

🐭✅ Research spike done right — instrument first, decide later.

Aoide module mirrors Melete/Mneme logger pattern byte-for-byte: dev-only file logger, null logger in production, no conditionals at call sites. Clean.

Three log points at the right seam:

1. Info summary at response entry — response received (N block(s), M tool_use) — scannable timeline
2. Debug: raw response + raw tool_use blocks pre-normalization — so missing ids look missing, and from_* names are traceable to source
3. Info: each dispatched tool name+id — the "what got acted on" counterpart

The correlation workflow is elegant: if from_melete_goal appears in raw blocks AND dispatch → LLM hallucinated it. If only in dispatch → internal leak. The architectural prior (phantom from_* pairs built inbound by PendingMessage#promote!, not in outbound registry) already points at hallucination, but now there's data.

Boy scout bonus: local variable extraction in persist_tool_call and dispatch_tool_executions — fewer repeated hash lookups, cleaner reading. Block form on log.debug so Toon.encode never runs unless debug level — no perf impact in production.

Test coverage: 5 specs including the "trace a spurious from_* call from raw blocks to dispatch" scenario — directly tests the diagnostic use case.