process

Good logging

How to print from your Node programs in formats compatible with 3rd party logging tools.

Logging is hard. Here is my advice:

Use debug module.

Module debug is extremely useful because it allows to dynamically turn on messages from various modules. All my NPM modules use it with convention DEBUG='module name' to turn on messages for a particular module.

index.js
1
2
3
const debug = require('debug')('foo')
const x = 42
debug('x =', x)

By default the above program prints nothing. But if we turn on debug logging for module foo we see one log line

1
2
$ DEBUG=foo node .
  foo x = 42 +0ms

By default, if the terminal supports it, debug uses terminal colors to highlight log messages coming from different files, making visual scanning the logs a breeze.

Format statements

Instead of letting debug or console.log pick the "best" representation of the arguments, explicitly set the format for each. For example:

index.js
1
2
3
4
const debug = require('debug')('foo')
const x = 42.123
// prints "x" as an integer
debug('x = %i', x)
1
2
$ DEBUG=foo node .
  foo x = 42 +0ms

Main format placeholders to remember (see Node documentation):

  • %s - String.
  • %d - Number (integer or floating point value).
  • %i - Integer.
  • %f - Floating point value.
  • %j - JSON. Replaced with the string '[Circular]' if the argument contains circular references.
  • %o - Object. A string representation of an object with generic JavaScript object formatting.

If in doubt - use %j to print value serialized as JSON.

index.js
1
2
3
const debug = require('debug')('foo')
const x = {foo: {bar: 'baz'}}
debug('x = %j', x)
1
2
$ DEBUG=foo node .
  foo x = {"foo":{"bar":"baz"}} +0ms

Another format I like is %o that outputs argument as a JavaScript object, which to me is easier to quickly scan.

index.js
1
2
3
const debug = require('debug')('foo')
const x = {foo: {bar: 'baz'}}
debug('x = %o', x)
1
2
$ DEBUG=foo node .
  foo x = { foo: { bar: 'baz' } } +0ms

Control the nesting depth

If an object has properties nested deeper than default threshold, %o serialization can cut it off

index.js
1
2
3
const debug = require('debug')('foo')
const x = {foo: {bar: {q: {x: {y: 'baz'}}}}}
debug('x = %o', x)
1
2
$ DEBUG=foo node .
  foo x = { foo: { bar: { q: [Object] } } } +0ms

Luckily, debug module can read environment variable DEBUG_DEPTH to control the depth threshold

1
2
$ DEBUG=foo DEBUG_DEPTH=10 node .
  foo x = { foo: { bar: { q: { x: { y: 'baz' } } } } } +0ms

Do not use console.log

So console.log has a problem with %o - it does not override depth threshold using an environment variable, and also it does NOT print the entire message on a single line. I will make the property names artificially long to show the problem

index.js
1
2
3
4
const debug = require('debug')('foo')
const x = {thisIsPropertyFoo: {thisIsPropertyBar: {thisIsPropertyQ: {thisIsPropertyX: {y: 'baz'}}}}}
debug('x = %o', x)
console.log('x = %o', x)

Compare the first message from debug to the second message from console.log

1
2
3
4
$ DEBUG=foo DEBUG_DEPTH=10 node .
  foo x = { thisIsPropertyFoo: { thisIsPropertyBar: { thisIsPropertyQ: { thisIsPropertyX: { y: 'baz' } } } } } +0ms
x = { thisIsPropertyFoo:
   { thisIsPropertyBar: { thisIsPropertyQ: { thisIsPropertyX: { y: 'baz' } } } } }

Notice how console.log has split the output into 2 lines. This is bad for external logging tools - because they will treat separate lines as separate messages, breaking context and search.

Replace console.log with debug

There are two differences between console.log and debug. First, debug by default writes to STDERR stream, while console.log writes to STDOUT stream. This usually is not very crucial.

Second, console.log messages are ON by default, while debug messages are only enabled via an environment variable (or programmatically). Thus we need a way to always print some messages using debug API. Luckily this is easy to do.

index.js
1
2
3
4
5
const debug = require('debug')('foo')
const alwaysLog = require('debug')('*')
const x = {foo: {bar: 'baz'}}
debug('x = %o', x)
alwaysLog('value x = %o', x)

Running with DEBUG=foo environment variable prints everything

1
2
3
$ DEBUG=foo node .
  foo x = { foo: { bar: 'baz' } } +0ms
  * value x = { foo: { bar: 'baz' } } +0ms

Running without DEBUG environment variable prints the second message only

1
2
$ node .
  * value x = { foo: { bar: 'baz' } } +0ms

Log details under namespace

In addition to module messages, you can log details useful to debugging using namespaces. For example

index.js
1
2
3
4
5
const debug = require('debug')('foo')
const debugX = require('debug')('foo:x')
const x = {foo: {bar: 'baz'}}
debugX('value x = %o', x)
debug('have x')

By default we log high level debug messages only

1
2
$ DEBUG=foo node .
  foo have x +0ms

But if there is some problem, we can debug it printing the value x

1
2
$ DEBUG=foo:x node .
  foo:x value x = { foo: { bar: 'baz' } } +0ms

Finally, we can print all messages with foo prefix using a wildcard

1
2
3
$ DEBUG=foo* node .
  foo:x value x = { foo: { bar: 'baz' } } +0ms
  foo have x +0ms

Expose debug function as a module method

To simplify debugging, if a file exports an object, you can attach the debug function to that object. This will significantly simplify unit testing. Make sure to call debug via method reference and not directly.

foo.js
1
2
3
4
5
6
7
8
9
10
11
12
const debug = require('debug')('foo')
const add = (a, b) => {
  const sum = a + b
  // call `debug` via method reference!
  api.debug('sum %d', sum)
  return sum
}
const api = {
  add,
  debug
}
module.exports = api

Now you can easily spy / stub api.debug from your unit tests using sinon.js for example.

test.js
1
2
3
4
5
6
7
8
9
10
11
12
const api = require('./foo')
beforeEach(() => {
  sinon.stub(api, 'debug')
})
afterEach(() => {
  api.debug.restore()
})
it('computes sum', () => {
  const result = api.add(2, 3)
  expect(result).to.equal(5)
  expect(api.debug).to.have.been.calledOnceWithExactly('sum %d', 5)
})

Log promise from promise chains

To better log intermediate values in promise chains, I usually use R.tap with an extra function to ensure logging the entire object in a single line.

1
2
3
4
5
6
7
const R = require('ramda')
const debug = require('debug')('api')
const debugOneLine = (x) => debug('%o', x)

foo() // returns a promise
  .then(R.tap(debugOneLine)) // log resolved value and pass it along
  .then(...) // use resolved value

If you use Bluebird promise library, it already has .tap and .tapCatch methods on its promises

1
2
3
4
5
6
7
Promise = require('bluebird')
const debug = require('debug')('api')
const debugOneLine = (x) => debug('%o', x)
foo() // returns a Bluebird promise instance
  .tap(debugOneLine) // logs the resolved value
  .tapCatch(debugOneLine) // logs the error
  // continue with the promise as usual

Log values from tests

To simplify debugging failed tests I use namespace test inside unit and end-to-end tests.

spec.js
1
2
3
4
5
6
const debug = require('debug')('test')
it('works', () => {
  const result = foo()
  debug(result)
  assert(...)
})

Whenever the test fails, I can run it with DEBUG=test npm t to see the result variable. I do not care much for single line output because these logs are only used for debugging tests and not for production.

Related

I will also consider switching from human-readable to JSON-by-default format using super fast pino logger, especially because it has debug compatible module pino-debug