feat: log MCP tool calls and agent messages to per-run JSONL

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

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"
@@ -47,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
@@ -63,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}")
@@ -78,6 +82,19 @@ 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)."""
+    kw: dict[str, Any] = {"msg_type": msg_type}
+    if content:
+        kw["content"] = str(content)[:500]
+    if tool_calls:
+        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:
     if not isinstance(content, list):