products

End to end unit testing

You can quickly verify complex logic if you use structured JSON logging.

Writing unit tests is simple. Verifying complex CLI tool behavior on the other hand is hard. Sometimes a bug appears for certain inputs and it requires lots of human debugging via log messages before the true cause is located. Can we automate at least the end to end regression tests?

We can, if instead of human log messages we output JSON messages, for example using bunyan or winston logger. Then we can easily parse the program's output and verify what has happened.

My own TDD QUnit-like test runner gt has an assertion gt.exec that runs any given command and verifies the exit code, or returns the program's standard output to the unit test for further validation. If the program outputs JSON objects, you can easily find them and verify the events.

Logger setup

I use bunyan and recommend only outputting JSON objects when necessary, for example, if the user called the program using --debug command line argument.

example.js
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
var bunyan = require('bunyan');
var log = bunyan.createLogger({ name: 'example' });
log.level(process.argv.some(function (str) {
  return str === '--debug';
}) ? 'debug' : 'info');
console.log('hi from console');
// always visible
log.debug('message', {
  foo: 'foo',
  bar: 'bar'
});
log.debug('message 2', {
  foo: 'foo',
  bar: 'bar'
});
// printed only if the program called with --debug

The JSON objects can be quickly printed by piping the program's output through the bunyan CLI tool

$ node index.js | bunyan -o short
hi from console
03:12:41.848Z  INFO myapp: message { foo: 'foo', bar: 'bar' }
03:12:41.849Z  INFO myapp: message 2 { foo: 'foo', bar: 'bar' }

Unit tests

The end to end unit test executes the separate program asynchronously using gt.exec passing the program name and its arguments. It also should pass the expected exit code and a callback function that can further verify the standard output text. To simplify parsing and finding the objects with given label, I wrote bunyan-gt that provides a single helper function:

1
2
3
4
5
6
7
8
9
10
11
12
13
var bgt = require('bunyan-gt');
gt.async('verify message 2', function () {
  var filename = path.join(__dirname, 'example.js');
  gt.exec('node', [filename, '--debug'], 0, function inspectOutput(stdout, stderr) {
    gt.equal(stderr, '', 'no stderr');
    var messages = bgt(stdout, 'example', 'message 2');
    gt.equal(messages.length, 1, 'single message 2');
    gt.equiv(messages[0].message, {
      foo: 'foo',
      bar: 'bar'
    }, 'checked message contents');
  });
}, 10000);

The bgt(stdout, loggerName, messageLabel) function finds messages first by the logger name, then by the message label. The returned array contains objects by the label

1
2
3
log.debug('my label', { foo: 'foo' });
// bgt(stdout, name, 'my label') returns
// { 'my label': { foo: 'foo' } }

Conclusion

While this end to end testing approach might not replace mocking objects and integration tests, it is significantly simpler to implement and use. It also mimics the manual debugging approach, and could be used to write simple regression tests after the debugging has found the problem.