MCP server structured logging

Why Pino, not console.log

Three reasons Pino outperforms console.log for production MCP servers:

1. Performance. Pino is one of the fastest Node.js logging libraries. It serialises to JSON using a low-allocation path and hands the write to a worker thread or a separate process (via transport). console.log performs synchronous string concatenation and a synchronous write to stdout — a noticeable bottleneck at hundreds of log calls per second.
2. Structured output. Pino emits newline-delimited JSON (NDJSON) by default. Log aggregators (Loki, Elasticsearch, CloudWatch Logs Insights) ingest NDJSON natively and index every field. No regex pipeline needed.
3. Child loggers. logger.child({ session_id, user_id }) creates a new logger that permanently binds those fields to every log line it emits. You bind the session context once at session open and every log call in that session automatically carries it.

Root logger with credential redaction

Define the root logger once at module scope. The redact option prevents accidental credential leakage when logging config objects or error details:

// logger.ts — root Pino logger
import pino from 'pino';

export const rootLogger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  base: {
    service: 'my-mcp-server',
    version: process.env.SERVICE_VERSION ?? '0.0.0',
    env: process.env.NODE_ENV ?? 'development',
  },
  redact: {
    // These paths are replaced with '[REDACTED]' before serialisation
    paths: [
      'config.DATABASE_URL',
      'config.REDIS_URL',
      '*.password',
      '*.token',
      '*.api_key',
      '*.apiKey',
      '*.secret',
      '*.SECRET',
      '*.authorization',
      'headers.authorization',
      'headers.cookie',
    ],
    censor: '[REDACTED]',
  },
  formatters: {
    level: (label) => ({ level: label }),  // emit level as string, not number
  },
  timestamp: pino.stdTimeFunctions.isoTime,
});

The redact.paths uses a subset of jq path syntax. Wildcards (*) match any object key at that depth. Pino walks the serialised object and replaces matched values before writing — the original values are never written to stdout.

Child loggers per session

At session open, create a child logger with the session ID and any available user identity. The child logger inherits all root logger settings (level, redact, formatters) and adds its bound fields to every log call:

// session-logger.ts — child logger at session open
import { rootLogger } from './logger';

export function createSessionLogger(sessionId: string, userId?: string) {
  return rootLogger.child({
    session_id: sessionId,
    ...(userId ? { user_id: userId } : {}),
  });
}

// In your MCP server's session handler
const sessionLogger = createSessionLogger(sessionId, context.meta?.userId);
sessionLogger.info('session opened');

// On session close
sessionLogger.info({ duration_ms: Date.now() - sessionStart }, 'session closed');

Every log call from this session logger automatically includes session_id. When a user reports "the tool was slow at 14:32 UTC", you run a Loki query for {service="my-mcp-server"} | json | session_id = "sess_abc123" and see the complete timeline of that session's tool calls, dependency responses, and any warnings.

AsyncLocalStorage for implicit context propagation

The problem with passing sessionLogger as a function parameter is that it must thread through every call on the stack — including utility functions and dependency helpers that shouldn't need to know about logging. AsyncLocalStorage solves this: store the session logger once when the session starts; retrieve it anywhere in the same async call chain without passing it explicitly:

// log-context.ts — AsyncLocalStorage for session context
import { AsyncLocalStorage } from 'async_hooks';
import pino from 'pino';
import { rootLogger } from './logger';

type LogContext = { logger: pino.Logger };

const logStorage = new AsyncLocalStorage<LogContext>();

// Run callback with a session-bound logger in context
export function withSessionLogger<T>(
  sessionLogger: pino.Logger,
  fn: () => Promise<T>,
): Promise<T> {
  return logStorage.run({ logger: sessionLogger }, fn);
}

// Retrieve the session logger (or fall back to root logger if not in a session context)
export function getLogger(): pino.Logger {
  return logStorage.getStore()?.logger ?? rootLogger;
}

// Using in a tool handler — no logger parameter needed
import { getLogger } from './log-context';

async function callSearchApi(query: string, agent: https.Agent): Promise<SearchResult[]> {
  const log = getLogger();
  log.debug({ query_length: query.length }, 'calling search API');

  const res = await fetch(`https://search.internal/v2/search`, { /* ... */ });
  if (!res.ok) {
    log.error({ status: res.status }, 'search API error');
    throw new Error(`search API ${res.status}`);
  }
  const data = await res.json();
  log.debug({ result_count: data.results.length }, 'search API response');
  return data.results;
}

// server.ts — wrap each tool call with the session's AsyncLocalStorage context
server.tool('search', searchSchema, async (params, context) => {
  const sessionLogger = createSessionLogger(context.meta?.sessionId ?? 'unknown');

  return withSessionLogger(sessionLogger, async () => {
    const log = getLogger();
    log.info({ tool: 'search' }, 'tool call started');

    try {
      const result = await runSearch(params, deps);
      log.info({ tool: 'search', ok: true }, 'tool call completed');
      return result;
    } catch (err) {
      log.error({ err, tool: 'search' }, 'tool call failed');
      return { isError: true, content: [{ type: 'text', text: 'search failed' }] };
    }
  });
});

Because Node.js's event loop preserves async context through await and promise chains, the AsyncLocalStorage context flows through every await inside withSessionLogger — including nested calls like callSearchApi — without any manual propagation.

Log level strategy

Log level discipline keeps production logs searchable without burying you in noise:

In production: set LOG_LEVEL=info. You'll see every tool call result, every session open/close, every error, and every warning — without the per-call parameter dumps that debug produces. When investigating a specific session, create a per-session debug mode: clone the session logger with sessionLogger.child({ level: 'debug' }) or flip the level via sessionLogger.level = 'debug' without restarting the server.

Logging errors correctly

Pino has first-class support for Error objects via its err serialiser. Pass the Error as the err field — not as a string or via err.message alone:

// Correct — Pino serialises err.message, err.stack, err.code, and err.name
log.error({ err }, 'dependency call failed');

// Incorrect — loses the stack trace, hides the error type
log.error(`dependency call failed: ${err.message}`);
log.error({ message: err.message }, 'dependency call failed');

Pino's default error serialiser extracts type, message, stack, and any enumerable properties from the Error. Custom error classes (e.g., a RetryableError with a retryable: true property) will have their custom properties included automatically because they're enumerable.

Never log raw database error messages from PostgreSQL or MySQL — they can contain fragments of the SQL query, which may include user-supplied data. Sanitise them:

function sanitiseDbError(err: Error): Error {
  const safe = new Error('database query failed');
  safe.stack = err.stack;
  // Do not copy err.message — it may contain query fragments with user data
  return safe;
}

try {
  await deps.db.query(sql, params);
} catch (err) {
  log.error({ err: sanitiseDbError(err as Error) }, 'database error');
  throw new Error('database query failed');
}

Correlation with OTel traces

If you're using OpenTelemetry, inject the active trace ID into every log line. Grafana can then draw a link from a log line to its parent trace in Grafana Tempo:

// logger.ts — inject OTel trace context into every log line
import { trace } from '@opentelemetry/api';

export const rootLogger = pino({
  // ...
  mixin() {
    const span = trace.getActiveSpan();
    if (!span) return {};
    const ctx = span.spanContext();
    return {
      trace_id: ctx.traceId,   // 32-char lowercase hex
      span_id:  ctx.spanId,    // 16-char lowercase hex
    };
  },
});

The mixin runs on every log call and reads the current OTel context from the async context propagation chain — the same chain that AsyncLocalStorage uses. If a span is active (because the log call is inside a tracer.startActiveSpan block), the trace ID is automatically included. This means that the error log from a failing callSearchApi has the same trace_id as the span for that tool call — you can jump from the error log directly to the span in Grafana.

Log shipping

Pino writes NDJSON to stdout by default. In a Docker environment, the container runtime captures stdout and makes it available to log shipping agents. Configure Pino to write to stdout (the default) and let the infrastructure handle collection:

# Dockerfile — no special log configuration needed
# Pino writes to stdout; Docker captures it via json-file log driver
CMD ["node", "dist/server.js"]

For local development, pipe Pino's output through pino-pretty for human-readable output without changing the production configuration:

# package.json dev script
"dev": "node --watch dist/server.js | npx pino-pretty"

For production log aggregation, see the log aggregation guide — covering Promtail + Loki, Filebeat + Elasticsearch, and AWS CloudWatch Logs. The key invariant is that your application always writes structured JSON to stdout; the shipping layer is a concern of the infrastructure, not the application code.

AliveMCP external probes complement structured logging: when a server crashes before logging any errors (an OOM kill, for example), there are no log lines to query. The AliveMCP probe catches the failure via its external connection attempt. See the observability overview for how external probes, structured logs, and metrics form a complete picture.