My logging strategy for Express
Tags: node, javascript, api
Published: 2023-01-05 12:19:53

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](https://nodejs.org/api/async_context.html#class-asynclocalstorage) to the rescue!

`AsyncLocalStorage` allows to identify a specific chaining of operations. 

Here is how it basically works:

```js
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:

```js
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`
```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:

```js
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