Structured Logging for MCP

Unstructured log lines — "Tool filesystem_read executed successfully" — are human-readable and machine-useless. Structured logging emits each log entry as a JSON object with consistent field names: timestamp, level, message, tool_name, session_id, user_id, duration_ms, result_status. This makes logs queryable: "show me all tool invocations for user X that took more than 5 seconds in the last hour" becomes a simple JSON filter instead of a regex nightmare. Every MCP server should emit structured logs from day one. Retrofitting structured logging onto an existing server with string-formatted logs is one of the most tedious refactors in operations.

Log levels in MCP have specific meanings. DEBUG logs protocol-level details (raw JSON-RPC messages, handshake steps). INFO logs business events (tool invoked, resource accessed, session started). WARN logs degraded conditions (slow downstream dependency, token expiring soon, retry triggered). ERROR logs failures (tool threw an exception, auth rejected, session corrupted). FATAL logs process-ending events (uncaught exception, out of memory). The discipline is: production runs at INFO level. DEBUG is for development. If your INFO logs do not tell you what is happening, your log levels are wrong.

Correlation IDs connect logs across services. When a request enters the MCP gateway, generate a unique request_id. Thread it through every service call, log entry, and error message in the request's lifecycle. When a user reports "the tool failed," the request_id lets you pull every log line from every service involved in that request — gateway, MCP server, downstream API, database — and reconstruct the complete execution timeline. Without correlation IDs, debugging distributed failures is guesswork.

// Structured logging middleware for MCP tool invocations
interface ToolLogEntry {
  timestamp: string;
  level: "DEBUG" | "INFO" | "WARN" | "ERROR";
  event: "tool_invoked" | "tool_completed" | "tool_failed";
  request_id: string;
  session_id: string;
  user_id: string;
  tool_name: string;
  duration_ms?: number;
  result_status?: "success" | "error";
  error_code?: number;
  error_message?: string;
}

function logToolInvocation(entry: ToolLogEntry): void {
  // Single JSON line per entry — machine-parseable
  process.stderr.write(JSON.stringify(entry) + "\n");
}

// Usage in tool handler wrapper
async function withLogging<T>(
  ctx: { requestId: string; sessionId: string; userId: string },
  toolName: string,
  handler: () => Promise<T>
): Promise<T> {
  const start = Date.now();
  logToolInvocation({
    timestamp: new Date().toISOString(),
    level: "INFO",
    event: "tool_invoked",
    request_id: ctx.requestId,
    session_id: ctx.sessionId,
    user_id: ctx.userId,
    tool_name: toolName,
  });

  try {
    const result = await handler();
    logToolInvocation({
      timestamp: new Date().toISOString(),
      level: "INFO",
      event: "tool_completed",
      request_id: ctx.requestId,
      session_id: ctx.sessionId,
      user_id: ctx.userId,
      tool_name: toolName,
      duration_ms: Date.now() - start,
      result_status: "success",
    });
    return result;
  } catch (err) {
    logToolInvocation({
      timestamp: new Date().toISOString(),
      level: "ERROR",
      event: "tool_failed",
      request_id: ctx.requestId,
      session_id: ctx.sessionId,
      user_id: ctx.userId,
      tool_name: toolName,
      duration_ms: Date.now() - start,
      result_status: "error",
      error_message: String(err),
    });
    throw err;
  }
}