From ca796e3a59aa0c01ceec80c7e49219b727af166d Mon Sep 17 00:00:00 2001 From: spomichter Date: Mon, 9 Mar 2026 22:20:15 +0000 Subject: [PATCH 1/2] feat: log MCP tool calls and agent messages to per-run JSONL MCP server: log every tool call (name, args), response (truncated to 200 chars), duration, and errors. Previously only errors were logged. Agent: pretty_print_langchain_message now also writes to structlog so agent conversation (human, AI, tool calls, tool responses) appears in per-run JSONL logs alongside module-level events. Both are now visible via dimos log. --- dimos/agents/mcp/mcp_server.py | 13 ++++++++++++- dimos/agents/utils.py | 19 +++++++++++++++++++ 2 files changed, 31 insertions(+), 1 deletion(-) diff --git a/dimos/agents/mcp/mcp_server.py b/dimos/agents/mcp/mcp_server.py index e63057b528..bfd45bc58a 100644 --- a/dimos/agents/mcp/mcp_server.py +++ b/dimos/agents/mcp/mcp_server.py @@ -16,6 +16,7 @@ import asyncio import json import os +import time from typing import TYPE_CHECKING, Any from fastapi import FastAPI @@ -107,20 +108,30 @@ async def _handle_tools_call( rpc_call = rpc_calls.get(name) if rpc_call is None: + logger.warning("MCP tool not found", tool=name) return _jsonrpc_result_text(req_id, f"Tool not found: {name}") + logger.info("MCP tool call", tool=name, args=args) + t0 = time.monotonic() + try: result = await asyncio.get_event_loop().run_in_executor(None, lambda: rpc_call(**args)) except Exception as e: - logger.exception("Error running tool", tool_name=name, exc_info=True) + logger.exception("MCP tool error", tool=name, duration=f"{time.monotonic() - t0:.3f}s") return _jsonrpc_result_text(req_id, f"Error running tool '{name}': {e}") + duration = f"{time.monotonic() - t0:.3f}s" + if result is None: + logger.info("MCP tool done (async)", tool=name, duration=duration) return _jsonrpc_result_text(req_id, "It has started. You will be updated later.") + response = str(result)[:200] if hasattr(result, "agent_encode"): + logger.info("MCP tool done", tool=name, duration=duration, response=response) return _jsonrpc_result(req_id, {"content": result.agent_encode()}) + logger.info("MCP tool done", tool=name, duration=duration, response=response) return _jsonrpc_result_text(req_id, str(result)) diff --git a/dimos/agents/utils.py b/dimos/agents/utils.py index 061e5ebb13..522a0463e7 100644 --- a/dimos/agents/utils.py +++ b/dimos/agents/utils.py @@ -17,6 +17,10 @@ from langchain_core.messages.base import BaseMessage +from dimos.utils.logging_config import setup_logger + +logger = setup_logger() + CYAN = "\033[36m" YELLOW = "\033[33m" GREEN = "\033[32m" @@ -78,6 +82,21 @@ def print_line(text: str) -> None: if first_line: print(f"{time_str} {type_str}") + # Also log to structlog so agent messages appear in per-run JSONL logs. + _log_message(msg_type, content, tool_calls) + + +def _log_message(msg_type: str, content: object, tool_calls: list[dict[str, Any]]) -> None: + """Write agent message to structlog (per-run JSONL).""" + content_str = str(content)[:500] if content else "" + if tool_calls: + tools = [{"name": tc.get("name"), "args": tc.get("args")} for tc in tool_calls] + logger.info("Agent message", msg_type=msg_type, content=content_str, tool_calls=tools) + elif content_str: + logger.info("Agent message", msg_type=msg_type, content=content_str) + else: + logger.info("Agent message", msg_type=msg_type) + def _try_to_remove_url_data(content: Any) -> Any: if not isinstance(content, list): From b5e5e843a0eadb846b2c65b678313842e3b38660 Mon Sep 17 00:00:00 2001 From: spomichter Date: Tue, 10 Mar 2026 08:16:00 +0000 Subject: [PATCH 2/2] fix: clean up agent message JSONL logging - Filter base64 image data once at content extraction instead of at each usage site (console output and JSONL logging). - Simplify _log_message: replace if/elif/else branches with a single logger.info call using conditional kwargs dict. --- dimos/agents/utils.py | 16 +++++++--------- 1 file changed, 7 insertions(+), 9 deletions(-) diff --git a/dimos/agents/utils.py b/dimos/agents/utils.py index 522a0463e7..5084c65b1f 100644 --- a/dimos/agents/utils.py +++ b/dimos/agents/utils.py @@ -51,7 +51,7 @@ def pretty_print_langchain_message(msg: BaseMessage) -> None: time_str = f"{GRAY}{timestamp}{RESET} " type_str = f"{type_color}{msg_type:<{TYPE_WIDTH}}{RESET}" - content = d.get("content", "") + content = _try_to_remove_url_data(d.get("content", "")) tool_calls = d.get("tool_calls", []) # 12 chars for timestamp + 1 space + TYPE_WIDTH + 1 space @@ -67,7 +67,7 @@ def print_line(text: str) -> None: print(f"{indent}{text}") if content: - content_str = repr(_try_to_remove_url_data(content)) + content_str = repr(content) if len(content_str) > 2000: content_str = content_str[:5000] + "... [truncated]" print_line(f"{BOLD}{type_color}{content_str}{RESET}") @@ -88,14 +88,12 @@ def print_line(text: str) -> None: def _log_message(msg_type: str, content: object, tool_calls: list[dict[str, Any]]) -> None: """Write agent message to structlog (per-run JSONL).""" - content_str = str(content)[:500] if content else "" + kw: dict[str, Any] = {"msg_type": msg_type} + if content: + kw["content"] = str(content)[:500] if tool_calls: - tools = [{"name": tc.get("name"), "args": tc.get("args")} for tc in tool_calls] - logger.info("Agent message", msg_type=msg_type, content=content_str, tool_calls=tools) - elif content_str: - logger.info("Agent message", msg_type=msg_type, content=content_str) - else: - logger.info("Agent message", msg_type=msg_type) + kw["tool_calls"] = [{"name": tc.get("name"), "args": tc.get("args")} for tc in tool_calls] + logger.info("Agent message", **kw) def _try_to_remove_url_data(content: Any) -> Any: