DEV Community

Cover image for My logging strategy for Express
Mathieu Marteau
Mathieu Marteau

Posted on

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
})
Enter fullscreen mode Exit fullscreen mode

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()
})
Enter fullscreen mode Exit fullscreen mode

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()
  ),
});
Enter fullscreen mode Exit fullscreen mode

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')
})
Enter fullscreen mode Exit fullscreen mode

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"}
Enter fullscreen mode Exit fullscreen mode

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

Top comments (1)

Collapse
 
crummy profile image
Malcolm Crum

This is such a nice pattern! Simple and really useful.