Structured Logging — Winston, Morgan, Correlation IDs, and AsyncLocalStorage

Structured logging transforms your application’s runtime behaviour from an opaque black box into an observable, queryable stream of events. Instead of console.log("user logged in") scattered through the codebase, structured logging produces machine-readable JSON events with consistent fields — timestamp, level, request ID, user ID, duration, error details — that can be indexed, aggregated, and alerted on by a log management system. Winston is the most widely used Node.js logging library; combined with Morgan for HTTP request logging and a correlation ID middleware for distributed tracing, it provides production-grade observability.

Log Level Strategy #

Complete Winston Logging Setup #

// src/config/logger.js — production-grade Winston logger
const winston = require('winston');
const { AsyncLocalStorage } = require('async_hooks');

// ── Async context for correlation IDs ─────────────────────────────────────
const asyncLocalStorage = new AsyncLocalStorage();

function getRequestContext() {
    return asyncLocalStorage.getStore() || {};
}

// ── Custom log format ──────────────────────────────────────────────────────
const logFormat = winston.format.combine(
    winston.format.timestamp({ format: 'YYYY-MM-DDTHH:mm:ss.SSSZ' }),
    winston.format.errors({ stack: true }),  // include stack traces
    winston.format.splat(),
    winston.format.printf(({ timestamp, level, message, stack, ...meta }) => {
        const ctx     = getRequestContext();
        const context = Object.keys(ctx).length > 0 ? ctx : {};
        const entry   = {
            timestamp,
            level,
            message,
            service: process.env.SERVICE_NAME || 'taskmanager-api',
            env:     process.env.NODE_ENV || 'development',
            ...context,   // requestId, userId, method, path from AsyncLocalStorage
            ...meta,      // any additional metadata passed to the log call
        };
        if (stack) entry.error = { stack };
        return JSON.stringify(entry);
    }),
);

// ── Console format for development ────────────────────────────────────────
const devFormat = winston.format.combine(
    winston.format.colorize(),
    winston.format.timestamp({ format: 'HH:mm:ss' }),
    winston.format.printf(({ timestamp, level, message, ...meta }) => {
        const ctx   = getRequestContext();
        const reqId = ctx.requestId ? ` [${ctx.requestId.slice(0,8)}]` : '';
        const extra = Object.keys(meta).length > 0 ? ` ${JSON.stringify(meta)}` : '';
        return `${timestamp}${reqId} ${level}: ${message}${extra}`;
    }),
);

// ── Create logger ─────────────────────────────────────────────────────────
const logger = winston.createLogger({
    level:      process.env.LOG_LEVEL || (process.env.NODE_ENV === 'production' ? 'info' : 'debug'),
    transports: [
        new winston.transports.Console({
            format: process.env.NODE_ENV === 'production' ? logFormat : devFormat,
        }),
        // File transport in production (or use log aggregation service)
        ...(process.env.NODE_ENV === 'production' ? [
            new winston.transports.File({
                filename: 'logs/error.log',
                level:    'error',
                format:   logFormat,
                maxsize:  10 * 1024 * 1024,   // 10MB per file
                maxFiles: 5,
                tailable:  true,
            }),
        ] : []),
    ],
});

// ── Correlation ID middleware ─────────────────────────────────────────────
const { v4: uuidv4 } = require('uuid');

function correlationMiddleware(req, res, next) {
    const requestId = req.headers['x-request-id'] || uuidv4();
    res.setHeader('X-Request-ID', requestId);

    // Store context in AsyncLocalStorage — automatically available in all async code
    asyncLocalStorage.run({
        requestId,
        userId: null,   // populated after auth middleware
    }, () => {
        next();
    });
}

// Set userId after auth middleware
function setLogUser(req) {
    const store = asyncLocalStorage.getStore();
    if (store && req.user?.sub) {
        store.userId = req.user.sub;
    }
}

module.exports = { logger, correlationMiddleware, setLogUser, asyncLocalStorage };

// ── HTTP request logging with Morgan ─────────────────────────────────────
// src/config/morgan.js
const morgan = require('morgan');
const { logger } = require('./logger');

const stream = {
    write: (message) => {
        logger.http(message.trim());
    },
};

const morganFormat = ':method :url :status :res[content-length] - :response-time ms';

// Skip health check logs (too noisy)
const skip = (req) => req.url === '/api/v1/health';

module.exports = morgan(morganFormat, { stream, skip });

// ── App integration ───────────────────────────────────────────────────────
// src/app.js
const app = require('express')();
const { correlationMiddleware, setLogUser, logger } = require('./config/logger');
const morganMiddleware = require('./config/morgan');

app.use(correlationMiddleware);   // must be first
app.use(morganMiddleware);

// After auth middleware, set user ID in log context
app.use((req, res, next) => {
    if (req.user) setLogUser(req);
    next();
});

// Example structured log in a route handler
app.post('/api/v1/tasks', async (req, res) => {
    const start = Date.now();
    try {
        const task = await Task.create({ ...req.body, user: req.user.sub });
        logger.info('Task created', {
            taskId:   task._id,
            userId:   req.user.sub,
            priority: task.priority,
            duration: Date.now() - start,
        });
        res.status(201).json({ success: true, data: task });
    } catch (err) {
        logger.error('Task creation failed', {
            error:    { message: err.message, code: err.code },
            userId:   req.user?.sub,
            body:     { title: req.body.title },  // sanitised — no sensitive fields
            duration: Date.now() - start,
        });
        throw err;
    }
});

// ── Global error logger ───────────────────────────────────────────────────
app.use((err, req, res, next) => {
    logger.error('Unhandled request error', {
        error:  { message: err.message, stack: err.stack, statusCode: err.statusCode },
        method: req.method,
        path:   req.path,
        userId: req.user?.sub,
    });
    // respond...
});

// Process-level error logging
process.on('unhandledRejection', (reason) => {
    logger.error('Unhandled promise rejection', {
        error: { message: reason?.message, stack: reason?.stack },
    });
});

process.on('uncaughtException', (err) => {
    logger.error('Uncaught exception — shutting down', {
        error: { message: err.message, stack: err.stack },
    });
    process.exit(1);
});

How It Works #

Step 1 — AsyncLocalStorage Propagates Context Without Passing It Explicitly #

AsyncLocalStorage provides a way to store data that is automatically available to all async code within a context. When asyncLocalStorage.run({ requestId }, callback) is called in the middleware, the store is accessible via asyncLocalStorage.getStore() in every function called within that middleware chain — including Mongoose query callbacks, downstream service calls, and error handlers. This enables automatic request ID inclusion in all log entries without passing the ID through every function call.

Step 2 — JSON Format Enables Log Aggregation and Querying #

JSON-formatted logs can be indexed by field in Elasticsearch, queried with CloudWatch Insights, parsed by Datadog, or processed by any log aggregation tool. A query like { "requestId": "abc-123" } retrieves every log entry from a specific request. { "level": "error", "userId": "user-456" } shows all errors encountered by a specific user. This querying capability turns logs from a stream of text into a structured audit trail.

Step 3 — Morgan Logs HTTP Requests to Winston #

Morgan is an HTTP request logger middleware. By providing a custom stream that writes to logger.http(), Morgan’s output goes through Winston’s transport chain rather than directly to stdout. This means HTTP request logs are formatted consistently with application logs, include the correlation ID from AsyncLocalStorage, and are routed to the same log aggregation destination. The skip function prevents health check polling (every 30 seconds) from flooding the logs.

Step 4 — Structured Error Logging Enables Alerting #

Including a consistent error object structure in all error logs ({ message, stack, code, statusCode }) allows log aggregation tools to extract error metrics automatically. Datadog can create an alert when level=error events exceed 10 per minute. Elasticsearch can aggregate by error.message to find the most common error types. CloudWatch Metric Filters can count errors and publish them to dashboards. None of this is possible with unstructured console.error messages.

Step 5 — Process-Level Handlers Catch All Errors #

unhandledRejection fires when a Promise rejection is not caught. uncaughtException fires when an error is thrown outside a try-catch. Both are global last-resort handlers. The uncaught exception handler logs the error and calls process.exit(1) — the application cannot continue safely after an unexpected exception. Log aggregation alerts on uncaughtException entries trigger on-call notifications for immediate investigation.

Common Mistakes #

Mistake 1 — Logging sensitive data #

❌ Wrong — password and token in logs:

logger.info('Login attempt', { body: req.body });
// Logs: { "body": { "email": "user@example.com", "password": "MyPassword123!" } }

✅ Correct — only log non-sensitive fields:

logger.info('Login attempt', { email: req.body.email });
// Logs: { "email": "user@example.com" } — no password

Mistake 2 — Using console.log instead of the structured logger #

❌ Wrong — unstructured, no correlation ID, no log level:

console.log('Task created:', task._id);
// Output: "Task created: 64a1..."  — no timestamp, no request ID, no level

✅ Correct — structured logger with context:

logger.info('Task created', { taskId: task._id, userId: req.user.sub });
// Output: { "timestamp": "...", "level": "info", "requestId": "...", ... }

Mistake 3 — Debug logging enabled in production #

❌ Wrong — debug logs slow down the application and leak internal details:

const logger = winston.createLogger({ level: 'debug' });
// In production: logs every MongoDB query, every function call — performance hit!

✅ Correct — use environment-controlled log level:

const logger = winston.createLogger({
    level: process.env.LOG_LEVEL || (process.env.NODE_ENV === 'production' ? 'info' : 'debug'),
});

Quick Reference #