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

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 (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
 

lib/aoide.rb

@@ -0,0 +1,26 @@
+# frozen_string_literal: true
+
+# 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
+  # 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

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
@@ -25,6 +27,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 +45,9 @@ def emit(event)
 
       private
 
+      # @return [Logger] dev-only Aoide logger
+      def log = Aoide.logger
+
       def content_blocks(response)
         response["content"] || response[:content] || []
       end
@@ -82,30 +89,56 @@ 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: 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)"
+        )
+        {"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
 end

spec/lib/events/subscribers/llm_response_handler_spec.rb

@@ -92,4 +92,67 @@ def dispatch(response, api_metrics: nil)
       expect(session.reload.aasm_state).to eq("idle")
     end
   end
+
+  describe "diagnostic logging" do
+    let(:debug_messages) { [] }
+
+    before do
+      allow(Aoide.logger).to receive(:info)
+      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
+      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 TOON at debug level" do
+      response = {"content" => [{"type" => "text", "text" => "hello"}], "stop_reason" => "end_turn"}
+      dispatch(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
+      dispatch({"content" => [
+        {"type" => "text", "text" => "thinking"},
+        {"type" => "tool_use", "name" => "from_melete_goal", "input" => {"goal" => "x"}}
+      ]})
+
+      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
+      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 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
+  end
 end