Improved Node.js logging for async code

We’ve taken a look in part 1 at how we can reason about Node.js code in terms of coroutines to get better code structure and make use of concurrency constructs similar to those of Golang. In this part we will look at what we need to add to support logging ids for async calls in Node.js similar to getting the ID of the current thread in Java.

The following simple approaches yield logs that allow us to correlate all logging statements that happen within the context of the same async call.

General case

Let’s assume we have a function

runWithContinuationId(id: string, f: () => Promise<any>) where id is the id of the async function execution that will show up in the logs and f is the async function to be executed.

full code here

;(async () => {
  for (let i = 0; i < MAX_CONCURRENT_REQUESTS; i++) {

    // launch async call with logging id
    log.runWithContinuationId(`consumer${i}`, async () => {
      while (true) {
        try {
          log.info(`Looking for work..`)
          const target = await asyncChan.read()
          const prices = await fetchPrices(target.from, target.to)
          console.log(`1 ${target.from} = ${JSON.stringify(prices)}`)
          log.info(`Done processing target ${JSON.stringify(target)}`)
        } catch (e) {
          log.error(`Failed to process value with ${e.stack}`)
        }
      }
    })
  }
})()

This will yield a log looking as such:

info: Looking for work.. {"timestamp":"2019-03-24 00:21:13","continuationId":"consumer0"}

info: Done processing target {"from":"ETH","to":"EUR,USD"} {"timestamp":"2019-03-24 00:21:14","continuationId":"consumer0"}

Which allows you to easily correlate all logs that happened within 1 async call. This kind of identifier is common-place in logging libraries for other environments such as Java or Python, where the thread id can be easily added to the log entry, but for Node.js it needs a tad more boilerplate.

Here’s a a way to setup this to work with the winston logger. if no id is specified, it defaults to a randomly generated id as a uuidv4.

full code here

const winston = require('winston')
const getNamespace = require('cls-hooked').getNamespace
const createNamespace = require('cls-hooked').createNamespace
const uuidv4 = require('uuid/v4')

const LOGGING_NAMESPACE_NAME = 'abb51eaa-749b-475c-9cba-8d7fa05b769f'
const CONTINUATION_ID_VAR_NAME = 'continuationId'

let loggingSession = getNamespace(LOGGING_NAMESPACE_NAME)
if (!loggingSession) {
  loggingSession = createNamespace(LOGGING_NAMESPACE_NAME)
}

function runWithContinuationId(value, f) {
  if (!value) {
    value = uuidv4()
  }
  let returnValue = null
  loggingSession.run(() => {
    loggingSession.set(CONTINUATION_ID_VAR_NAME, value)
    returnValue = f()
  })
  return returnValue
}

const continuationIdFormat = winston.format((info, opts) => {
  const continuationId = loggingSession.get(CONTINUATION_ID_VAR_NAME)
  info.continuationId = continuationId
  return info
})

const logger = winston.createLogger({
  format: winston.format.combine(winston.format.json(), winston.format.timestamp({
    format: 'YYYY-MM-DD HH:mm:ss'
  }), continuationIdFormat()),
  transports: [
    new winston.transports.Console({
      format: winston.format.combine(winston.format.simple(), winston.format.timestamp({
        format: 'YYYY-MM-DD HH:mm:ss'
      }), continuationIdFormat()),
      level: 'info',
      handleExceptions: true
    })
  ],
  exitOnError: false
})

logger.runWithContinuationId = runWithContinuationId
module.exports = logger

The code above makes use of the library cls-hooked to ensure there is continuation local context passed from caller to callee starting at from the root function called with runWithContinuationId. This is akin to ThreadLocal storage in Java.

Request id logging in Express

A more specific use case is the logging of a request id for each request handled by your web server, in this case if we are using the Express framework. Because the use case is more specific, we can take a simpler approach as such:

full code here

const express = require('express')
const uuid = require('uuid')
const httpContext = require('express-http-context')
const log = require('./expressLogging')

const app = express()

app.use(httpContext.middleware)
// Run the context for each request. Assign a unique identifier to each request
app.use((req, res, next) => {
  httpContext.set('reqId', uuid.v1())
  next()
})

app.use('/hello/:name', async (req, res) => {
  log.info(`Responding to hello from ${req.params.name}`)
  res.json({hello: req.params.name})
})

const port = 3000
app.listen(port)

This yields a log such as:

info: Responding to hello from dan {"timestamp":"2019-04-13T07:40:15.889Z","reqId":"60fd9900-5dbf-11e9-a413-5be45196053c"}

To achieve this type of logging, we can make use of the express-http-context and winston libraries. Here’s the implementation for the local ./expressLogging module:

full code here

const httpContext = require('express-http-context')
const winston = require('winston')

const requestIdFormat = winston.format((info, opts) => {
  const reqId = httpContext.get('reqId')
  info.reqId = reqId
  return info
})

const logger = winston.createLogger({
  format: winston.format.combine(winston.format.simple(), winston.format.timestamp(), requestIdFormat()),
  transports: [
    new winston.transports.Console({
      format: winston.format.combine(winston.format.simple(), winston.format.timestamp()),
      level: 'info',
      handleExceptions: true
    })
  ],
  exitOnError: false
})

module.exports = logger

• ← Previous Post
• Next Post →