Extend logs in Node.js with unique trace ID

When number of requests to an application grows, it might be hard to read logs and group them together to one single request. This can be solved with trace ID that is unique for each request.

What you need to do

It is quite easy to implement it. You need to install cls-hooked package (there are couple of other packages) and wrap request process.

Install package:

npm install cls-hooked

# if you use yarn

yarn add cls-hooked

Add new middleware (e.g. /middlewares/trace.ts):

import { Request, Response, NextFunction } from 'express';
import { v4 as uuidv4 } from 'uuid';
import cls from 'cls-hooked';

export default function trace(req: Request, res: Response, next: NextFunction): void {
  if (req.method === 'OPTIONS') {
    next();
    return;
  }

  const namespace = cls.createNamespace('namespace');

  namespace.bind(req);
  namespace.bind(res);

  const traceId = req.query.traceId ? req.params.traceId : uuidv4();

  req['traceId'] = traceId;

  namespace.run(() => {
    namespace.set('traceId', traceId);

    next();
  });
}

Add this middleware before routes definitions:

// ...
const app = express();

app.use(express.json());
app.use(express.urlencoded({ extended: true }));
app.use(trace);

app.use(routes);
// ...

If you want to use this variable now, you can read it from the namespace and add it to your logs:

import cls from 'cls-hooked';

const namespace = cls.getNamespace('namespace');

console.log('Whatever', { traceId: namespace.get('traceId') });

Or if you use for example winston package for logging, you can enrich logs on one place with new format:

import winston, { format } from 'winston';
import namespace from '../services/cls';

const hookedFormat = format((info) => {
  const traceId = namespace.get('traceId');

  if (typeof traceId !== 'undefined') {
    info.traceId = traceId;
  }

  return info;
});

const logger = winston.createLogger({
  level: 'debug',
  transports: [
    new winston.transports.Console({
      format: winston.format.combine(
        hookedFormat(),
        winston.format.json(),
        winston.format.errors({ stack: true }),
      ),
    }),
  ],
});

export default logger;

Logs with traceId:

{"level":"debug","message":"New request", "traceId":"f93f930f-ba7e-480b-bfd3-4e1342f08af8"}
{"level":"debug","message":"Loading data from DB", "traceId":"f93f930f-ba7e-480b-bfd3-4e1342f08af8"}
{"level":"debug","message":"Response time 11.969668ms", "traceId":"f93f930f-ba7e-480b-bfd3-4e1342f08af8"}

caution

If you use multer in route, then traceId becomes undefined. This can be "fixed" by wrapping multer in a Promise and run it as middleware. You can read more in links below.

Update response

You can also return traceId to the caller in response headers as x-request-id.

Update /middlewares/trace.ts:

import { Request, Response, NextFunction } from 'express';
import { v4 as uuidv4 } from 'uuid';
import cls from 'cls-hooked';

export default function trace(req: Request, res: Response, next: NextFunction): void {
  if (req.method === 'OPTIONS') {
    next();
    return;
  }

  const namespace = cls.createNamespace('namespace');

  namespace.bind(req);
  namespace.bind(res);

  const traceId = req.query.traceId ? req.params.traceId : uuidv4();

  req['traceId'] = traceId;

  namespace.run(() => {
    namespace.set('traceId', traceId);
    res.header('x-request-id', traceId); // <-- return traceId in headers

    next();
  });
}

References

• GitHub - Continuation-Local Storage ( Hooked )
• npm - cls-hooked
• Medium - Using Multer and Cls-Hooked together
• GitHub - CLS Context is lost after using multer middleware
• GitHub - next() function not called in middleware, which breaks express-http-context (cls-hooked)