Merge master into feature/session-proxy

src/grist_mcp/server.py

@@ -1,6 +1,7 @@
 """MCP server setup and tool registration."""
 
 import json
+import time
 
 from mcp.server import Server
 from mcp.types import Tool, TextContent
@@ -9,6 +10,9 @@ from grist_mcp.auth import Authenticator, Agent, AuthError
 from grist_mcp.session import SessionTokenManager
 from grist_mcp.tools.session import get_proxy_documentation as _get_proxy_documentation
 from grist_mcp.tools.session import request_session_token as _request_session_token
+from grist_mcp.logging import get_logger, extract_stats, format_tool_log
+
+logger = get_logger("server")
 
 from grist_mcp.tools.discovery import list_documents as _list_documents
 from grist_mcp.tools.read import list_tables as _list_tables
@@ -239,6 +243,22 @@ def create_server(auth: Authenticator, agent: Agent, token_manager: SessionToken
 
     @server.call_tool()
     async def call_tool(name: str, arguments: dict) -> list[TextContent]:
+        start_time = time.time()
+        document = arguments.get("document")
+
+        # Log arguments at DEBUG level
+        logger.debug(
+            format_tool_log(
+                agent_name=_current_agent.name,
+                token=_current_agent.token,
+                tool=name,
+                document=document,
+                stats=f"args: {json.dumps(arguments)}",
+                status="started",
+                duration_ms=0,
+            )
+        )
+
         try:
             if name == "list_documents":
                 result = await _list_documents(_current_agent)
@@ -311,11 +331,53 @@ def create_server(auth: Authenticator, agent: Agent, token_manager: SessionToken
             else:
                 return [TextContent(type="text", text=f"Unknown tool: {name}")]
 
+            duration_ms = int((time.time() - start_time) * 1000)
+            stats = extract_stats(name, arguments, result)
+
+            logger.info(
+                format_tool_log(
+                    agent_name=_current_agent.name,
+                    token=_current_agent.token,
+                    tool=name,
+                    document=document,
+                    stats=stats,
+                    status="success",
+                    duration_ms=duration_ms,
+                )
+            )
+
             return [TextContent(type="text", text=json.dumps(result))]
 
         except AuthError as e:
+            duration_ms = int((time.time() - start_time) * 1000)
+            logger.warning(
+                format_tool_log(
+                    agent_name=_current_agent.name,
+                    token=_current_agent.token,
+                    tool=name,
+                    document=document,
+                    stats="-",
+                    status="auth_error",
+                    duration_ms=duration_ms,
+                    error_message=str(e),
+                )
+            )
             return [TextContent(type="text", text=f"Authorization error: {e}")]
+
         except Exception as e:
+            duration_ms = int((time.time() - start_time) * 1000)
+            logger.error(
+                format_tool_log(
+                    agent_name=_current_agent.name,
+                    token=_current_agent.token,
+                    tool=name,
+                    document=document,
+                    stats="-",
+                    status="error",
+                    duration_ms=duration_ms,
+                    error_message=str(e),
+                )
+            )
             return [TextContent(type="text", text=f"Error: {e}")]
 
     return server