JavaScript / Jest: How to show logs from test case only when test fails?

Question

I'm working on an end-to-end test suite using selenium where the test cases are written in JavaScript using the jest test runner.

My problem is that selenium often fails unceremoniously when something doesn’t work with little explanation to where it failed. Needless to say, debugging tests like this can be quite difficult.

I am looking for a way to log in each test case so I know where the test fail, but to only show these logs in the test output if the test actually fails (in order to not pollute the console output from the test with lots of unnecessary logs).

So I would like to do something like:

describe(() => {
    it('case 1', async () => {
        // this log should only be printed on the console if this test fails
        logger.info('message from case 1');
        // ...
    });

    it('case 2', () => {
        logger.info('message from case 2');
        // ...
    });
});

So that if the test in case 1 fails and case 2 doesn't fail, I see message from case 1 in the console output (ideally right before the error from that test case) and not message from case 2.

Is this possible with jest? I'm free to use any logging library for this.

Answer 1

I had the same problem and couldn't find a definitive solution. It seems it's low on Facebook's to do list so here's a workaround. It's using snippets of code I found here and here. The idea is that before each jest run, you set up a message stash and override the console globally to divert all logging to that. After each test, you then check if that test failed and if so, print out the stashed messages.

package.json:

"jest": {
    ...
    "verbose": true,
    "setupFilesAfterEnv": ["<rootDir>/test/setup.js"],
    ...
  }

setup.js:

const util = require('util')

global.consoleMessages = []

// get information about the current test
jasmine.getEnv().addReporter({
    specStarted: result => jasmine.currentTest = result,
    specDone: result => jasmine.currentTest = result,
})

function squirrelAway(text, logger) {
    // use error to get stack trace
    try {
        throw new Error('stacktrace')
    } catch (err) {
        let trace = err.stack.split('\n')
        trace.shift()   // removes Error: stacktrace
        trace.shift()   // removes squirrelAway() call from the "throw" command
        trace.shift()   // removes console logger call in the console override
        consoleMessages.push({logger: logger, payload: text, stacktrace: trace.join('\n')})
    }
}

const orig = console
global.console = {...console,
    // use jest.fn() to silence, comment out to leave as it is
    log: (text => squirrelAway(text, orig.log)),
    error: (text => squirrelAway(text, orig.error)),
    warn: (text => squirrelAway(text, orig.warn)),
    info: (text => squirrelAway(text, orig.info)),
    debug: (text => squirrelAway(text, orig.debug))
}

global.afterEach(() => {
    // this includes tests that got aborted, ran into errors etc.
    let failed = (jasmine && jasmine.currentTest
                  && Array.isArray(jasmine.currentTest.failedExpectations)) ?
                 jasmine.currentTest.failedExpectations.length>0 : true
    //orig.log(`test "${jasmine.currentTest.fullName}" finished. failed? ${failed}`)
    if (failed) {
        //orig.log(`Logging for "${jasmine.currentTest.fullName}" start`)
        consoleMessages.forEach(msg => {
            if (typeof msg.payload === 'object' || typeof msg.payload === 'function') {
                msg.payload = util.inspect(msg.payload, false, null, true)
            }
            msg.logger.call(msg.logger, msg.payload + '\n' + msg.stacktrace)
        })
        //orig.log(`Logging for "${jasmine.currentTest.fullName}" end`)
    }
    consoleMessages = []
})

If you need to do any other clean up, you can "extend" afterEach in your test file like this:

some.test.js

const globalAfterEach = afterEach
afterEach((globalAfterEach) => {
    // do things here
    globalAfterEach()
    // or do things here
})

Drawbacks:

• Because we override the console, the stack trace for the logging is lost and when the console is called, the stacktrace used by jest only contains the stack for the overwritten console.log(/debug/error/...) call in the setup file. So in order to get hold of the original stack trace, we throw an error. This can then be appended to the text being logged. Not particularly pretty but works.