How to use Jest to test that pino debug log is written to stdout when load a module in a test?

Question

I am using pino as a logger with output sent to stdout destination. I am trying to test that a debug message is written to stdout but cannot see anything written to process.stdout in the test....can anyone help?

Pino logger

'use strict'

const pino = require('pino')
const log = pino({ name: 'TensorFlow-WithFiltering-And-MQTT', level: 'debug' }, pino.destination(1))

module.exports = {
  parentLogger: log
}

The code under test

const { parentLogger, Process } = require('./libs/utils/src')
const log = parentLogger.child({ module: 'child_process' })

/** main function that spawns process is here */

/** 
Want to test that the promise resolves and the debug message is written to stdout when it resolves. 
In VSCode it is hitting the breakpoint in the then block and can see that it resolves
but the test included below fails
**/
main()
  .then(() => {
    log.debug('notify.js process finished initialising')
  })
  .catch((error) => {
    log.error(`notify.js process failed to initialise := ${error}`)
  })

Current Jest test

test.only('main function resolves promise and logs debug message', () => {
    const args = [
      'node',
      'notify.js',
      `mqtts://${global.config.user}:${global.config.user}@${global.config.host}:8883`,
      `${__dirname}/../../docker/certs/localCA.crt`,
      5000,
      'false'
    ]

    /** pino logger writes to stdout - trying to check what is written to stdout stream **/
    let logged = ''
    process.stdout._orig_write = process.stdout.write
    process.stdout.write = (data) => {
      logged = logged + data
      process.stdout._orig_write(data)
    }

    const oldArgs = process.argv
    process.argv = args

    const notify = require('../../../src/notify')

    try {
      expect(logged).toEqual('notify.js process finished initialising')
    } finally {
      process.argv = oldArgs
      process.stdout.write = process.stdout._orig_write
    }
  })

Answer 1

pino.destination is implemented on sonic-boom and this library is managing stream. See docs.

Somehow it works out of your app process.stdout, so replacing write function will not capture logs stdout.

You can access it by replace SonicBoom stream write which is accessible from logger. If you can expose your log, so it can be imported into test file - you use it in this way:

Solution

/* Import log. Better to define it in another file, then import to both main and test. */
const { log } = require('../../../src/notify');

// Import stream symbol
const { streamSym } = require('pino/lib/symbols');


test.only('main function resolves promise and logs debug message', () => {
    const args = [
      'node',
      'notify.js',
      `mqtts://${global.config.user}:${global.config.user}@${global.config.host}:8883`,
      `${__dirname}/../../docker/certs/localCA.crt`,
      5000,
      'false'
    ]

    let logged = ''
    log[streamSym]._orig_write = log[streamSym].write
    process.stdout.write = (data) => {
      logged = logged + data
      process.stdout._orig_write(data)
    }

    const oldArgs = process.argv
    process.argv = args

    const notify = require('../../../src/notify')

    try {
      expect(logged).toEqual('notify.js process finished initialising')
    } finally {
      process.argv = oldArgs
      log[streamSym].write = log[streamSym]._orig_write
    }
  })

SpyOn version

Even better is use jest.spyOn:

/* Import log. Better to define it in another file, then import to both main and test. */
const { log } = require('../../../src/notify');

// Import stream symbol
const { streamSym } = require('pino/lib/symbols');


let stdoutSpy, oldArgs;

const args = [
      'node',
      'notify.js',
      `mqtts://${global.config.user}:${global.config.user}@${global.config.host}:8883`,
      `${__dirname}/../../docker/certs/localCA.crt`,
      5000,
      'false'
];

beforeAll(() => {
  stdoutSpy = jest.spyOn(log[streamSym], 'write');
  oldArgs = process.argv
  process.argv = args

})

afterAll(() => {
  process.argv = oldArgs
  stdoutSpy.mockRestore();
})

test.only('main function resolves promise and logs debug message', () => {
    const notify = require('../../../src/notify')
    expect(stdoutSpy).toHaveBeenCalledWith('notify.js process finished initialising');
  })