diff --git a/CLAUDE.md b/CLAUDE.md index 5ca343bd..2b50ad24 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 (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 new file mode 100644 index 00000000..2780cb0c --- /dev/null +++ b/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 diff --git a/lib/events/subscribers/llm_response_handler.rb b/lib/events/subscribers/llm_response_handler.rb index ed3de658..2dcbd630 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 @@ -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 diff --git a/spec/lib/events/subscribers/llm_response_handler_spec.rb b/spec/lib/events/subscribers/llm_response_handler_spec.rb index 5c357dc8..805a2302 100644 --- a/spec/lib/events/subscribers/llm_response_handler_spec.rb +++ b/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