Ultimate guide to concurrent logging in Node.js

Here is a problem that everyone will recognise: logs produced by concurrent tasks are useless without their initiation context.

Roarr! The most powerful logger for Node.js.

If you need an example, consider a program that executes some code that produces logs after receiving an event. It could be an incoming HTTP request, a job queue, etc., e.g.

process.on('task', (task) => {
  executeTask(task);
});
const executeTask = async (task) => {
  try {
    // [..]
    console.log('task completed');
  } catch (error) {
    console.log('task failed');
  }
};

As it is, this program will produce logs that look like this:

task completed
task completed
task failed
task completed
task failed

The point is that, if we want to produce meaningful logs, then we have to somehow associate task with each log message.

const executeTask = async (task) => {
  try {
    await download(task.url);
    console.log({task}, 'task completed');
  } catch (error) {
    console.log({task}, 'task failed');
  }
};

The problem is that, in order to achieve this, you have to pass-down task object down to every single function that produces logs. It is easy enough to add task to console.log in our example, but usually functions that produce codes are deeply nested, or they are third-party modules and there is no way to pass additional context to the logger.

const download = (url) => {
  if ([..]) {
    return console.error('invalid url');
  }
  if ([..]) {
    return console.error('unsupported protocol');
  }
  // [..]
};

As there are no conventions for passing-down logger context, you will end up with a log trail that lists random events without providing the necessary context required to associate those events with the asynchronous task that it belongs to.

invalid url
task completed {id:6, url: [..]}
task completed {id:4, url: [..]}
unsupported protocol
task completed {id:5, url: [..]}
task completed {id:3, url: [..]}
task failed {id:2, url: [..]}
task completed
task failed {id:1, url: [..]}

The above log would not be sufficient to identify which task failed for which reason. Luckily, there is a solution.

Using Node.js Domain

Using Node.js Domain, we can add context to a chain of asynchronous calls without passing them down explicitly (think of it as a closure or Context in React), e.g.

import domain from 'domain';
process.on('task', (task) => {
  domain
    .create()
    .run(() => {
      process.domain.context = {
        task,
      };
      executeTask(task);
    });
});
const download = (url) => {
  if ([..]) {
    return console.error(process.domain.context, 'invalid url');
  }
  if ([..]) {
    return console.error(process.domain.context, 'unsupported protocol');
  }
  // [..]
};
const executeTask = async (task) => {
  try {
    await download(task.url);
    console.log({task}, 'task completed');
  } catch (error) {
    console.log({task}, 'task failed');
  }
};

This way, each log message is associated with the asynchronous context that initiated the chain of the asynchronous calls.

invalid url {id:1, url: [..]}
task completed {id:6, url: [..]}
task completed {id:4, url: [..]}
unsupported protocol {id:2, url: [..]}
task completed {id:5, url: [..]}
task completed {id:3, url: [..]}
task failed {id:2, url: [..]}
task completed {id:2, url: [..]}
task failed {id:1, url: [..]}

In theory, domains can be even nested, i.e. a domain that is aware of a parent domain could be used to associate a log message with the entire chain of asynchronous calls that led to the log message. Node.js does not provide this functionality out of the box. However, Node.js can be monkey-patched to explicitly bind parent domain to the active domain, e.g.

const domain = require('domain');
const originalCreate = domain.create;
domain.create = (...args) => {
  const parentDomain = process.domain || null;
  const nextDomain = originalCreate(...args);
  nextDomain.parentDomain = parentDomain;
  return nextDomain;
};

After which parentDomain becomes a reference to the parent domain:

const d0 = domain.create();
d0.run(() => {
  const d1 = domain.create();
  d1.run(() => {
    d1.parentDomain === d0;
  });
});

In order to use the logger that I am about to introduce, you will need to patch Node.js using domain-parent.

Domain deprecation

Several people commented that domain module is deprecated and it should not be used.

Deprecation notice.

Despite the big red banner stating that this module is deprecated — domain module is not deprecated. If you read the paragraph following the banner, it states that the module is pending deprecation once a replacement API is finalised. It is likely that async_hooks will eventually provide all functionality provided by domain module and will supersede it. Behind the scenes domain module is already implemented using async_hooks. However, it is not happening any time soon (because loads of popular NPM modules and Node.js internals depend on domain module) and until that time it safe to use domain module.

Finally, this all adds up to an introduction to a convention driven, context-aware logger that has been already developed and ready to us: Roarr.

Using Roarr

Roarr adopt method creates a domain that efficiently binds user-defined context to all log messages that will produced during the asynchronous call. In order to associate context with your asynchronous code, simply execute your routine using Roarr adopt method, e.g.

import Logger from 'roarr';
process.on('task', (task) => {
  Logger
    .adopt(
      () => {
        return executeTask(task);
      },
      // Here we define the context that we want to associate with
      // all the Roarr loggers that will be called when executing
      // `executeTask` with the current `task` value. 
      {
        task,
      }
    );
});
const download = (url) => {
  if ([..]) {
    return log.error('invalid url');
  }
  if ([..]) {
    return log.error('unsupported protocol');
  }
  // [..]
};
const executeTask = async (task) => {
  try {
    await download(task.url);
    log.info('task completed');
  } catch (error) {
    log.info('task failed');
  }
};

The above would produce log equivalent to:

invalid url {id:1, url: [..]}
task completed {id:6, url: [..]}
task completed {id:4, url: [..]}
unsupported protocol {id:2, url: [..]}
task completed {id:5, url: [..]}
task completed {id:3, url: [..]}
task failed {id:2, url: [..]}
task completed {id:2, url: [..]}
task failed {id:1, url: [..]}

Of course, in order for all logs to include their asynchronous context, all of the dependencies would need to be using Roarr logger (or they would have to read logger context from process.domain.roarr.context). However, unlike the other loggers, Roarr does not have configuration and can be used in distributable packages and top-level programs alike. As a result, there are already thousands of packages using Roarr.

In order for you to start using Roarr, read what makes Roarr the perfect logger from Node.js and have a look at example libraries that implement the logger (Slonik is a good start).

To recap:

1. Logs without context in a concurrent execution environment are meaningless.
2. Domains can be used to associated context with asynchronous call chains.
3. Roarr leverages domains to inherit context that describes the asynchronous call chain that led to the log message. This allows Roarr to produce logs that describe full execution context even when multiple tasks are executed concurrently.

Give Roarr a try. It even has a neat CLI program with a built-in pretty-print and filtering.