Checking log4js output in your node.js testsuite

This post will teach you how to test log4js  log statements in your code.

You can also find the code below in the `src/log4js-unittest` dir of my blog code repository.

Let’s say that we have written this simple node.js module, foo.js .

'use strict';

var log4js = require('log4js');
var logger = log4js.getLogger('foo');

function logSomething() {
  logger.info('something');
}

module.exports = {
  logSomething: logSomething
};

It would be good to verify that logSomething()  actually logs something. Let’s use this mocha test file skeleton foo.spec.js :

'use strict';

var foo = require('./foo');

describe('Foo logger', function() {
  it('should log something', function() {
    // Prepare to detect the log output here

    foo.logSomething();

    // Verify the log output here
  });
});

We obviously cannot test logSomething() ‘s return value, so we have to think of something else. Maybe we can somehow stub either log4js.getLogger()  or logger.info() ?

Normally, I use sinon to create spies, stubs and mocks. With sinon, you can replace object methods or even the objects themselves.

As far as I know, it is not possible to modify the logger  object inside foo.js , because foo.spec.js  doesn’t have access to the scope of foo.js . We could add the logger  object to the foo.js  exports, but that doesn’t seem to be a very elegant solution. I’d rather not modify foo.js  itself.

Let’s see if we can stub getLogger() :

'use strict';

var should = require('should');
var sinon  = require('sinon');

// First require log4js here, so we are in time to stub getLogger.
var log4js = require('log4js');

// Create a spy to see which logger.info calls were done.
var infoSpy = sinon.spy();

// Make sure log4js.getLogger() returns an object containing our spy.
var getLoggerStub = sinon.stub(log4js, 'getLogger');
getLoggerStub.returns({ info: infoSpy });

// Now we can require foo.js, which will use our getLogger stub.
var foo = require('./foo');

describe('Foo logger', function() {
  it('should log something', function() {
    foo.logSomething();

    infoSpy.calledOnce.should.equal(true);
    infoSpy.calledWithExactly('something').should.equal(true);
  });
});

Does it work?

czapka:~/src/blog/log4js-unittest$ mocha foo.spec.js

  Foo logger
    ✓ should log something

  1 passing (5ms)

Yes it does!

However, this method relies on being able to stub log4js.getLogger()  before foo.js  is required. What happens if we require foo.js  before stubbing?

'use strict';

// What if this file (or any other code file or spec file!)
// requires foo before we can create the getLogger stub?
var foo = require('./foo');

var should = require('should');
var sinon  = require('sinon');
var log4js = require('log4js');
var infoSpy = sinon.spy();
var getLoggerStub = sinon.stub(log4js, 'getLogger');
getLoggerStub.returns({ info: infoSpy });

describe('Foo logger', function() {
  it('should log something', function() {
    foo.logSomething();

    infoSpy.calledOnce.should.equal(true);
    infoSpy.calledWithExactly('something').should.equal(true);
  });
});

Unfortunately, this fails:

czapka:~/src/blog/log4js-unittest$ mocha foo.spec.js

  Foo logger
[2015-09-27 12:49:55.284] [INFO] foo - something
    1) should log something

  0 passing (7ms)
  1 failing

  1) Foo logger should log something:

      AssertionError: expected false to be true

The reason that this fails, is that node.js uses a module cache. The first time a module is required, it is loaded; any followup require()  calls simply return the loaded module from node.js’s module cache.

This makes the test very fragile. If any other module requires foo.js  before this test is run, the logger  object inside foo.js  has already been created before the getLogger()  stub can be used.

What else is there to try?

We could add an appender to log4js  that captures any logged lines for verification afterward. Since there did not seem to be such an appender yet, I decided to create one.

This is how to use it:

'use strict';

// We can now load foo.js at any point, because we are no longer
// stubbing log4js.getLogger().
var foo    = require('./foo');
var should = require('should');

var testAppender = require('log4js-test-appender');
testAppender.init();

describe('Foo logger', function() {
  it('should log something', function() {
    foo.logSomething();

    var logEvents = testAppender.getLogEvents();
    logEvents.should.have.length(1);
    logEvents[0].level.levelStr.should.equal('INFO');
    logEvents[0].data[0].should.equal('something');
  });
});

There we go, a robust, working test.

The API of log4js-test-appender  is not very elegant yet, so if you have any suggestions for improvement, feel free to comment or create a merge request! And if you have an alternative suggestion to test log4js  log statements, I’m all ears.