Structured Logging

Why Structured Logging

Unstructured log:

[2024-01-15 10:23:41] ERROR: Payment failed for order ord-123 (user usr-456): card declined

To extract order_id from this, you write regex. Multiply by 10k log lines per second. Now count how many different developers wrote how many different formats.

Structured log (JSON):

{
	"level": "error",
	"time": "2024-01-15T10:23:41Z",
	"service": "order-service",
	"order_id": "ord-123",
	"user_id": "usr-456",
	"event": "payment_failed",
	"reason": "card_declined",
	"duration_ms": 234
}

Every field is a key-value pair. Query: {service="order-service"} | json | reason="card_declined" | order_id != "" — instant, no regex.

Pino (Node.js)

Pino is the fastest Node.js logger — synchronous JSON output with minimal allocation:

import pino from 'pino';

const log = pino({
	level: process.env.LOG_LEVEL ?? 'info',
	base: {
		service: 'order-service',
		version: process.env.GIT_SHA ?? 'dev',
		env: process.env.NODE_ENV
	},
	// In development: pretty-print. In production: raw JSON.
	transport:
		process.env.NODE_ENV === 'development'
			? { target: 'pino-pretty', options: { colorize: true } }
			: undefined
});

export { log };

// Usage
log.info({ orderId, customerId }, 'Order created');
log.error({ orderId, err: err.message, stack: err.stack }, 'Order creation failed');
log.warn({ queueDepth: 500 }, 'Queue depth high');

// Child logger — inherits context
const reqLog = log.child({ requestId, userId });
reqLog.info({ orderId }, 'Processing order');
// Output: {"requestId":"...","userId":"...","orderId":"...","msg":"Processing order"}

Correlation IDs

A request passes through multiple services. To follow it across all logs, generate one ID at ingress and propagate it everywhere.

// Express middleware — generate or propagate correlation ID
import { randomUUID } from 'crypto';

app.use((req, res, next) => {
	const correlationId = (req.headers['x-correlation-id'] as string) ?? randomUUID();
	req.correlationId = correlationId;
	res.setHeader('x-correlation-id', correlationId);

	// Attach to request logger
	req.log = log.child({ correlationId, method: req.method, path: req.path });
	next();
});

// Request handler
app.post('/orders', async (req, res) => {
	req.log.info('Creating order');

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

Pass the correlation ID to downstream services:

async function callPaymentService(order: Order, log: Logger) {
	const response = await fetch('http://payment-service/charge', {
		method: 'POST',
		headers: {
			'x-correlation-id': log.bindings().correlationId,
			'content-type': 'application/json'
		},
		body: JSON.stringify(order)
	});
}

Now a single query {correlationId="abc-123"} across all services shows the complete request journey.

Log Levels

Use levels consistently — they determine what gets stored and what triggers alerts:

ERROR  — unexpected failure requiring investigation; fires an alert
WARN   — degraded state, expected to recover; may fire a low-priority alert
INFO   — significant business events (order created, user registered)
DEBUG  — diagnostic detail; disabled in production, enabled per-request when debugging
TRACE  — everything (query parameters, raw HTTP bodies); never in production

// Good level usage
log.error({ err, orderId }, 'Payment service unreachable'); // alert
log.warn({ queueDepth, threshold }, 'Queue depth approaching limit'); // investigate soon
log.info({ orderId, total }, 'Order confirmed'); // business event
log.debug({ sql, params }, 'Executing query'); // dev only

// Common mistake: ERROR for expected failures
log.error('Order not found'); // NOT_FOUND is normal — use warn or info
log.info({ orderId }, 'Order not found, returning 404'); // correct

Dynamic log levels in production:

// Change level at runtime without restart
process.on('SIGUSR1', () => {
	if (log.level === 'info') {
		log.level = 'debug';
		log.info('Debug logging enabled');
	} else {
		log.level = 'info';
		log.info('Debug logging disabled');
	}
});

Log Aggregation with Loki

Loki stores logs indexed by labels (like Prometheus, but for logs). Promtail ships logs from files or journald to Loki.

# docker-compose.yml
services:
  loki:
    image: grafana/loki:latest
    ports: ['3100:3100']
    command: -config.file=/etc/loki/loki.yml
    volumes:
      - ./loki.yml:/etc/loki/loki.yml
      - loki-data:/loki

  promtail:
    image: grafana/promtail:latest
    volumes:
      - /var/log:/var/log # host logs
      - /var/run/docker.sock:/var/run/docker.sock
      - ./promtail.yml:/etc/promtail/config.yml
    command: -config.file=/etc/promtail/config.yml

# promtail.yml — ship Docker container logs
server:
  http_listen_port: 9080

clients:
  - url: http://loki:3100/loki/api/v1/push

scrape_configs:
  - job_name: docker
    docker_sd_configs:
      - host: unix:///var/run/docker.sock
        refresh_interval: 5s
    relabel_configs:
      - source_labels: ['__meta_docker_container_name']
        target_label: container
      - source_labels: ['__meta_docker_container_label_service']
        target_label: service
    pipeline_stages:
      - json:
          expressions:
            level: level
            correlation_id: correlationId
      - labels:
          level:
          correlation_id:

journald (systemd services)

For bare-metal or VM deployments (not Docker), logs go to journald:

# All logs from a service
journalctl -u order-service -f

# Logs since yesterday
journalctl -u order-service --since yesterday

# JSON output (for parsing)
journalctl -u order-service -o json | jq '.MESSAGE | fromjson | select(.level == "error")'

# Filter by time range
journalctl -u order-service --since "2024-01-15 10:00:00" --until "2024-01-15 11:00:00"

Forward journald to Loki:

# promtail.yml — journald source
scrape_configs:
  - job_name: journal
    journal:
      max_age: 12h
      labels:
        job: systemd-journal
    relabel_configs:
      - source_labels: ['__journal__systemd_unit']
        target_label: unit

Loki Queries (LogQL)

# All errors from order-service
{service="order-service"} |= "error"

# Parse JSON and filter
{service="order-service"} | json | level="error"

# Filter by specific field
{service="order-service"} | json | order_id="ord-123"

# Count errors per minute
count_over_time({service="order-service"} | json | level="error" [1m])

# Rate of errors
rate({service="order-service"} | json | level="error" [5m])

# Top error reasons
{service="order-service"} | json | level="error"
  | line_format "{{.reason}}"
  | topk(10, count_over_time[1h])

What to Log

Log these:

• Business events (order created, payment charged, user registered)
• All errors with full context (user, resource ID, error code, message)
• Slow operations (requests > 1s, queries > 100ms)
• Security events (failed auth, permission denied, unusual access patterns)
• Service startup and shutdown

Don’t log these:

• Passwords, tokens, card numbers (PCI), personal data (GDPR)
• Successful health checks (100% noise)
• Debug-level SQL in production (volume)
• Stacktraces on expected errors (404, 401)

// Sanitize sensitive data before logging
function sanitizeOrder(order: Order) {
	return {
		...order,
		paymentMethod: { last4: order.paymentMethod.cardNumber.slice(-4) }
		// never log full card number
	};
}

log.info({ order: sanitizeOrder(order) }, 'Order created');