TDD and Winston Logger now with less pain and more gain

You know what gets swept under the rug and forgotten during TDD a lot? Logs. After many years of test-driven development (and/or pretending to do test-driven development), testing is still more of an art than a science to me in many cases off the beaten path. Especially determining exactly what to test, and how much testing is “good enough.” I would argue that, unless the worried face on the man in this oil panting I commissioned to illustrate my point¹ sparks joy for you, zero tests for logging is not “good enough.”

However, don’t feel bad if you’ve skipped testing your logging; I haven’t done a survey or anything, but you’re certainly not alone — after all it’s not a “user-facing feature”… I mean, unless you care about the experience of the people maintaining the software, which is to say your own experience, so… maybe…. Anyway, regardless of that, I found it to be a surprisingly non-trivial task in a recent feature I implemented because of our logging library, winston. So I’m here to help.

Now don’t get me wrong, winston is a great logger for Node.js apps. It’s highly configurable, is feature-rich and makes it easy to configure a default logging format while adding extra metadata depending on the context of the module doing the logging, using “child” loggers. However, it can be tedious and/or challenging to test file output in JavaScript, particularly a winston logger where the module under test uses logger.child to add metadata that you want to test — like this one:

const defaultLogger = require('../lib/logger') // winston.createLogger(...)

const logger = defaultLogger.child({ label: 'job:processTheThings' })

export default function processTheThings() {
  // some lets and stuff
  logger.info('starting process')
  // some important stuff
  logger.info('finished process', {success: true})
}

How do we test this? Ideally, in my test, I want to be able to just say something like this to test the output, including any expected metadata (using testdouble.js, of course, but I’ll add the jest version in comments for those who prefer it):

const logger = td.replace('../lib/logger') // or jest.createMockFromModule(...)
const subject = require('./processTheThings.js')
subject()
td.verify(logger.info('finished process',{ // or expect(logger.info).toHaveBeenCalledWith(...)
  label: 'job:processTheThings',
  success: true
}))

The problem: Child

This test would fail though, because my module doesn’t call logger.info, it calls logger.child. I could mock that as well, but I don’t want my test to be coupled to the module’s implementation by expecting logger.child to be called specifically (that would make for a brittle test).

“Why not just test the output?” you may ask (at least that’s what I asked myself). But this logger happens to be writing to a file, so I can’t just mock global.console and see what it says, and have you ever tried mocking/testing file output in Node.js without your test becoming hopelessly complex or coupled to the implementation? (See oil painting above.)

What I really want is a mockLogger that I can spy on without worrying about how many times child is called, if at all. I want to write the test in a family-tree-agnostic way, so to speak (i.e. just verify the job is getting done, regardless of how many children are involved, if any.²)

Solution: Make one! (a mockLogger)

Since our mocking libraries already do a pretty good job of creating mocks that look like real things (i.e. have mocked versions of all the methods and properties of the real thing), let’s just start with that:

  const mockLogger = td.replace('../lib/logger')
  // or ...        = jest.createMockFromModule('../lib/logger')

The only catch is, we need to change the behavior of the child method so that it propagates messages sent to any child logger up to the parent for testing. We can address that with something like this:

// Takes a mocked logger, and replaces the child method to simplify testing
function mockChildLoggers(logger) {
  logger.child = childArgs => buildChildLogger(logger, childArgs)
  return logger
}
const mockLogger = mockChildLoggers(td.replace('../lib/logger'))

But what does buildChildLogger look like? Well, ideally I want something that will just call .info on the parent logger, with the extra metadata attached. That will make it very easy to test the output, using only the original mocked logger. But we need to do this for every log level, not just .info — and oooh winston. Good old winston lets you create as many custom log levels as you want! So rather than hard code them (which would couple our mock module to our winston config) let’s use winston’s .levels property to get a list of methods to replace. (You might think this wouldn’t work seeing as how it’s a mocked instance, but td.replace() and jest.createMockFromModule both copy primitive property values to the mocked instance, so .levels will return whatever levels your winston config defines)

// mockChildLoggers.js
export default function mockChildLoggers(logger) {
  logger.child = childArgs => buildChildLogger(logger, childArgs)
  return logger
}

function buildChildLogger(logger = {}, childArgs){
  const childLogger = {}

  // For each logging method:
  for (const logLevel in logger.levels) {
    childLogger[logLevel] = (message, args) => {
      // Just call the same method on the parent, adding the extra metadata from childArgs
      logger[logLevel](message, {...childArgs, ...args})
    }
  }

  // And just in case someone decides to call `.child` on the child logger...
  return mockChildLoggers(childLogger)
}

Voila! This creates a mock of a winston logger, with which you can verify any calls to info or error (or any other method) on the primary mocked logger, even if the module delegates to child loggers to do the actual logging.

So now, in my test, I can simply mock my logger import with this function and expect any required logging to be called directly on the mocked logger, with all the required metadata, regardless of whether it’s passed in directly or through one or more child loggers. That is, I can define the requirement in the test, but the implementation can be changed without breaking the test. 🙌 

Check out processTheThings.test.js now:

import mockChildLoggers from '@/test/mockChildLoggers'

describe('processTheThings', function() {
  let logger, processTheThings
  beforeEach(() => {
    logger = mockChildLoggers(td.replace('../lib/logger'))
    // ...or mockChildLoggers(jest.createMockFromModule(...))
    processTheThings = require('./processTheThings').default
  })

  it('logs sucessful completion', async () => {
    processTheThings()
    td.verify(logger.info('finished process',{
    // or expect(logger.info).toHaveBeenCalledWith(...)
      label: 'job:processTheThings',
      success: true
    }))
  })
})

Is this good?

Pro: This test is not coupled to the implementation of the module (you can use .child, you can pass in metadata directly, you can do both)

Pro: This test is not coupled to the winston constructor in lib/logger (you can change the log transport and format, and use any method to initialize the logger, all without rewriting your tests, as long as the export is a winston logger)

Con: This test IS coupled to the implementation of the logger itself (winston). If the module starts using something else for logging, we’ll have to rewrite the test and/or mockLogger. But to be fair, the logging is what we’re testing, and every test has to be coupled to something it can deterministically test… (unless your test framework is an LLM I suppose…. 🤔)

The takeaway

Let’s step back from this particular problem for a moment to see if there’s anything more general we can learn.

The root cause of the problem here was a combination of 3 characteristics of the thing we wanted to test:

1. It was something we wanted to mock rather than test in an end-to-end style (in this case that’s because testing the final output is a bit of a pain, but the reasons don’t really matter).
2. It was non-trivial to mock and verify, due to its flexible API. The subject module had several options on how it might accomplish the same basic task using its collaborator module (i.e. the logger).
3. It used a collaborator that didn’t expose a canonical testing interface.

If any of these three things weren’t the case, we would have had a simple path for testing.

The most solvable of these is #3. We just needed to created a canonical testing interface, against which we could test requirements were met, regardless of which part of the flexible API was used to meet them. Given these circumstances, you might choose to write a fully independent mock of the module being tested. In our case that would look similar to buildChildLogger, but it would also be storing the log results somewhere, and have methods for checking/verifying which logs were written (it would almost look like a fake, since it’s using similar logic to maintain an internal state parallel the real thing, but I would only call it a fake if the resulting state were used by the application, and in this case it’s only used by the test framework).

Fortunately, testdouble.js and jest are both pretty good at mocking things, and verifying mocked things, so we didn’t have to maintain any state! All we had to do was account for the flexibility of the API. No mocking library could know that .child(...).info(...) counts as a call to .info(...). So we still solved #3, just in a simpler way: in our case, the only flexible part of the API was .child(), so it was simple to delegate that to a similar call on the parent to create a canonical testing interface.

How reusable is this concept? Who knows… I think it depends on how easy it is to identify “a canonical testing interface” despite a module having a flexible API. I don’t know of a name for the pattern that this style of mocking follows. It’s probably just “mocks.” 😏 Mocking libraries have just gotten so good that I rarely end up having to do any manual mocking outside of complex cases. This was an interesting case for thinking about how to write a mock that can decouple tests from implementations, where the potential for coupling is the mocked module’s flexible API.