Structured Logging: Why JSON Logs Changed How We Debug

The before picture

[2024-03-15 10:23:45] INFO: User usr_123 placed order ord_456
[2024-03-15 10:23:45] ERROR: Payment failed for order ord_456: insufficient funds
[2024-03-15 10:23:46] INFO: Sent email to usr_123 about failed payment

This works for a single service. When three services each produce logs like this, finding every log related to one request means grepping across three log files with partial string matches. It breaks constantly.

The after picture

{"timestamp":"2024-03-15T10:23:45.123Z","level":"info","service":"order-api","traceId":"abc-123","userId":"usr_123","orderId":"ord_456","message":"Order placed"}
{"timestamp":"2024-03-15T10:23:45.456Z","level":"error","service":"payment-api","traceId":"abc-123","userId":"usr_123","orderId":"ord_456","error":"insufficient_funds","message":"Payment failed"}
{"timestamp":"2024-03-15T10:23:46.789Z","level":"info","service":"notification-api","traceId":"abc-123","userId":"usr_123","message":"Failure email sent"}

Now I can query: traceId = "abc-123" and get every log from every service for that request.

Setting up with Pino

Pino is the fastest Node.js logger. It outputs JSON by default:

import pino from 'pino';

const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  formatters: {
    level: (label) => ({ level: label }),
  },
  timestamp: pino.stdTimeFunctions.isoTime,
});

export default logger;

Request-scoped logging

Every log within a request should include the trace ID and user ID without the developer remembering to add them:

import { AsyncLocalStorage } from 'node:async_hooks';

const als = new AsyncLocalStorage<{ traceId: string; userId?: string }>();

// Middleware
app.use((req, res, next) => {
  const traceId = req.headers['x-trace-id'] || crypto.randomUUID();
  const userId = req.user?.id;
  als.run({ traceId, userId }, next);
});

// Logger wrapper
function log(level: string, message: string, data?: Record<string, unknown>) {
  const context = als.getStore();
  logger[level]({ ...context, ...data }, message);
}

// Usage — trace ID is automatic
log('info', 'Order placed', { orderId: 'ord_456' });

What to log

Always: request start/end, errors, external service calls, authentication events
Never: passwords, tokens, credit card numbers, PII beyond what is necessary
Conditionally: request/response bodies (debug level only, redacted)

Log levels that mean something

error: something broke and needs human attention
warn: something is wrong but the system handled it (retry succeeded, fallback activated)
info: normal business events (order placed, user signed up)
debug: detailed technical context (query plans, cache hits, serialization details)

In production, run at info. Switch to debug per-service when investigating issues.

Shipping logs to a central platform

JSON logs on stdout are useless in isolation. Ship them to a central platform:

App (stdout) → Fluentd/Vector → Elasticsearch/Loki → Kibana/Grafana

We use Vector as the log collector because it is fast, has built-in parsing and routing, and handles backpressure gracefully. Logs go to Elasticsearch for search and Grafana for dashboards.

The one thing that changed everything

The trace ID. One string that ties together every log, every span, every metric for a single request across every service. Without it, distributed debugging is archaeology. With it, debugging is a query.