Structured logging

Backend Fundamentals · Observability · 7 min read

1. What problem does this solve?

• Problem: Traditional log messages are free‑text strings. When a service crashes or a request fails, developers must sift through noisy, unstructured logs to find the root cause.
• Why it matters: In production, logs are the primary source of truth for debugging, monitoring, and compliance. Unstructured logs make it hard to search, filter, and correlate events across distributed systems.
• Consequences of not using structured logging:
  • Hard to automate: No reliable way to extract fields for alerts or dashboards.
  • Inconsistent context: Missing request IDs, user IDs, or error codes.
  • Security risk: Sensitive data may be logged in plain text.
  • Performance hit: Parsing large unstructured logs is expensive.
• Real‑world appearance:
  • Microservice backends (Node.js, FastAPI) ship logs to ELK/EFK stacks.
  • Serverless functions use structured logs to correlate cold starts.
  • AI model serving pipelines log inference latency and input shapes.

2. Mental model

Analogy
Think of a diary. A free‑text diary is great for storytelling, but if you want to find all entries about “rain” you have to read every page. A structured diary has tags (e.g., weather:rain, mood:happy) so you can instantly filter. Structured logging is that tagged diary for your backend.

Engineering model

• Log entry = a JSON object with a schema (fixed set of keys).
• Log level = severity (debug, info, warn, error).
• Correlation ID = a unique token that ties all events of a single request.
• Transport = async writer that pushes logs to a sink (file, stdout, log aggregator).

3. Deep explanation

4. How it works

1. Request enters → middleware generates a requestId.
2. Application code logs events: logger.info({ event: 'user_login', userId }).
3. Logger serializes to JSON, queues the message.
4. Async writer flushes the queue to the sink (file, stdout, or remote collector).
5. Collector ingests, indexes, and stores logs.
6. Ops query logs by requestId, userId, or level.

sequenceDiagram
    participant Client
    participant API
    participant Logger
    participant Sink
    participant Collector

    Client->>API: GET /api/user
    API->>Logger: log.info({event:"fetch_user", userId:123})
    Logger->>Logger: serialize & queue
    Logger->>Sink: async write
    Sink->>Collector: ship logs
    Collector->>Ops: query by requestId

5. Practical implementation

Below is a minimal Express + Pino example that demonstrates structured logging with request correlation.

// logger.ts
import pino from 'pino';
import { randomUUID } from 'crypto';

const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  // Pretty printing only in dev
  transport: process.env.NODE_ENV === 'development'
    ? { target: 'pino-pretty', options: { colorize: true } }
    : undefined,
});

export default logger;

// middleware.ts
import { Request, Response, NextFunction } from 'express';
import logger from './logger';

export function requestLogger(req: Request, res: Response, next: NextFunction) {
  const requestId = randomUUID();
  // Attach to request for downstream use
  (req as any).requestId = requestId;

  // Log request start
  logger.info({
    event: 'request_start',
    requestId,
    method: req.method,
    url: req.originalUrl,
    headers: req.headers,
  });

  // Ensure requestId is in all logs
  const originalLog = logger.info.bind(logger);
  logger.info = (msg, meta) => {
    originalLog({ ...meta, requestId, ...msg });
  };

  res.on('finish', () => {
    logger.info({
      event: 'request_end',
      requestId,
      statusCode: res.statusCode,
      durationMs: Date.now() - (req as any).startTime,
    });
  });

  next();
}

// app.ts
import express from 'express';
import logger from './logger';
import { requestLogger } from './middleware';

const app = express();
app.use(requestLogger);

app.get('/api/user/:id', async (req, res) => {
  const userId = req.params.id;
  try {
    // Simulate DB call
    const user = { id: userId, name: 'Alice' };
    logger.info({ event: 'user_fetched', userId, user });
    res.json(user);
  } catch (err) {
    logger.error({ event: 'db_error', error: err.message });
    res.status(500).json({ error: 'Internal' });
  }
});

app.listen(3000, () => logger.info('Server started on :3000'));

Key points

• pino writes JSON to stdout; container orchestrators capture it.
• requestId is propagated to all logs for a single request.
• Errors are logged with error level and stack trace (err.stack).
• In production, set LOG_LEVEL=warn to reduce noise.

6. Production considerations

7. Common mistakes

8. Senior engineer perspective

At scale, structured logging becomes a contract between services.

• Architecture decisions
  • Centralized vs. distributed log ingestion.
  • Choosing a schema registry to enforce field consistency.
  • Deciding between JSON vs. binary (e.g., Protobuf) for log transport.
• Trade‑offs
  • More fields → richer context but higher bandwidth.
  • Strict schema → easier downstream processing but harder to evolve.
• Bottlenecks
  • Log shipping can become a network bottleneck; use compression.
  • Log aggregation services may saturate CPU if parsing huge volumes.
• Failure scenarios
  • Log shipper crash → loss of logs; mitigate with local buffering.
  • Schema drift → downstream dashboards break; mitigate with versioned schemas.
• Monitoring
  • Set up alerts on log volume, error rates, and missing correlation IDs.
  • Use log‑based metrics (e.g., rate{level="error"}) in Prometheus.
• Cost/performance
  • Cloud log services charge per GB ingested; keep logs lean.
  • Use log sampling for high‑volume services.
• When NOT to use
  • Small, single‑purpose scripts where console output suffices.
  • Legacy systems that cannot ship structured logs without major refactor.

9. Interview questions

10. Hands‑on task

Goal: Add structured logging to an existing Next.js API route that returns a list of users from PostgreSQL.

Steps

1. Install pino and pino-http (npm i pino pino-http).
2. Create a logger.ts that exports a Pino logger.
3. Wrap the API route with pino-http middleware to automatically log requests.
4. In the route handler, log the number of users fetched and any errors.
5. Run the server, hit the endpoint with curl, and verify that logs appear as JSON with fields event, userCount, requestId.
6. (Optional) Add a requestId middleware that injects a UUID into each log.

11. Quick revision

• Structured logs are JSON objects with fixed keys.
• Use a correlation ID to tie logs across services.
• pino is a fast Node.js logger that writes JSON to stdout.
• Log levels: debug, info, warn, error.
• Avoid logging sensitive data; sanitize before logging.
• Asynchronous, batched writers prevent blocking requests.
• Log shipping to a collector (ELK, Loki) enables search and alerting.
• Schema evolution should be versioned; use a registry.
• In production, set LOG_LEVEL=warn or error to reduce noise.
• Monitor log volume and error rates; alert on spikes.
• Use log‑based metrics for real‑time dashboards.
• Always include a timestamp, level, and event name.

12. References

• Pino – Fast Node.js logger
• Pino‑http – HTTP request logging middleware
• OpenTelemetry – Structured Logging
• ELK Stack – Log ingestion
• Loki – Grafana Loki
• Node.js Logging Best Practices