From 48e7efa2904005a444754bab116331b0fcb40e87 Mon Sep 17 00:00:00 2001 From: Yevhenii Hurin Date: Thu, 30 Apr 2026 10:25:58 +0300 Subject: [PATCH 1/3] #480 chore: instrument Aoide main loop with dev-only debug logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds Aoide.logger (dev-only file logger at log/aoide.log) mirroring Melete.logger and Mneme.logger, and wires three diagnostic log points into Events::Subscribers::LLMResponseHandler so we can pin down where spurious from_* tool calls originate: * Raw Anthropic API response payload at debug, captured before any normalization or filtering runs. * Raw tool_use blocks at debug, shown pre-normalization so a reader can tell whether a tool name like from_melete_goal arrived in the API response or was synthesized later. * One info line per dispatched tool execution with name+id, so the inbound list can be correlated against what gets queued for ToolExecutionJob. Once we run a session that exhibits the bug, the logs will show whether the LLM produced the from_* tool_use block (hallucination) or whether something inside Anima synthesized it (internal leak). The codebase review for the spike already favours hallucination — phantom from_* pairs are assembled by PendingMessage#promote! on the inbound side and the outgoing tool registry is built exclusively from real Tool subclasses with non-from_ names — but the logging exists to confirm or refute that, not assume it. Boy Scout cleanup in the same handler: factor session.id, tool_use["id"], and tool_use["name"] reads in dispatch_tool_executions and persist_tool_call to local variables; reek was flagging duplicate method calls. Refs #480 --- CLAUDE.md | 1 + lib/aoide.rb | 27 ++++++++ .../subscribers/llm_response_handler.rb | 41 ++++++++++--- .../subscribers/llm_response_handler_spec.rb | 61 +++++++++++++++++++ 4 files changed, 123 insertions(+), 7 deletions(-) create mode 100644 lib/aoide.rb diff --git a/CLAUDE.md b/CLAUDE.md index 5ca343bd..fa9ba8a3 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -94,6 +94,7 @@ Always clean up tmux sessions when done. Use `anima-test` as the session name fo **Important:** Use `./exe/anima` (not `bundle exec anima`) to test local code changes. The exe uses `require_relative` so it loads local `lib/` directly. `bundle exec` may load the installed gem version instead. Melete debug log (dev only): `tail -f log/melete.log` +Aoide debug log (dev only): `tail -f log/aoide.log` — raw API response, raw tool_use blocks, and dispatched tool name/id from the main loop. ## Triggering API 400 for smoke testing diff --git a/lib/aoide.rb b/lib/aoide.rb new file mode 100644 index 00000000..40e76181 --- /dev/null +++ b/lib/aoide.rb @@ -0,0 +1,27 @@ +# frozen_string_literal: true + +# Aoide — the muse of voice. The agent's main conversational loop: +# she takes the system prompt, recent messages, and tool registry, and +# turns each LLM response into dispatched tool executions. One of the +# Three Muses: Melete prepares, Aoide performs, Mneme remembers. +module Aoide + # Dev-only logger that writes to log/aoide.log. + # In non-development environments returns a null logger so + # call sites don't need conditionals. + # + # @return [Logger] + def self.logger + @logger ||= build_logger + end + + def self.build_logger + return Logger.new(File::NULL) unless Rails.env.development? + + Logger.new(Rails.root.join("log", "aoide.log")).tap do |log| + log.formatter = proc { |severity, time, _progname, msg| + "[#{time.strftime("%H:%M:%S.%L")}] #{severity} #{msg}\n" + } + end + end + private_class_method :build_logger +end diff --git a/lib/events/subscribers/llm_response_handler.rb b/lib/events/subscribers/llm_response_handler.rb index ed3de658..09355501 100644 --- a/lib/events/subscribers/llm_response_handler.rb +++ b/lib/events/subscribers/llm_response_handler.rb @@ -25,6 +25,8 @@ def emit(event) response = payload[:response] || {} api_metrics = payload[:api_metrics] + log_raw_response(session, response) + tool_uses = normalize_tool_uses(response) text = extract_text(response) @@ -41,6 +43,8 @@ def emit(event) private + def log = Aoide.logger + def content_blocks(response) response["content"] || response[:content] || [] end @@ -82,30 +86,53 @@ def persist_agent_message(session, text, api_metrics) end def persist_tool_call(session, tool_use) + tool_use_id = tool_use["id"] + tool_name = tool_use["name"] session.messages.create!( message_type: "tool_call", - tool_use_id: tool_use["id"], + tool_use_id: tool_use_id, payload: { "type" => "tool_call", - "tool_name" => tool_use["name"], - "tool_use_id" => tool_use["id"], + "tool_name" => tool_name, + "tool_use_id" => tool_use_id, "tool_input" => tool_use["input"], - "content" => "Calling #{tool_use["name"]}" + "content" => "Calling #{tool_name}" }, timestamp: Time.current.to_ns ) end def dispatch_tool_executions(session, tool_uses) + sid = session.id tool_uses.each do |tool_use| + tool_use_id = tool_use["id"] + tool_name = tool_use["name"] + log.info("session=#{sid} dispatching tool=#{tool_name} id=#{tool_use_id}") ToolExecutionJob.perform_later( - session.id, - tool_use_id: tool_use["id"], - tool_name: tool_use["name"], + sid, + tool_use_id: tool_use_id, + tool_name: tool_name, tool_input: tool_use["input"] ) end end + + # Diagnostic trace of every Anthropic response that reaches the + # main loop: full payload at debug, raw +tool_use+ blocks at + # debug, one-line summary at info. Lets a reader correlate + # "what came in from the API" against "what got dispatched" + # when investigating spurious tool calls. + def log_raw_response(session, response) + sid = session.id + blocks = content_blocks(response) + raw_tool_uses = blocks.select { |block| block_type(block) == "tool_use" } + log.info( + "session=#{sid} — response received " \ + "(#{blocks.size} block(s), #{raw_tool_uses.size} tool_use)" + ) + log.debug("session=#{sid} raw response:\n#{JSON.pretty_generate(response)}") + log.debug("session=#{sid} raw tool_use blocks:\n#{JSON.pretty_generate(raw_tool_uses)}") + end end end end diff --git a/spec/lib/events/subscribers/llm_response_handler_spec.rb b/spec/lib/events/subscribers/llm_response_handler_spec.rb index 5c357dc8..e4ebcd9e 100644 --- a/spec/lib/events/subscribers/llm_response_handler_spec.rb +++ b/spec/lib/events/subscribers/llm_response_handler_spec.rb @@ -92,4 +92,65 @@ def dispatch(response, api_metrics: nil) expect(session.reload.aasm_state).to eq("idle") end end + + describe "diagnostic logging" do + before do + allow(Aoide.logger).to receive(:info) + allow(Aoide.logger).to receive(:debug) + end + + it "logs a one-line summary including block and tool_use counts" do + dispatch({"content" => [ + {"type" => "text", "text" => "thinking"}, + {"type" => "tool_use", "id" => "toolu_1", "name" => "bash", "input" => {}} + ]}) + + expect(Aoide.logger).to have_received(:info) + .with(/session=#{session.id} — response received \(2 block\(s\), 1 tool_use\)/) + end + + it "logs the raw response payload as pretty JSON at debug level" do + response = {"content" => [{"type" => "text", "text" => "hello"}], "stop_reason" => "end_turn"} + dispatch(response) + + expect(Aoide.logger).to have_received(:debug) + .with(a_string_including("raw response:", JSON.pretty_generate(response))) + end + + it "logs raw tool_use blocks before normalization, preserving missing ids" do + raw_blocks_message = nil + allow(Aoide.logger).to receive(:debug) do |msg| + raw_blocks_message = msg if msg.start_with?("session=#{session.id} raw tool_use blocks:") + end + + dispatch({"content" => [ + {"type" => "text", "text" => "thinking"}, + {"type" => "tool_use", "name" => "from_melete_goal", "input" => {"goal" => "x"}} + ]}) + + expect(raw_blocks_message).to include("from_melete_goal") + expect(raw_blocks_message).not_to match(/"id":\s*"[0-9a-f-]{36}"/i) + end + + it "logs each dispatched tool name and id at info level" do + dispatch({"content" => [ + {"type" => "tool_use", "id" => "toolu_1", "name" => "bash", "input" => {"command" => "ls"}}, + {"type" => "tool_use", "id" => "toolu_2", "name" => "read", "input" => {"path" => "/tmp"}} + ]}) + + expect(Aoide.logger).to have_received(:info) + .with(/dispatching tool=bash id=toolu_1/) + expect(Aoide.logger).to have_received(:info) + .with(/dispatching tool=read id=toolu_2/) + end + + it "traces spurious from_* tool calls all the way to dispatch" do + dispatch({"content" => [ + {"type" => "tool_use", "id" => "toolu_phantom", "name" => "from_zero-width-sleuth", "input" => {}} + ]}) + + expect(Aoide.logger).to have_received(:info) + .with(/dispatching tool=from_zero-width-sleuth id=toolu_phantom/) + end + end end From 8da27dc3e06e26ea0c1a4b251a4cc8cbeb87de85 Mon Sep 17 00:00:00 2001 From: Yevhenii Hurin Date: Thu, 30 Apr 2026 10:39:08 +0300 Subject: [PATCH 2/3] Encode debug log payloads as TOON instead of pretty JSON MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Matches the project convention (Toon.encode for any structured data that is read by an agent or human in a logfile) and shrinks each debug line: a typical text-only response goes from ~30 lines of JSON to ~19 lines of TOON, with the same information in a more scannable table-header form. Lossless round-trip back to JSON if anyone needs it. Smoke-tested against the dev brain on 42135 — log/aoide.log now renders content blocks as a 1-row TOON table and empty arrays as [0]: instead of []. --- lib/events/subscribers/llm_response_handler.rb | 6 ++++-- spec/lib/events/subscribers/llm_response_handler_spec.rb | 4 ++-- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/lib/events/subscribers/llm_response_handler.rb b/lib/events/subscribers/llm_response_handler.rb index 09355501..facbf22b 100644 --- a/lib/events/subscribers/llm_response_handler.rb +++ b/lib/events/subscribers/llm_response_handler.rb @@ -1,5 +1,7 @@ # frozen_string_literal: true +require "toon" + module Events module Subscribers # Handles the aftermath of a single LLM round-trip emitted via @@ -130,8 +132,8 @@ def log_raw_response(session, response) "session=#{sid} — response received " \ "(#{blocks.size} block(s), #{raw_tool_uses.size} tool_use)" ) - log.debug("session=#{sid} raw response:\n#{JSON.pretty_generate(response)}") - log.debug("session=#{sid} raw tool_use blocks:\n#{JSON.pretty_generate(raw_tool_uses)}") + log.debug("session=#{sid} raw response:\n#{Toon.encode(response)}") + log.debug("session=#{sid} raw tool_use blocks:\n#{Toon.encode(raw_tool_uses)}") end end end diff --git a/spec/lib/events/subscribers/llm_response_handler_spec.rb b/spec/lib/events/subscribers/llm_response_handler_spec.rb index e4ebcd9e..f3f90eef 100644 --- a/spec/lib/events/subscribers/llm_response_handler_spec.rb +++ b/spec/lib/events/subscribers/llm_response_handler_spec.rb @@ -109,12 +109,12 @@ def dispatch(response, api_metrics: nil) .with(/session=#{session.id} — response received \(2 block\(s\), 1 tool_use\)/) end - it "logs the raw response payload as pretty JSON at debug level" do + it "logs the raw response payload as TOON at debug level" do response = {"content" => [{"type" => "text", "text" => "hello"}], "stop_reason" => "end_turn"} dispatch(response) expect(Aoide.logger).to have_received(:debug) - .with(a_string_including("raw response:", JSON.pretty_generate(response))) + .with(a_string_including("raw response:", Toon.encode(response))) end it "logs raw tool_use blocks before normalization, preserving missing ids" do From c837f8d82d7802452a9c3941eea205c3e5f681d1 Mon Sep 17 00:00:00 2001 From: Yevhenii Hurin Date: Thu, 30 Apr 2026 10:48:59 +0300 Subject: [PATCH 3/3] Address self-review findings on PR #485 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Self-review surfaced one real test bug, one perf-leaning idiom fix, and some doc/style drift from the established project conventions. Changes: * `spec/.../llm_response_handler_spec.rb`: the "preserving missing ids" test asserted with a JSON-shaped regex (`/"id":\s*"[0-9a-f-]{36}"/i`) but the encoding is TOON — the regex would never have matched, making the assertion vacuous (could pass with a synthesised UUID present). Replaced with a UUID-shaped regex that matches in any encoding. * `lib/events/subscribers/llm_response_handler.rb`: switch the two `log.debug` calls in `log_raw_response` to block form so `Toon.encode` is not evaluated unless the logger level allows it. Under the current null-logger-defaults-to-DEBUG configuration the savings are zero, but the form is idiomatic Ruby Logger and protects against future level changes. Also factored the two debug payloads into a small `Hash#each` to eliminate the duplicate `log.debug` call reek had flagged. * `lib/events/subscribers/llm_response_handler.rb`: added `@return [Logger]` YARD on `def log = Aoide.logger` to mirror the convention in `lib/melete/runner.rb:344-345`. Stripped the trailing task-referential clause ("when investigating spurious tool calls") from the comment on `log_raw_response` per CLAUDE.md ("Don't reference the current task, fix, or callers"). * `lib/aoide.rb`: tightened the module docstring to match Melete and Mneme — single-clause role description plus sister-relational framing of the Three Muses. * `CLAUDE.md`: added the correlation use case to the Aoide log line so a reader knows what they'd tail it for. * `spec/.../llm_response_handler_spec.rb`: renamed the "all the way to dispatch" test to be honest about what it asserts, and strengthened it to actually check the raw blocks log too — so the test now verifies the inbound→outbound trace the PR exists to produce. Test/lint state: 13 examples 0 failures, standardrb clean, reek back to the same 2 pre-existing FeatureEnvy warnings (none introduced). --- CLAUDE.md | 2 +- lib/aoide.rb | 7 +++--- .../subscribers/llm_response_handler.rb | 16 ++++++++----- .../subscribers/llm_response_handler_spec.rb | 24 ++++++++++--------- 4 files changed, 27 insertions(+), 22 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index fa9ba8a3..2b50ad24 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -94,7 +94,7 @@ Always clean up tmux sessions when done. Use `anima-test` as the session name fo **Important:** Use `./exe/anima` (not `bundle exec anima`) to test local code changes. The exe uses `require_relative` so it loads local `lib/` directly. `bundle exec` may load the installed gem version instead. Melete debug log (dev only): `tail -f log/melete.log` -Aoide debug log (dev only): `tail -f log/aoide.log` — raw API response, raw tool_use blocks, and dispatched tool name/id from the main loop. +Aoide debug log (dev only): `tail -f log/aoide.log` — raw API response, raw tool_use blocks (pre-normalization), and dispatched tool name/id. Use to correlate "what came in from the API" against "what got dispatched". ## Triggering API 400 for smoke testing diff --git a/lib/aoide.rb b/lib/aoide.rb index 40e76181..2780cb0c 100644 --- a/lib/aoide.rb +++ b/lib/aoide.rb @@ -1,9 +1,8 @@ # frozen_string_literal: true -# Aoide — the muse of voice. The agent's main conversational loop: -# she takes the system prompt, recent messages, and tool registry, and -# turns each LLM response into dispatched tool executions. One of the -# Three Muses: Melete prepares, Aoide performs, Mneme remembers. +# Aoide — the muse of voice. Turns each LLM response into dispatched +# tool executions and persisted messages. One of the Three Muses: she +# performs while Melete prepares the stage and Mneme remembers. module Aoide # Dev-only logger that writes to log/aoide.log. # In non-development environments returns a null logger so diff --git a/lib/events/subscribers/llm_response_handler.rb b/lib/events/subscribers/llm_response_handler.rb index facbf22b..2dcbd630 100644 --- a/lib/events/subscribers/llm_response_handler.rb +++ b/lib/events/subscribers/llm_response_handler.rb @@ -45,6 +45,7 @@ def emit(event) private + # @return [Logger] dev-only Aoide logger def log = Aoide.logger def content_blocks(response) @@ -120,20 +121,23 @@ def dispatch_tool_executions(session, tool_uses) end # Diagnostic trace of every Anthropic response that reaches the - # main loop: full payload at debug, raw +tool_use+ blocks at - # debug, one-line summary at info. Lets a reader correlate - # "what came in from the API" against "what got dispatched" - # when investigating spurious tool calls. + # main loop: a one-line summary at info, the full payload and + # raw +tool_use+ blocks (pre-normalization) at debug — paired so + # the inbound API response can be correlated against what got + # dispatched. Block form on +log.debug+ so +Toon.encode+ never + # runs unless the level allows it. def log_raw_response(session, response) sid = session.id blocks = content_blocks(response) raw_tool_uses = blocks.select { |block| block_type(block) == "tool_use" } + log.info( "session=#{sid} — response received " \ "(#{blocks.size} block(s), #{raw_tool_uses.size} tool_use)" ) - log.debug("session=#{sid} raw response:\n#{Toon.encode(response)}") - log.debug("session=#{sid} raw tool_use blocks:\n#{Toon.encode(raw_tool_uses)}") + {"raw response" => response, "raw tool_use blocks" => raw_tool_uses}.each do |label, payload| + log.debug { "session=#{sid} #{label}:\n#{Toon.encode(payload)}" } + end end end end diff --git a/spec/lib/events/subscribers/llm_response_handler_spec.rb b/spec/lib/events/subscribers/llm_response_handler_spec.rb index f3f90eef..805a2302 100644 --- a/spec/lib/events/subscribers/llm_response_handler_spec.rb +++ b/spec/lib/events/subscribers/llm_response_handler_spec.rb @@ -94,9 +94,14 @@ def dispatch(response, api_metrics: nil) end describe "diagnostic logging" do + let(:debug_messages) { [] } + before do allow(Aoide.logger).to receive(:info) - allow(Aoide.logger).to receive(:debug) + messages = debug_messages + allow(Aoide.logger).to receive(:debug) do |*args, &block| + messages << (block ? block.call : args.first) + end end it "logs a one-line summary including block and tool_use counts" do @@ -113,23 +118,18 @@ def dispatch(response, api_metrics: nil) response = {"content" => [{"type" => "text", "text" => "hello"}], "stop_reason" => "end_turn"} dispatch(response) - expect(Aoide.logger).to have_received(:debug) - .with(a_string_including("raw response:", Toon.encode(response))) + expect(debug_messages).to include(a_string_including("raw response:", Toon.encode(response))) end it "logs raw tool_use blocks before normalization, preserving missing ids" do - raw_blocks_message = nil - allow(Aoide.logger).to receive(:debug) do |msg| - raw_blocks_message = msg if msg.start_with?("session=#{session.id} raw tool_use blocks:") - end - dispatch({"content" => [ {"type" => "text", "text" => "thinking"}, {"type" => "tool_use", "name" => "from_melete_goal", "input" => {"goal" => "x"}} ]}) - expect(raw_blocks_message).to include("from_melete_goal") - expect(raw_blocks_message).not_to match(/"id":\s*"[0-9a-f-]{36}"/i) + raw_blocks = debug_messages.find { |m| m.start_with?("session=#{session.id} raw tool_use blocks:") } + expect(raw_blocks).to include("from_melete_goal") + expect(raw_blocks).not_to match(/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/i) end it "logs each dispatched tool name and id at info level" do @@ -144,11 +144,13 @@ def dispatch(response, api_metrics: nil) .with(/dispatching tool=read id=toolu_2/) end - it "traces spurious from_* tool calls all the way to dispatch" do + it "traces a spurious from_* tool call from the raw blocks log to dispatch" do dispatch({"content" => [ {"type" => "tool_use", "id" => "toolu_phantom", "name" => "from_zero-width-sleuth", "input" => {}} ]}) + raw_blocks = debug_messages.find { |m| m.start_with?("session=#{session.id} raw tool_use blocks:") } + expect(raw_blocks).to include("from_zero-width-sleuth") expect(Aoide.logger).to have_received(:info) .with(/dispatching tool=from_zero-width-sleuth id=toolu_phantom/) end