process

Capture all the logs

How to capture console.log, console.error and even DEBUG=... logs.

In this blog post I will show how to intercept messages logged by a Node process using a pre-loaded module. You can find the source code for these examples in bahmutov/capture-logs-example repository.

Capture console logs

Imagine you want to collect all strings logged from a Node program. You could proxy all console.log calls and store them until needed. Take an example Node program like this one in index.js:

index.js
1
2
3
console.log('this is %s log message ✅', 'console')
console.warn('this is console %s ⚠️', 'warn')
console.error('this is console error 🔥')

When we run this program, all logs are written to their respective output streams. Note that values are substituted into placeholders like %s -> "console".

1
2
3
4
$ node .
this is console log message ✅
this is console warn ⚠️
this is console error 🔥

Note that console.log writes its messages to STDOUT, while console.warn and console.error write to STDERR. You can verify this by hiding STDERR stream via redirect.

1
2
3
4
5
6
7
# hide STDERR stream
$ node . 2> /dev/null
this is console log message ✅
# hide STDOUT stream
$ node . 1> /dev/null
this is console warn ⚠️
this is console error 🔥

Great, now let's collect the messages by pre-loading a module that is going to proxy console.* methods. Here is the log.js file:

log.js
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
const util = require('util')

// ignore "console.table" and "console.dir" for now
const methodNames = ['log', 'warn', 'error']

// put all messages interleaved into single list
// so we can see how they all appeared
// each message should have "type" and "message"
const messages = []
/**
 * put the original log methods into a global object
 * so we can do two things:
 *  1: restore the methods when needed
 *  2: print messages without going through proxied methods
 *      like "cnsl.log('my message')"
 */
global.cnsl = {}

methodNames.forEach(methodName => {
  const originalMethod = (global.cnsl[methodName] = console[methodName])

  console[methodName] = function () {
    // save the original message (formatted into a single string)
    // use "util.format" to perform string formatting if needed
    const params = Array.prototype.slice.call(arguments, 1)
    const message = params.length
      ? util.format(arguments[0], ...params)
      : arguments[0]
    messages.push({
      type: methodName, // "log", "warn", "error"
      message
    })

    // call the original method like "console.log"
    originalMethod.apply(console, arguments)
  }
})

/**
 * A method to restore the original console methods
 */
const restore = () => {
  Object.keys(global.cnsl).forEach(methodName => {
    console[methodName] = global.cnsl[methodName]
  })
}

process.on('beforeExit', () => {
  restore()

  console.log('*** printing saved messages ***')
  messages.forEach(m => {
    console.log('%s: %s', m.type, m.message)
  })
})

Each method like console.log is replaced with our function that keeps a copy of the formatted string and calls the original log method. We can now run our original program, but require the ./log.js first; all logged strings will be collected and printed again at the end.

1
2
3
4
5
6
7
8
9
$ node -r ./log .

this is console log message ✅
this is console warn ⚠️
this is console error 🔥
*** printing saved messages ***
log: this is console log message ✅
warn: this is console warn ⚠️
error: this is console error 🔥

Capture debug logs

I love using debug module to control my verbose logs. Just import the module and control if its messages are showing up in the terminal using an environment variable DEBUG=some:name:space. Here is a copy of the program but with additional logging statement. See index-debug.js file:

index-debug.js
1
2
3
4
5
6
7
8
const debug = require('debug')('verbose')

console.log('this is %s log message ✅', 'console')
console.warn('this is console %s ⚠️', 'warn')
console.error('this is console error 🔥')

// only visible when you call "DEBUG=verbose node ./index-debug"
debug('this is verbose debug = %d', 42)

If we run the program "normally" the debug calls are ignored. We need to enable "verbose" namespace to actually see them.

1
2
3
4
5
6
7
8
9
10
$ node ./index-debug.js
this is console log message ✅
this is console warn ⚠️
this is console error 🔥

$ DEBUG=verbose node ./index-debug.js
this is console log message ✅
this is console warn ⚠️
this is console error 🔥
  verbose this is verbose debug = 42 +0ms

Perfect - can we capture the log calls to the debug instances? Well, debug module writes directly into process.stderr stream bypassing console.* methods, thus our proxy is not going to work. Luckily, the debug module exposes its internals so we can easily proxy its methods. Bonus: we can log even the disabled debug namespaces!

Look at the implementation of log-debug.js. When a new debug log instance is created using require('debug')(... namespace name ...), it is added to the list of debug instances. That list is an Array instance, and a new instance is pushed to the array using "standard" debug.instances.push(). Well, we can overwrite this method, just like we can overwrite pretty much everything in JavaScript. When we do this, we get access to every debug instance instantiated by the process. That's where we can insert out logic to capture debug log messages - even if the namespace is disabled!

log-debug.js
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
const util = require('util')

function logDebugCalls (messages) {
  // assume there is "debug" module, otherwise
  // do nothing (put try / catch around require)
  const debug = require('debug')

  // All enabled debug instances by default use "debug.log" method
  // to actually write to process.stderr stream. Assume user code
  // does not change this, just save the message
  const debugLog = debug.log
  debug.log = (...args) => {
    messages.push({
      type: 'debug',
      message: util.format(...args)
    })
    // and call the original method to print it
    debugLog.apply(debug, args)
  }

  // new instances are added using "debug.instances.push()"
  // so we can proxy this method
  debug.instances.push = debugInstance => {
    Array.prototype.push.call(debug.instances, debugInstance)

    if (debugInstance.enabled) {
      // ignore custom debugInstance.log method - we could
      // intercept that as well by using "setter" property
      return
    }
    // if the debug instance is disabled, the common "debug.log"
    // method is NOT going to be called. We DO want to record the message though
    // to enable test debugging
    debugInstance.enabled = true
    debugInstance.log = (...args) => {
      messages.push({
        type: 'debug',
        message: util.format(...args)
      })
    }
  }
}

module.exports = logDebugCalls

The above file log-debug.js exports the logDebugCalls and we can call it from our log.js file passing the messages list. Thus the debug messages get inserted into the same list as the intercepted console.log messages, giving us the right order.

1
2
3
// in log.js
// intercept "debug" module logging calls
require('./log-debug')(messages)

And there is the logging in action - first let's run with DEBUG=verbose enabled. The debug call shows up in the terminal AND is captured. Then we will run the process without DEBUG environment variable. The debug call is NOT in the normal terminal output, because the namespace is not enabled, yet it is still captured.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
$ DEBUG=verbose node -r ./log ./index-debug.js
this is console log message ✅
this is console warn ⚠️
this is console error 🔥
  verbose this is verbose debug = 42 +0ms
*** printing saved messages ***
log: this is console log message ✅
warn: this is console warn ⚠️
error: this is console error 🔥
debug:   verbose this is verbose debug = 42 +0ms

$ node -r ./log ./index-debug.js
this is console log message ✅
this is console warn ⚠️
this is console error 🔥
*** printing saved messages ***
log: this is console log message ✅
warn: this is console warn ⚠️
error: this is console error 🔥
debug:   verbose this is verbose debug = 42 +0ms

Beautiful - we have all the logs we might need, yet the "normal" terminal output only shows top level messages. We are now free to do anything with the verbose logs. For example we could show all the logs ONLY if something goes wrong, avoiding double test runs like locha does.

See also

Update 1 - util.debuglog

In Node, there is built-in NODE_DEBUG=<namespace> mechanism for verbose logs, see util.debuglog.

1
2
3
const util = require('util');
const debuglog = util.debuglog('foo');
debuglog('hello from foo [%d]', 123);

If you run the above piece of code with NODE_DEBUG=foo it will show the namespace (uppercased) and process id

1
FOO 3245: hello from foo [123]

One can intercept these log messages by overwriting util.debuglog method.