{"id":417,"date":"2015-09-27T13:25:26","date_gmt":"2015-09-27T11:25:26","guid":{"rendered":"http:\/\/joost.vunderink.net\/blog\/?p=417"},"modified":"2015-10-12T16:10:25","modified_gmt":"2015-10-12T14:10:25","slug":"checking-log4js-output-in-your-node-js-testsuite","status":"publish","type":"post","link":"https:\/\/joost.vunderink.net\/blog\/2015\/09\/27\/checking-log4js-output-in-your-node-js-testsuite\/","title":{"rendered":"Checking log4js output in your node.js testsuite"},"content":{"rendered":"

This post will teach you how to test\u00a0log4js<\/span>\u00a0 log statements in your code.<\/p>\n

You can also find the code below in the `src\/log4js-unittest` dir of my blog code repository<\/a>.<\/p>\n

Let’s say that we have written this simple node.js<\/a> module, foo.js<\/span>\u00a0.<\/p>\n

'use strict';\r\n\r\nvar log4js = require('log4js');\r\nvar logger = log4js.getLogger('foo');\r\n\r\nfunction logSomething() {\r\n  logger.info('something');\r\n}\r\n\r\nmodule.exports = {\r\n  logSomething: logSomething\r\n};\r\n<\/pre>\n
It would be good to verify that logSomething()<\/span>\u00a0 actually logs something. Let’s use this mocha test file skeleton foo.spec.js<\/span>\u00a0:<\/p>\n
'use strict';\r\n\r\nvar foo = require('.\/foo');\r\n\r\ndescribe('Foo logger', function() {\r\n  it('should log something', function() {\r\n    \/\/ Prepare to detect the log output here\r\n\r\n    foo.logSomething();\r\n\r\n    \/\/ Verify the log output here\r\n  });\r\n});\r\n<\/pre>\n
We obviously cannot test logSomething()<\/span>\u00a0‘s\u00a0return value, so we have to think of something else. Maybe we can somehow stub\u00a0either log4js.getLogger()<\/span>\u00a0 or logger.info()<\/span>\u00a0?<\/p>\n
Normally, I use sinon<\/a> to create spies<\/a>, stubs<\/a>\u00a0and mocks<\/a>. With sinon, you can replace object methods or even the objects themselves.<\/p>\n
As far as I know, it is not\u00a0possible to modify the logger<\/span>\u00a0 object inside foo.js<\/span>\u00a0, because foo.spec.js<\/span>\u00a0 doesn’t have access to the scope of foo.js<\/span>\u00a0. We could add the logger<\/span>\u00a0 object to the foo.js<\/span>\u00a0 exports, but that doesn’t seem to be a very elegant solution. I’d rather not modify foo.js<\/span>\u00a0 itself.<\/p>\n
Let’s see if we can stub getLogger()<\/span>\u00a0:<\/p>\n
'use strict';\r\n\r\nvar should = require('should');\r\nvar sinon  = require('sinon');\r\n\r\n\/\/ First require log4js here, so we are in time to stub getLogger.\r\nvar log4js = require('log4js');\r\n\r\n\/\/ Create a spy to see which logger.info calls were done.\r\nvar infoSpy = sinon.spy();\r\n\r\n\/\/ Make sure log4js.getLogger() returns an object containing our spy.\r\nvar getLoggerStub = sinon.stub(log4js, 'getLogger');\r\ngetLoggerStub.returns({ info: infoSpy });\r\n\r\n\/\/ Now we can require foo.js, which will use our getLogger stub.\r\nvar foo = require('.\/foo');\r\n\r\ndescribe('Foo logger', function() {\r\n  it('should log something', function() {\r\n    foo.logSomething();\r\n\r\n    infoSpy.calledOnce.should.equal(true);\r\n    infoSpy.calledWithExactly('something').should.equal(true);\r\n  });\r\n});\r\n<\/pre>\n
Does it work?<\/p>\n
czapka:~\/src\/blog\/log4js-unittest$ mocha foo.spec.js\r\n\r\n  Foo logger\r\n    \u2713 should log something\r\n\r\n  1 passing (5ms)<\/pre>\n
Yes it does!<\/p>\n
However, this method relies on being able to stub log4js.getLogger()<\/span>\u00a0 before foo.js<\/span>\u00a0 is required. What happens if we require foo.js<\/span>\u00a0 before stubbing?<\/p>\n
'use strict';\r\n\r\n\/\/ What if this file (or any other code file or spec file!)\r\n\/\/ requires foo before we can create the getLogger stub?\r\nvar foo = require('.\/foo');\r\n\r\nvar should = require('should');\r\nvar sinon  = require('sinon');\r\nvar log4js = require('log4js');\r\nvar infoSpy = sinon.spy();\r\nvar getLoggerStub = sinon.stub(log4js, 'getLogger');\r\ngetLoggerStub.returns({ info: infoSpy });\r\n\r\ndescribe('Foo logger', function() {\r\n  it('should log something', function() {\r\n    foo.logSomething();\r\n\r\n    infoSpy.calledOnce.should.equal(true);\r\n    infoSpy.calledWithExactly('something').should.equal(true);\r\n  });\r\n});\r\n<\/pre>\n
Unfortunately, this fails:<\/p>\n
czapka:~\/src\/blog\/log4js-unittest$ mocha foo.spec.js\r\n\r\n  Foo logger\r\n[2015-09-27 12:49:55.284] [INFO] foo - something\r\n    1) should log something\r\n\r\n  0 passing (7ms)\r\n  1 failing\r\n\r\n  1) Foo logger should log something:\r\n\r\n      AssertionError: expected false to be true<\/pre>\n
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()<\/span>\u00a0\u00a0calls simply return the loaded module from node.js’s module cache.<\/p>\n
This makes the test very fragile. If any other module requires foo.js<\/span>\u00a0 before this test is run, the logger<\/span>\u00a0 object inside foo.js<\/span>\u00a0 has already been created before the getLogger()<\/span>\u00a0 stub can be used.<\/p>\n
What else is there to try?<\/p>\n
We could add an appender<\/a> to log4js<\/span>\u00a0 that captures any logged lines for verification afterward. Since there did not seem to be such an appender yet, I decided to create one<\/a>.<\/p>\n
This is how to use it:<\/p>\n
'use strict';\r\n\r\n\/\/ We can now load foo.js at any point, because we are no longer\r\n\/\/ stubbing log4js.getLogger().\r\nvar foo    = require('.\/foo');\r\nvar should = require('should');\r\n\r\nvar testAppender = require('log4js-test-appender');\r\ntestAppender.init();\r\n\r\ndescribe('Foo logger', function() {\r\n  it('should log something', function() {\r\n    foo.logSomething();\r\n\r\n    var logEvents = testAppender.getLogEvents();\r\n    logEvents.should.have.length(1);\r\n    logEvents[0].level.levelStr.should.equal('INFO');\r\n    logEvents[0].data[0].should.equal('something');\r\n  });\r\n});\r\n<\/pre>\n
There we go, a robust, working test.<\/p>\n
The API of log4js-test-appender<\/span>\u00a0 is not very elegant yet, so if you have any suggestions for improvement, feel free to comment or create a merge request<\/a>! And if you have an alternative suggestion to test log4js<\/span>\u00a0 log statements, I’m all ears.<\/p>\n","protected":false},"excerpt":{"rendered":"
This post will teach you how to test\u00a0log4js\u00a0 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\u00a0. … Continue reading →<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[176,177,10],"tags":[240,238,239,242,232,228,226,243,231,234,233,236,241,237,235],"class_list":["post-417","post","type-post","status-publish","format-standard","hentry","category-javascript","category-node-js","category-software-development","tag-log-output","tag-log4js","tag-logger","tag-mocha","tag-mock","tag-node","tag-node-js","tag-npm","tag-sinon","tag-spy","tag-stub","tag-test","tag-test-log-output","tag-test-suite","tag-unit-test"],"_links":{"self":[{"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/posts\/417"}],"collection":[{"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/comments?post=417"}],"version-history":[{"count":16,"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/posts\/417\/revisions"}],"predecessor-version":[{"id":437,"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/posts\/417\/revisions\/437"}],"wp:attachment":[{"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/media?parent=417"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/categories?post=417"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/joost.vunderink.net\/blog\/wp-json\/wp\/v2\/tags?post=417"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}