node-debug-hooked

A wrapper around the debug package that prints out an arbitrary id (requestId, contextId) from the asnyc context along with each line. It uses the cls-hooked package to follow async contexts. CLS stands for continuation local storage and is very similar to Java's ThreadLocal. cls-hooked is the implementation based on async-hooks introduced in Node.js 8.x.

Using this package, all your debug entries will be prefixed with a unique ID (e.g. HTTP request id) so you can follow the lifecycle of each incoming requests.

NOTE: right now, this package only works with Node.js 8.x+ as the compilation target is ES2017.

Usage with Express.js

The following is a small example for Express.js but you can easily refactor to other frameworks like Koa.js.

const express = require('express')
const uuidV4 = require('uuid/v4')

const cls = require("cls-hooked")
const { debugHookedFactory } = require('debug-hooked')

// request is the name of the CLS namespace that will hold the request id
const clsNamespaceName = 'request'
const ns = cls.createNamespace(clsNamespaceName)
// it wraps the debug package, you can use it the same way as the original debug package
const debugHooked = debugHookedFactory(clsNamespaceName, 'requestId')

// example express middleware that binds cls contexts to incoming requests
// based on the following example: https://clakech.github.io/cls-hooked-sample/
// ns.run() is the important part as cls namespaces only work if the starting code
// is wrapped in an ns.run() call
const clsBinder = (req, res, next) => {
  ns.bindEmitter(req)
  ns.bindEmitter(res)
  ns.run(() => {
    const requestId = req.headers['x-request-id'] || uuidV4()
    cls.getNamespace(clsNamespaceName).set('requestId', requestId)
    next()
  })
}

const app = express()
app.use(clsBinder)

// create a new wrapped debug logger. this can be used the same way as the original debug
const debug = debugHooked('sample:hello')

app.get('/hello', (req, res) => {
  debug("before")
  res.status(200).send('hello world!')
  debug("after")
})

app.listen(3000, () => {
  console.log(`server started on port 3000`)
})

Copy the code above to a javascript file (sample.js) and start it with the following command:

DEBUG=sample* node sample.js

Then call your server with the following:

curl http://localhost:3000/hello

You'll see something like this on the standard output of your server:

sample:hello [51f53654-647f-455a-8e45-91584aa31d1b] before +0ms
sample:hello [51f53654-647f-455a-8e45-91584aa31d1b] after +5ms

Usage with some simple async code

This code sample uses async-await, but can be easily refactored.

const uuidV4 = require('uuid/v4')

const cls = require("cls-hooked")
const { debugHookedFactory } = require('debug-hooked')

// request is the name of the CLS namespace that will hold the async context id
const clsNamespaceName = 'asyncCtx'
const ns = cls.createNamespace(clsNamespaceName)
// it wraps the debug package, you can use it the same way as the original debug package
const debugHooked = debugHookedFactory(clsNamespaceName, 'asyncId')
// create a new wrapped debug logger. this can be used the same way as the original debug
const debug = debugHooked('sample:asyncawait')

async function myAsyncFunction() {
  debug('myOtherAsyncFunction running')
  const res = await myOtherAsyncFunction()
  debug('myOtherAsyncFunction result:', res)
  return new Promise((resolve, reject) => {
    setTimeout(() => resolve('myAsyncFunction result'), 1000)
  })
}

async function myOtherAsyncFunction() {
  debug("myOtherAsyncFunction")
  return new Promise((resolve, reject) => {
    setTimeout(() => resolve('myOtherAsyncFunction result'), 800)
  })
}

[1, 2, 3].forEach(i => {
  // ns.run() is the important part as cls namespaces only work if the starting code is wrapped in an ns.run() call
  ns.run(async () => {
    cls.getNamespace(clsNamespaceName).set('asyncId', 'async_' + i)
    const res = await myAsyncFunction()
    debug('myAsyncFunction result:', res)
  })
})

Copy the code above to a javascript file (sample.js) and start it with the following command:

DEBUG=sample* node sample.js

You'll see something like this on the standard output:

sample:asyncawait [async_1] myOtherAsyncFunction running +0ms
sample:asyncawait [async_1] myOtherAsyncFunction +3ms
sample:asyncawait [async_2] myOtherAsyncFunction running +1ms
sample:asyncawait [async_2] myOtherAsyncFunction +0ms
sample:asyncawait [async_3] myOtherAsyncFunction running +0ms
sample:asyncawait [async_3] myOtherAsyncFunction +0ms
sample:asyncawait [async_1] myOtherAsyncFunction result: myOtherAsyncFunction result +801ms
sample:asyncawait [async_2] myOtherAsyncFunction result: myOtherAsyncFunction result +1ms
sample:asyncawait [async_3] myOtherAsyncFunction result: myOtherAsyncFunction result +1ms
sample:asyncawait [async_1] myAsyncFunction result: myAsyncFunction result +999ms
sample:asyncawait [async_2] myAsyncFunction result: myAsyncFunction result +1ms
sample:asyncawait [async_3] myAsyncFunction result: myAsyncFunction result +1ms

You can find the above Javascript code in the sample directory in async-await.js as well.