Skip to content
BSWEN
Blog

How to Set Up Structured Logging in Node.js with Winston (JSON Logs + Correlation IDs)

Cowrie
Cowrie
Dev @ Bswen

Purpose

This post demonstrates how to implement structured logging in Node.js using Winston with JSON format and correlation IDs for request tracing.

Environment

  • Node.js 20.x
  • Winston 3.x
  • Express.js 4.18.x
  • uuid 9.x
  • npm 10.x

The Problem

When I deployed my first Node.js API to production, I used console.log for debugging. This worked fine in development, but when something broke in production at 2 AM, I found myself SSH’d into a server, running tail -f on log files, and helplessly grepping for keywords.

Here’s what my logging looked like:

src/routes/users.js
app.post('/api/users', async (req, res) => {
  console.log('Creating user');
  console.log('Request body:', req.body);


  try {
    const user = await createUser(req.body);
    console.log('User created:', user.id);
    res.json(user);
  } catch (error) {
    console.log('Error creating user:', error);
    res.status(500).json({ error: 'Internal server error' });
  }
});

This approach had several problems:

  1. Unstructured text: Logs were free-form text, impossible to query programmatically.
  2. No context: Each log line was isolated. I couldn’t trace a single request through multiple log entries.
  3. No timestamps: console.log doesn’t add timestamps by default.
  4. Lost in noise: With multiple instances running, finding relevant logs was like finding a needle in a haystack.

When a user reported that “the API returned 500 yesterday around 3 PM”, I spent two hours grepping through log files, trying to find the relevant error. I knew there had to be a better way.

The Solution

I discovered structured logging - outputting logs as JSON objects with consistent fields. Combined with correlation IDs for request tracing, this transformed debugging from a nightmare into a straightforward query.

Method 1: Basic Winston Logger with JSON Format

I started by replacing console.log with Winston:

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


const logger = winston.createLogger({
  level: process.env.LOG_LEVEL || 'info',
  format: winston.format.combine(
    winston.format.timestamp(),
    winston.format.errors({ stack: true }),
    winston.format.json()
  ),
  defaultMeta: {
    service: 'user-service',
    environment: process.env.NODE_ENV || 'development'
  },
  transports: [
    new winston.transports.Console(),
    new winston.transports.File({
      filename: 'logs/error.log',
      level: 'error'
    }),
    new winston.transports.File({
      filename: 'logs/combined.log'
    })
  ]
});


module.exports = logger;

Now my logs looked like this:

{"level":"info","message":"User created","service":"user-service","environment":"production","timestamp":"2024-01-15T10:30:00.000Z","userId":"123","email":"[email protected]"}

Instead of console.log, I used:

src/routes/users.js
const logger = require('../utils/logger');


app.post('/api/users', async (req, res) => {
  logger.info('Creating user', {
    email: req.body.email
  });


  try {
    const user = await createUser(req.body);
    logger.info('User created', {
      userId: user.id,
      email: user.email
    });
    res.json(user);
  } catch (error) {
    logger.error('Failed to create user', {
      email: req.body.email,
      error: error.message,
      stack: error.stack
    });
    res.status(500).json({ error: 'Internal server error' });
  }
});

This was better - I now had structured JSON with timestamps and metadata. But I still couldn’t trace a single request across multiple log entries.

Method 2: Correlation IDs for Request Tracing

I added correlation IDs - unique identifiers attached to each request and included in every log entry for that request:

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


const correlationMiddleware = (req, res, next) => {
  // Use existing correlation ID from headers (for distributed tracing)
  // or generate a new one
  const correlationId = req.headers['x-correlation-id'] || uuidv4();


  // Store in request for use throughout request lifecycle
  req.correlationId = correlationId;


  // Add to response headers for client tracking
  res.setHeader('x-correlation-id', correlationId);


  next();
};


module.exports = correlationMiddleware;

Then I created a logger that automatically includes the correlation ID:

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


const baseLogger = winston.createLogger({
  level: process.env.LOG_LEVEL || 'info',
  format: winston.format.combine(
    winston.format.timestamp(),
    winston.format.errors({ stack: true }),
    winston.format.json()
  ),
  defaultMeta: {
    service: 'api-server',
    version: '1.0.0'
  },
  transports: [
    new winston.transports.Console()
  ]
});


// Create a child logger with correlation ID
const createRequestLogger = (correlationId) => {
  return baseLogger.child({ correlationId });
};


module.exports = { baseLogger, createRequestLogger };

Now I attached the logger to each request:

src/middleware/requestLogger.js
const { createRequestLogger } = require('../utils/logger');


const requestLoggerMiddleware = (req, res, next) => {
  req.logger = createRequestLogger(req.correlationId);


  req.logger.info('Incoming request', {
    method: req.method,
    path: req.path,
    query: req.query
  });


  next();
};


module.exports = requestLoggerMiddleware;

And my routes became cleaner:

src/routes/users.js
app.get('/api/users/:id', async (req, res) => {
  req.logger.info('Fetching user', { userId: req.params.id });


  try {
    const user = await getUser(req.params.id);
    req.logger.info('User fetched successfully', { userId: user.id });
    res.json(user);
  } catch (error) {
    req.logger.error('Failed to fetch user', {
      userId: req.params.id,
      error: error.message
    });
    res.status(500).json({ error: 'Failed to fetch user' });
  }
});

Now all log entries for a single request shared the same correlation ID:

{"level":"info","message":"Incoming request","correlationId":"a1b2c3d4-...","method":"GET","path":"/api/users/123","timestamp":"2024-01-15T10:30:00.000Z"}
{"level":"info","message":"Fetching user","correlationId":"a1b2c3d4-...","userId":"123","timestamp":"2024-01-15T10:30:00.050Z"}
{"level":"info","message":"User fetched successfully","correlationId":"a1b2c3d4-...","userId":"123","timestamp":"2024-01-15T10:30:00.100Z"}

To find all logs for that request, I just searched for correlationId: "a1b2c3d4-...".

Method 3: Complete Express Integration

I combined everything into a complete logging setup:

src/app.js
const express = require('express');
const { baseLogger, createRequestLogger } = require('./utils/logger');
const correlationMiddleware = require('./middleware/correlation');


const app = express();


// Apply correlation ID middleware first
app.use(correlationMiddleware);


// Request logging middleware
app.use((req, res, next) => {
  const startTime = Date.now();
  req.logger = createRequestLogger(req.correlationId);


  // Log request
  req.logger.info('Request started', {
    method: req.method,
    path: req.path,
    query: req.query,
    userAgent: req.headers['user-agent'],
    ip: req.ip
  });


  // Log response on finish
  res.on('finish', () => {
    const duration = Date.now() - startTime;
    req.logger.info('Request completed', {
      method: req.method,
      path: req.path,
      statusCode: res.statusCode,
      duration: `${duration}ms`
    });
  });


  next();
});


app.use(express.json());


// Routes
app.get('/api/health', (req, res) => {
  req.logger.info('Health check');
  res.json({ status: 'healthy' });
});


// Error logging middleware (must be last)
app.use((err, req, res, next) => {
  req.logger.error('Request failed', {
    error: err.message,
    stack: err.stack,
    method: req.method,
    path: req.path
  });


  res.status(500).json({
    success: false,
    error: 'Internal server error',
    correlationId: req.correlationId
  });
});


app.listen(3000, () => {
  baseLogger.info('Server started', { port: 3000 });
});

Now every request had:

  • A unique correlation ID
  • Start and end timestamps
  • Duration tracking
  • Automatic error logging

Method 4: Environment-Specific Formats

I wanted human-readable logs in development but JSON in production:

src/utils/logger.js
const winston = require('winston');
const { combine, timestamp, printf, colorize, json } = winston.format;


// Development format (human-readable)
const devFormat = printf(({ level, message, timestamp, ...metadata }) => {
  const meta = Object.keys(metadata).length ? JSON.stringify(metadata, null, 2) : '';
  return `${timestamp} [${level}]: ${message} ${meta}`;
});


// Production format (JSON)
const prodFormat = combine(
  timestamp(),
  winston.format.errors({ stack: true }),
  json()
);


// Create logger based on environment
const logger = winston.createLogger({
  level: process.env.LOG_LEVEL || 'info',
  format: process.env.NODE_ENV === 'production' ? prodFormat : combine(
    colorize(),
    timestamp(),
    devFormat
  ),
  defaultMeta: {
    service: process.env.SERVICE_NAME || 'app',
    environment: process.env.NODE_ENV || 'development'
  },
  transports: [
    new winston.transports.Console()
  ]
});


// Add file transport in production
if (process.env.NODE_ENV === 'production') {
  logger.add(new winston.transports.File({
    filename: 'logs/error.log',
    level: 'error'
  }));


  logger.add(new winston.transports.File({
    filename: 'logs/combined.log'
  }));
}


module.exports = logger;

In development, logs looked like this:

2024-01-15T10:30:00.000Z [info]: Incoming request {
  "method": "GET",
  "path": "/api/users/123",
  "correlationId": "a1b2c3d4-..."
}

In production, they were pure JSON for log aggregation systems.

Method 5: Advanced Context with AsyncLocalStorage

For services where passing req.logger everywhere was cumbersome, I used Node’s AsyncLocalStorage:

src/utils/contextLogger.js
const winston = require('winston');
const { AsyncLocalStorage } = require('async_hooks');
const { v4: uuidv4 } = require('uuid');


const asyncLocalStorage = new AsyncLocalStorage();


// Enhanced logger with automatic context
class ContextLogger {
  constructor(baseLogger) {
    this.logger = baseLogger;
  }


  getCorrelationId() {
    const store = asyncLocalStorage.getStore();
    return store?.correlationId;
  }


  log(level, message, meta = {}) {
    const correlationId = this.getCorrelationId();
    this.logger.log(level, message, {
      ...meta,
      correlationId
    });
  }


  info(message, meta) { this.log('info', message, meta); }
  error(message, meta) { this.log('error', message, meta); }
  warn(message, meta) { this.log('warn', message, meta); }
  debug(message, meta) { this.log('debug', message, meta); }
}


// Middleware to set up async context
const contextMiddleware = (req, res, next) => {
  const correlationId = req.headers['x-correlation-id'] || uuidv4();
  res.setHeader('x-correlation-id', correlationId);


  asyncLocalStorage.run({ correlationId }, () => {
    next();
  });
};


// Base logger setup
const baseLogger = winston.createLogger({
  level: 'info',
  format: winston.format.combine(
    winston.format.timestamp(),
    winston.format.errors({ stack: true }),
    winston.format.json()
  ),
  transports: [new winston.transports.Console()]
});


const logger = new ContextLogger(baseLogger);


module.exports = { logger, contextMiddleware };

Now I could use logger anywhere without passing request objects:

src/services/userService.js
const { logger } = require('../utils/contextLogger');


class UserService {
  async createUser(userData) {
    logger.info('Creating user', { email: userData.email });


    try {
      const user = await this.db.insert(userData);


      logger.info('User created successfully', {
        userId: user.id,
        email: user.email
      });


      return user;
    } catch (error) {
      logger.error('Failed to create user', {
        email: userData.email,
        error: error.message,
        stack: error.stack
      });


      throw error;
    }
  }
}

The correlation ID automatically propagated through the async call stack.

How It Works

The power of structured logging becomes apparent when you need to query logs:

// Example structured log:
{"level":"error","message":"Database connection failed","timestamp":"2024-01-15T03:23:45.123Z","correlationId":"abc-123","service":"user-api","error":"Connection timeout"}

With a log aggregation system (ELK, Splunk, CloudWatch, Datadog), I can query:

  • All errors in the last hour: level: "error" AND timestamp: [now-1h TO now]
  • Trace a specific request: correlationId: "abc-123"
  • Find failed user creations: message: "Failed to create user" AND level: "error"
  • Find slow requests: duration: >1000
  • Service health: service: "user-api" AND level: "error" | stats count by error

This is the difference between a 5-minute fix and a 2-hour debugging session.

Common Mistakes

I made several mistakes while implementing structured logging:

1. Logging sensitive data

I initially logged full request bodies, including passwords. I had to add sanitization:

const sanitize = (body) => {
  const { password, ...safe } = body;
  return safe;
};


logger.info('Request received', { body: sanitize(req.body) });

2. Not setting log levels appropriately

I logged everything at info level, which flooded production logs. I learned to use:

  • debug: Detailed diagnostic info
  • info: General operational events
  • warn: Unexpected but recoverable issues
  • error: Failures requiring attention

3. Losing context in error handlers

When I caught errors and re-threw them, I lost the original stack trace. Winston’s errors({ stack: true }) format option helped preserve stack traces.

4. Ignoring log rotation

In production, log files grew without bound until they filled the disk. I added log rotation with winston-daily-rotate-file:

const DailyRotateFile = require('winston-daily-rotate-file');


logger.add(new DailyRotateFile({
  filename: 'logs/application-%DATE%.log',
  datePattern: 'YYYY-MM-DD',
  maxSize: '20m',
  maxFiles: '14d'
}));

Why This Matters

Structured logging transformed my production debugging:

  1. Fast incident response: When something breaks at 3 AM, I can query logs by correlation ID, error type, or time range instead of grepping text files.

  2. Request tracing: A single correlation ID shows the complete journey of a request through my system.

  3. Context preservation: Every log includes relevant metadata automatically, no more “what was the user ID again?”

  4. Integration ready: JSON format works with ELK, Splunk, CloudWatch, Datadog, and any other log aggregation system.

  5. Proactive monitoring: I can set up alerts on error patterns instead of waiting for user complaints.

The insight from production experience: developers don’t appreciate structured logs until something breaks in production. Once you’ve debugged a production incident with structured logs versus without, you’ll never go back to console.log.

Summary

In this post, I showed how to implement structured logging in Node.js using Winston with JSON format and correlation IDs. The key insight is that structured logs transform debugging from “searching through text files” to “querying structured data.”

Start with basic Winston JSON logging, add correlation IDs for request tracing, and consider AsyncLocalStorage for automatic context propagation. Your future self debugging a 3 AM production incident will thank you.

Final Words + More Resources

My intention with this article was to help others share my knowledge and experience. If you want to contact me, you can contact by email: Email me

Here are also the most important links from this article along with some further resources that will help you in this scope:

Oh, and if you found these resources useful, don’t forget to support me by starring the repo on GitHub!

Comments

Tags: