My logging strategy for Express

Logging has sometimes been a nightmare with my NodeJS applications.

Sometimes I get error logs and I'd like to find all the logs of a specific request.

Here comes AsyncLocalStorage to the rescue!

AsyncLocalStorage allows to identify a specific chaining of operations.

Here is how it basically works:

import { AsyncLocalStorage } from 'node:async_hooks';

const storage = new AsyncLocalStorage()

storage.run('abc', () => {
  const id = storage.getStore();
  console.log(id) // abc
})

Ok, so you might be wondering what the hell I'm trying to tell you. Just look at the code right now, try it at home and you'll notice that the console outputs abc.

Now, let's see the magic of AsyncLocalStorage and add an other function on the top level of your app. Log again and see:

import { AsyncLocalStorage } from 'node:async_hooks';

const storage = new AsyncLocalStorage()

const someOtherFunction = () => {
  const id = storage.getStore();
  console.log(id) // abc
}

storage.run('abc', () => {
  someOtherFunction()
})

See the magic? Even if someOtherFunction is called on the top level, the storage object is aware that it comes from storage.run('abc', ...).

This is really helpful for building a good logging strategy for Express.

I'll be using the winston package with express and create a middleware in order to configure my logger:

logger.js

import winston from 'winston'
import {v4 as uuid} from 'uuid'
import { AsyncLocalStorage } from 'node:async_hooks';

// Initialize an asyncLocalStorage to trace logs down to a specific request.
const asyncLocalStorage = new AsyncLocalStorage();

// Create a winston format to add the traceId information based on asyncLocalStorage
// This function will be run at each log entry.
const uuidFormat = winston.format((info, opts) => {
  return {
    ...info,
    traceId: asyncLocalStorage.getStore()
  }
})

// Define a middleware and wrap the next() function into 
// the asyncLocalStorage.run() in order to initialize tracing
// of the request
export const loggerMiddleware = (req, res, next) => {
  asyncLocalStorage.run(uuid(), () => {
    next()
  })
}

// Create a logger using our uuidFormat to inject our traceId into logs
export const logger = winston.createLogger({
  level: 'debug',
  transports: [
    new winston.transports.Console()
  ],
  format: winston.format.combine(
    winston.format.timestamp(),
    uuidFormat(),
    winston.format.json()
  ),
});

We can now enjoy our excellent logger in express really easily:

import express from 'express'
import { loggerMiddleware, logger } from './logger.js'

logger.debug('hello world!')

const app = express()

// Use the middleware we just created
app.use(loggerMiddleware)

app.get('/', async (req, res) => {
  logger.debug('In a request!')
  res.send({
    status: 'ok'
  })
})

app.listen(3000, () => {
  console.log('Listening to http://localhost:3000')
})

When making a request to http://localhost:3000, you'll notice the following log appearing on your server:

{"level":"debug","message":"In a request!","timestamp":"2023-01-05T12:07:52.289Z","traceId":"b68ab53c-aa14-47a1-a4ac-b9066375781d"}

Tell me in the comments if you found this helpful or if you didn't get the why I wrote this article, I'll be happy to respond!

Have a nice day

Blog

My logging strategy for Express

Mathieu Marteau

Join Our Newsletter. No Spam, Only the good stuff.

Related