Episode 6 — Scaling Reliability Microservices Web3 / 6.7 — Logging and Observability

6.7.a -- Structured Logging

In one sentence: Structured logging means emitting log entries as machine-parseable JSON with consistent fields (timestamp, level, message, requestId, service), making logs searchable, filterable, and correlatable across microservices -- the foundation of production observability.

Navigation: <- 6.7 Overview | 6.7.b -- Monitoring and Metrics ->

1. Why Plain Text Logs Fail at Scale

In a small single-server app, console.log('User signed up') works fine. You SSH in, read the logs, and find what you need. In production microservices with 10+ services, hundreds of containers, and thousands of requests per second, plain text logs become unusable.

// Plain text -- UNSTRUCTURED
Server started on port 3000
User login successful
Error processing payment
Database connection timeout
User login successful
Error: Cannot read properties of undefined

Problems with plain text:

  • No searchable fields -- you cannot filter "show me only errors from the payment service"
  • No request correlation -- which "User login successful" belongs to which request?
  • No timestamps -- when exactly did this happen?
  • No context -- which user? Which server? Which deployment version?
  • Impossible to parse programmatically -- every log line has a different format

Structured logging solves all of this

{
  "timestamp": "2026-04-11T14:32:01.234Z",
  "level": "info",
  "message": "User login successful",
  "service": "auth-service",
  "requestId": "req-abc-123",
  "userId": "user-456",
  "method": "POST",
  "path": "/api/auth/login",
  "duration": 142,
  "ip": "192.168.1.100"
}

Now you can:

  • Filter: level=error AND service=payment-service
  • Correlate: requestId=req-abc-123 shows every log from a single request across all services
  • Aggregate: "How many login attempts per minute?"
  • Alert: "Notify me when error count > 50 in 5 minutes"

2. Log Levels

Log levels categorize the severity of each log entry. Every structured logger supports them, and using them correctly is essential for filtering signal from noise.

LevelWhen to UseExampleProduction Visibility
fatalSystem is crashing, immediate actionDatabase connection permanently lostAlways visible
errorSomething failed, needs investigationPayment charge failed, API returned 500Always visible
warnSomething unexpected but recoveredRetry succeeded on 3rd attempt, rate limit approachingVisible by default
infoNormal operations, key business eventsUser signed up, order placed, deployment startedVisible by default
debugDetailed flow for developers"Entering validateToken()", request body contentsOff in production
traceExtremely granular step-by-step"Checking cache key user:456", SQL query textOff in production

Level hierarchy

fatal > error > warn > info > debug > trace

Setting LOG_LEVEL=warn means:
  fatal  ✓  (logged)
  error  ✓  (logged)
  warn   ✓  (logged)
  info   ✗  (suppressed)
  debug  ✗  (suppressed)
  trace  ✗  (suppressed)

Golden rules for log levels

  1. error -- something broke that should not have broken
  2. warn -- something unusual that might become an error
  3. info -- things you want to see in production to understand normal flow
  4. debug -- only enable temporarily when investigating a specific issue
  5. Never log sensitive data (passwords, tokens, credit cards) at any level

3. Winston Logger for Node.js

Winston is the most popular Node.js logging library. It supports multiple transports (console, file, cloud services), log levels, and structured formatting.

Basic Winston setup

// src/config/logger.js
const winston = require('winston');

const logger = winston.createLogger({
  level: process.env.LOG_LEVEL || 'info',
  format: winston.format.combine(
    winston.format.timestamp({ format: 'YYYY-MM-DDTHH:mm:ss.SSSZ' }),
    winston.format.errors({ stack: true }),
    winston.format.json()
  ),
  defaultMeta: {
    service: process.env.SERVICE_NAME || 'api-service',
    environment: process.env.NODE_ENV || 'development',
    version: process.env.APP_VERSION || '1.0.0'
  },
  transports: [
    // Write all logs to console (structured JSON in production)
    new winston.transports.Console({
      format: process.env.NODE_ENV === 'production'
        ? winston.format.json()
        : winston.format.combine(
            winston.format.colorize(),
            winston.format.simple()
          )
    }),
    // Write error logs to a separate file
    new winston.transports.File({
      filename: 'logs/error.log',
      level: 'error',
      maxsize: 5242880,  // 5MB
      maxFiles: 5
    }),
    // Write all logs to combined file
    new winston.transports.File({
      filename: 'logs/combined.log',
      maxsize: 5242880,
      maxFiles: 10
    })
  ]
});

module.exports = logger;

Using the logger

const logger = require('./config/logger');

// Simple log
logger.info('Server started', { port: 3000 });

// Log with extra context
logger.info('User registered', {
  userId: user._id,
  email: user.email,
  plan: 'free'
});

// Log an error with stack trace
try {
  await processPayment(order);
} catch (error) {
  logger.error('Payment processing failed', {
    orderId: order._id,
    userId: order.userId,
    amount: order.total,
    error: error.message,
    stack: error.stack
  });
}

// Warn about something unusual
logger.warn('Rate limit approaching', {
  userId: user._id,
  currentCount: 95,
  limit: 100,
  windowMs: 60000
});

// Debug (only visible when LOG_LEVEL=debug)
logger.debug('Cache lookup', {
  key: `user:${userId}`,
  hit: false,
  ttl: 300
});

Output in production (JSON):

{"timestamp":"2026-04-11T14:32:01.234Z","level":"info","message":"User registered","service":"api-service","environment":"production","version":"1.0.0","userId":"user-456","email":"jane@example.com","plan":"free"}

4. Pino Logger -- The Performance Choice

Pino is significantly faster than Winston (up to 5x) because it uses a low-overhead JSON serializer. For high-throughput services, Pino is the better choice.

// src/config/logger.js (Pino version)
const pino = require('pino');

const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  // Default fields on every log
  base: {
    service: process.env.SERVICE_NAME || 'api-service',
    environment: process.env.NODE_ENV || 'development',
    version: process.env.APP_VERSION || '1.0.0'
  },
  // ISO timestamp format
  timestamp: pino.stdTimeFunctions.isoTime,
  // Pretty-print in development, JSON in production
  transport: process.env.NODE_ENV !== 'production'
    ? { target: 'pino-pretty', options: { colorize: true } }
    : undefined,
  // Redact sensitive fields
  redact: {
    paths: ['password', 'token', 'authorization', 'creditCard', 'ssn'],
    censor: '[REDACTED]'
  }
});

module.exports = logger;

Pino usage

const logger = require('./config/logger');

logger.info({ userId: 'user-456', path: '/api/orders' }, 'Order created');
logger.error({ err: error, orderId: '123' }, 'Payment failed');

// Child loggers -- add context for a specific scope
const reqLogger = logger.child({ requestId: 'req-abc-123', userId: 'user-456' });
reqLogger.info('Processing order');     // requestId and userId are automatic
reqLogger.info('Inventory checked');    // requestId and userId are automatic
reqLogger.info('Payment charged');      // requestId and userId are automatic

Winston vs Pino comparison

FeatureWinstonPino
SpeedModerate (~15K logs/sec)Fast (~75K logs/sec)
API stylelogger.info('msg', { meta })logger.info({ meta }, 'msg')
Pretty printingBuilt-inRequires pino-pretty
TransportsBuilt-in (file, console, HTTP)Via separate modules
EcosystemLarger, more integrationsGrowing, performance-focused
Best forMost applicationsHigh-throughput services
Child loggersSupportedFirst-class feature

5. Structured Log Format Standard

Every log entry in your system should contain these core fields:

{
  // --- ALWAYS PRESENT ---
  "timestamp": "2026-04-11T14:32:01.234Z",  // ISO 8601, UTC
  "level": "info",                            // fatal/error/warn/info/debug/trace
  "message": "Order created",                 // Human-readable description
  "service": "order-service",                 // Which microservice emitted this

  // --- REQUEST CONTEXT (when inside an HTTP request) ---
  "requestId": "req-abc-123",                 // Unique per request, propagated across services
  "userId": "user-456",                       // Authenticated user (if known)
  "method": "POST",                           // HTTP method
  "path": "/api/orders",                      // Request path
  "statusCode": 201,                          // Response status code
  "duration": 142,                            // Response time in ms

  // --- ENVIRONMENT ---
  "environment": "production",                // dev/staging/production
  "version": "2.3.1",                         // Application version
  "hostname": "order-svc-pod-7b4d",           // Container/host ID

  // --- BUSINESS CONTEXT (varies per event) ---
  "orderId": "order-789",
  "amount": 49.99,
  "currency": "USD"
}

Why each field matters

  • timestamp -- when did it happen (always UTC, never local time)
  • level -- severity filtering in log aggregation tools
  • message -- human-readable for quick scanning
  • service -- which microservice (essential in distributed systems)
  • requestId -- the single most important field for debugging microservices
  • userId -- who experienced the issue
  • duration -- performance monitoring from logs

6. Request ID Propagation Across Services

In a microservices architecture, a single user request might touch 5-10 services. A request ID (also called a correlation ID) is a unique identifier generated at the entry point and passed through every service in the chain.

User Request
    │
    ▼
┌─────────────────┐  requestId: req-abc-123
│   API Gateway   │──────────────────────────────────┐
└────────┬────────┘                                  │
         │ X-Request-Id: req-abc-123                 │
         ▼                                           │
┌─────────────────┐  logs: requestId=req-abc-123     │
│  Auth Service   │──────────────────────────────┐   │
└────────┬────────┘                              │   │
         │ X-Request-Id: req-abc-123             │   │
         ▼                                       │   │
┌─────────────────┐  logs: requestId=req-abc-123 │   │
│  Order Service  │─────────────────────────┐    │   │
└────────┬────────┘                         │    │   │
         │ X-Request-Id: req-abc-123        │    │   │
         ▼                                  │    │   │
┌─────────────────┐  logs: requestId=...    │    │   │
│ Payment Service │────────────────┐        │    │   │
└─────────────────┘                │        │    │   │
                                   ▼        ▼    ▼   ▼
                           ┌─────────────────────────────┐
                           │  Log Aggregation (CloudWatch │
                           │  / ELK / Datadog)            │
                           │                              │
                           │  Filter: requestId=req-abc-  │
                           │  123 shows ALL logs from     │
                           │  ALL 4 services for this     │
                           │  single request              │
                           └─────────────────────────────┘

Implementation -- Request ID middleware

// src/middleware/requestId.js
const { v4: uuidv4 } = require('uuid');

function requestIdMiddleware(req, res, next) {
  // Use incoming header (from upstream service) or generate new one
  const requestId = req.headers['x-request-id'] || `req-${uuidv4()}`;

  // Attach to request object for use in route handlers
  req.requestId = requestId;

  // Set response header so the client can reference it
  res.setHeader('X-Request-Id', requestId);

  next();
}

module.exports = requestIdMiddleware;

Propagating the request ID to downstream services

const axios = require('axios');

async function callOrderService(orderData, requestId) {
  const response = await axios.post('http://order-service:3001/api/orders', orderData, {
    headers: {
      'X-Request-Id': requestId,   // Forward the request ID
      'Authorization': `Bearer ${token}`
    }
  });
  return response.data;
}

// In a route handler
app.post('/api/checkout', async (req, res) => {
  const { requestId } = req;
  logger.info({ requestId, userId: req.user.id }, 'Checkout initiated');

  // The order service will receive the same requestId
  const order = await callOrderService(req.body, requestId);

  logger.info({ requestId, orderId: order.id }, 'Checkout completed');
  res.json(order);
});

7. Correlation IDs in Microservices

While request ID tracks a single HTTP request chain, correlation IDs can track higher-level business operations that span multiple requests.

// A user signs up -- this triggers multiple async operations
const correlationId = `signup-${uuidv4()}`;

// Step 1: Create user (sync)
logger.info({ correlationId, step: 'create-user' }, 'Creating user account');
const user = await createUser(data);

// Step 2: Send welcome email (async via queue)
await messageQueue.publish('email-queue', {
  type: 'welcome-email',
  correlationId,   // Same correlation ID in the queue message
  userId: user.id,
  email: user.email
});

// Step 3: Provision default resources (async via queue)
await messageQueue.publish('provisioning-queue', {
  type: 'setup-defaults',
  correlationId,
  userId: user.id
});

logger.info({ correlationId, userId: user.id }, 'Signup initiated');

When the email service processes the message:

// email-service/handlers/welcomeEmail.js
async function handleWelcomeEmail(message) {
  const { correlationId, userId, email } = message;

  logger.info({ correlationId, userId }, 'Sending welcome email');

  await sendEmail(email, 'Welcome!', template);

  logger.info({ correlationId, userId }, 'Welcome email sent');
}

Now searching correlationId=signup-abc-123 across all services shows the complete signup flow.

8. Log Context Enrichment

Instead of manually adding the same fields to every log call, create child loggers or use middleware to automatically enrich log context.

Express middleware for automatic log context

// src/middleware/logContext.js
const logger = require('../config/logger');

function logContextMiddleware(req, res, next) {
  // Create a request-scoped logger with automatic context
  req.log = logger.child({
    requestId: req.requestId,
    userId: req.user?.id || 'anonymous',
    method: req.method,
    path: req.originalUrl,
    ip: req.ip,
    userAgent: req.get('User-Agent')
  });

  // Log request start
  req.log.info('Request started');

  // Log request completion
  const startTime = Date.now();
  res.on('finish', () => {
    const duration = Date.now() - startTime;
    req.log.info({
      statusCode: res.statusCode,
      duration,
      contentLength: res.get('Content-Length')
    }, 'Request completed');
  });

  next();
}

module.exports = logContextMiddleware;

Usage in route handlers (clean code)

app.post('/api/orders', authenticate, async (req, res) => {
  // req.log already has requestId, userId, method, path
  req.log.info({ items: req.body.items.length }, 'Creating order');

  const order = await orderService.create(req.body);

  req.log.info({ orderId: order.id, total: order.total }, 'Order created');
  res.status(201).json(order);
});

Every log from this request automatically includes requestId, userId, method, and path without you typing them each time.

9. Sensitive Data Filtering (PII Protection)

Logs often accidentally contain personally identifiable information (PII) -- passwords, credit cards, social security numbers, API keys. This is a security and compliance risk (GDPR, HIPAA, PCI-DSS).

Pino built-in redaction

const pino = require('pino');

const logger = pino({
  level: 'info',
  redact: {
    paths: [
      'password',
      'token',
      'authorization',
      'req.headers.authorization',
      'creditCard',
      'creditCardNumber',
      'ssn',
      'socialSecurityNumber',
      'apiKey',
      'secret',
      '*.password',         // Nested password fields
      '*.token',            // Nested token fields
      'user.email',         // Redact email if needed
      'body.creditCard'     // Specific nested path
    ],
    censor: '[REDACTED]'
  }
});

// Input
logger.info({
  userId: 'user-123',
  password: 'supersecret',
  creditCard: '4111-1111-1111-1111'
}, 'User update');

// Output
// {"userId":"user-123","password":"[REDACTED]","creditCard":"[REDACTED]","msg":"User update"}

Custom sanitizer for Winston

const winston = require('winston');

const sanitizeFormat = winston.format((info) => {
  const sensitiveKeys = ['password', 'token', 'authorization', 'creditCard',
                         'ssn', 'apiKey', 'secret', 'accessToken', 'refreshToken'];

  function sanitize(obj) {
    if (typeof obj !== 'object' || obj === null) return obj;
    const sanitized = Array.isArray(obj) ? [...obj] : { ...obj };
    for (const key of Object.keys(sanitized)) {
      if (sensitiveKeys.some(sk => key.toLowerCase().includes(sk.toLowerCase()))) {
        sanitized[key] = '[REDACTED]';
      } else if (typeof sanitized[key] === 'object') {
        sanitized[key] = sanitize(sanitized[key]);
      }
    }
    return sanitized;
  }

  return sanitize(info);
});

const logger = winston.createLogger({
  format: winston.format.combine(
    sanitizeFormat(),
    winston.format.timestamp(),
    winston.format.json()
  ),
  transports: [new winston.transports.Console()]
});

What to NEVER log

Never LogWhyAlternative
Passwords / hashesSecurity breach if logs leakLog "password changed" event only
Full credit card numbersPCI-DSS violationLog last 4 digits: ****1234
Social security numbersIdentity theft riskLog "SSN verified: true/false"
API keys / tokensCredential exposureLog "token validated" event
Full request bodies (blindly)May contain any of the aboveLog specific safe fields only
Session tokensSession hijackingLog session ID prefix only
Medical recordsHIPAA violationLog "record accessed" with record ID

10. Logging Middleware for Express

A complete logging middleware setup combines request ID generation, context enrichment, and request/response logging.

// src/middleware/logging.js
const morgan = require('morgan');
const logger = require('../config/logger');

// Custom Morgan token for request ID
morgan.token('request-id', (req) => req.requestId);
morgan.token('user-id', (req) => req.user?.id || 'anonymous');

// Morgan writes to Winston stream
const morganMiddleware = morgan(
  ':request-id :method :url :status :res[content-length] - :response-time ms',
  {
    stream: {
      write: (message) => {
        logger.info(message.trim(), { source: 'morgan' });
      }
    }
  }
);

module.exports = morganMiddleware;

11. Complete Structured Logging Setup

Putting it all together -- a production-ready logging setup for an Express microservice.

// src/config/logger.js
const pino = require('pino');

const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  base: {
    service: process.env.SERVICE_NAME || 'api-service',
    env: process.env.NODE_ENV || 'development',
    version: process.env.APP_VERSION || '1.0.0'
  },
  timestamp: pino.stdTimeFunctions.isoTime,
  redact: {
    paths: ['password', 'token', 'authorization', 'creditCard', 'ssn',
            '*.password', '*.token', 'req.headers.authorization'],
    censor: '[REDACTED]'
  },
  serializers: {
    err: pino.stdSerializers.err,
    req: pino.stdSerializers.req,
    res: pino.stdSerializers.res
  },
  transport: process.env.NODE_ENV !== 'production'
    ? { target: 'pino-pretty', options: { colorize: true, translateTime: true } }
    : undefined
});

module.exports = logger;

// src/middleware/requestId.js
const { v4: uuidv4 } = require('uuid');

function requestIdMiddleware(req, res, next) {
  req.requestId = req.headers['x-request-id'] || `req-${uuidv4()}`;
  res.setHeader('X-Request-Id', req.requestId);
  next();
}

module.exports = requestIdMiddleware;

// src/middleware/httpLogger.js
const pinoHttp = require('pino-http');
const logger = require('../config/logger');

const httpLogger = pinoHttp({
  logger,
  genReqId: (req) => req.requestId,
  customLogLevel: (req, res, err) => {
    if (res.statusCode >= 500 || err) return 'error';
    if (res.statusCode >= 400) return 'warn';
    return 'info';
  },
  customSuccessMessage: (req, res) => {
    return `${req.method} ${req.originalUrl} ${res.statusCode}`;
  },
  customErrorMessage: (req, res, err) => {
    return `${req.method} ${req.originalUrl} ${res.statusCode} - ${err.message}`;
  },
  customAttributeKeys: {
    req: 'request',
    res: 'response',
    err: 'error',
    responseTime: 'duration'
  }
});

module.exports = httpLogger;

// src/app.js -- Putting it all together
const express = require('express');
const requestIdMiddleware = require('./middleware/requestId');
const httpLogger = require('./middleware/httpLogger');
const logger = require('./config/logger');

const app = express();

// Order matters: requestId first, then logging
app.use(requestIdMiddleware);
app.use(httpLogger);
app.use(express.json());

// Route example
app.post('/api/orders', async (req, res) => {
  req.log.info({ items: req.body.items?.length }, 'Creating order');

  try {
    const order = await createOrder(req.body, req.user);
    req.log.info({ orderId: order.id, total: order.total }, 'Order created');
    res.status(201).json(order);
  } catch (error) {
    req.log.error({ err: error }, 'Order creation failed');
    res.status(500).json({ error: 'Order creation failed' });
  }
});

// Global error handler
app.use((err, req, res, next) => {
  const log = req.log || logger;
  log.error({
    err,
    requestId: req.requestId,
    method: req.method,
    path: req.originalUrl
  }, 'Unhandled error');

  res.status(err.status || 500).json({
    error: 'Internal server error',
    requestId: req.requestId  // Return requestId so users can reference it
  });
});

const PORT = process.env.PORT || 3000;
app.listen(PORT, () => {
  logger.info({ port: PORT }, 'Server started');
});

Sample production log output:

{"level":"info","time":"2026-04-11T14:32:01.234Z","service":"order-service","env":"production","version":"2.3.1","requestId":"req-abc-123","request":{"method":"POST","url":"/api/orders"},"msg":"Creating order","items":3}
{"level":"info","time":"2026-04-11T14:32:01.376Z","service":"order-service","env":"production","version":"2.3.1","requestId":"req-abc-123","orderId":"ord-789","total":149.97,"msg":"Order created"}
{"level":"info","time":"2026-04-11T14:32:01.378Z","service":"order-service","env":"production","version":"2.3.1","requestId":"req-abc-123","response":{"statusCode":201},"duration":144,"msg":"POST /api/orders 201"}

12. Key Takeaways

  1. Structured (JSON) logs are non-negotiable in production -- they make logs searchable, filterable, and parseable by machines.
  2. Log levels (fatal through trace) let you control verbosity per environment -- production runs at info, debugging temporarily drops to debug.
  3. Request ID propagation is the single most valuable pattern -- it lets you trace a request through 10 services with one filter query.
  4. Pino is faster; Winston has more integrations -- both are production-ready for Node.js.
  5. Never log sensitive data -- use redaction, never log passwords, credit cards, or tokens.
  6. Log context enrichment via child loggers and middleware eliminates repetitive logging code and ensures consistency.

Explain-It Challenge

  1. Your PM says "just use console.log, logging libraries are overengineering." Explain with three concrete production scenarios why structured logging is essential.
  2. A junior developer's log says logger.info('Error happened'). What are three problems with this log line?
  3. A user reports a bug but cannot explain what happened. All you have is their request ID req-xyz-789. Walk through how you debug the issue using structured logs.

Navigation: <- 6.7 Overview | 6.7.b -- Monitoring and Metrics ->