16

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.

skyboyer
  • 22,209
  • 7
  • 57
  • 64
Paul
  • 7,836
  • 2
  • 41
  • 48
  • Are you collecting logs from within test cases only? – miki noidea Nov 22 '19 at 08:28
  • @mikinoidea not fully sure I understand the question. As this is an end-to-end test, the application under test would not log into the same facility. – Paul Nov 22 '19 at 13:53

5 Answers5

10

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.
casualcoder
  • 480
  • 4
  • 17
  • 1
    The solution works in general. Some issues: 1) `consoleMessages` doesn't need to be global, you can just use `let consoleMessages`; 2) `currentTest` doesn't need to be in `jasmine` too; 3) no throw is required, just call `const trace = new Error().stack.split('\n')`; 4) logging with multiple arguments isn't supported, replace `text` with `...args` to fix; 5) `util.inspect` isn't required, just pass the value as an argument to the logger (move the stacktrace to a separate argument). – Finesse Sep 03 '20 at 03:58
  • 1
    Also `afterEach` doesn't require special treatment in test files. I just type `afterEach(() => ...)` and everything works as expected. – Finesse Sep 03 '20 at 04:03
5

There are ways to be tricky with your expect calls to let you know where a failure happens. Would something like this be of use?

const location = "case 1 failed";
const result = someFunction();  
expect({result: result, location}).toEqual({result: "hello", location});

Now if someFunction() returns something other than "hello", it will tell you location value as it complains about what was expected.

This is really only useful if you're getting a Jest error, but not getting enough information from the normal expect failure message and you need more detail.

Always Learning
  • 5,510
  • 2
  • 17
  • 34
  • Thank you for this comment. Unfortunately this doesn't quite do what I want, my problem is that Selenium will give me errors like "element Foo not found" and its not clear where in the test this happens. So I'm looking to add logging steps basically after every step (automating this in the future), but only see these logs if the test fails. – Paul Nov 19 '19 at 15:03
0

Test environments handle this quite well. It buffers all console messages, groups them by test and only displays them if the test failed. The nice thing about the environment vs setup files or reporters is that it can be selectively applied to specific tests, leaving the global console alone for all others.

./tests/testEnvironment.js

const NodeEnvironment = require('jest-environment-node');
const colors = require('colors');

class TestEnvironment extends NodeEnvironment {
    constructor(config, context) {
        super(config, context);
    }

    async setup() {
        await super.setup();

        this.global.consoleItems = [];

        this.global.console = { ...console,
            original: console,
            log: ((message) => this.global.consoleItems.push({type: 'log', message })),
            error: ((message) => this.global.consoleItems.push({type: 'error', message })),
            warn: ((message) => this.global.consoleItems.push({type: 'warn', message })),
            info: ((message) => this.global.consoleItems.push({type: 'info', message })),
            debug: ((message) => this.global.consoleItems.push({type: 'debug', message })),
        };
    }

    async teardown() {
        this.global.console = this.global.console.original;
        await super.teardown();
    }

    async handleTestEvent(event, state) {
        if (event.name === 'test_done' && event.test.errors.length > 0) {
            let test = event.test;
            let fullTestName = event.test.name;
            while (test.parent != null && test.parent.name !== 'ROOT_DESCRIBE_BLOCK') {
                fullTestName = test.parent.name + ' › ' + fullTestName;
                test = test.parent;
            }
            this.global.console.original.log(colors.bold.red('Console messages for failed test ' + fullTestName));
            this.global.consoleItems.forEach((item) => {
                if (item.type === 'log') {
                    this.global.console.original.log('    - ' + item.message);
                } else if (item.type === 'error') {
                    this.global.console.original.error('    - ' + item.message);
                } else if (item.type === 'warn') {
                    this.global.console.original.warn('    - ' + item.message);
                } else if (item.type === 'info') {
                    this.global.console.original.info('    - ' + item.message);
                } else if (item.type === 'debug') {
                    this.global.console.original.debug('    - ' + item.message);
                }
            });
            this.global.console.original.log('\n');
        }
        if (event.name === 'test_done') {
            this.global.consoleItems = [];
        }
    }

}

module.exports = TestEnvironment;

For each test suite the following comment is needed to use this environment:

/**
 * @jest-environment ./tests/testEnvironment
 */
sqwk
  • 2,649
  • 1
  • 28
  • 42
0

This is probably the bad practice, but I noticed expect().toBe() or something will throw an Error if it's not equal, you can catch it first before and logging it.

This is example code when I try to test is every text message has translated language.

test('All message has translate', () => {

  allAvailableText.forEach((key) => {

    const languagesOnTheKey = Object.keys(text[key]).sort()
    try {
      expect(languagesOnTheKey).toStrictEqual(languages)
    } catch (error) {
      console.log(key, languagesOnTheKey)
    }
    expect(languagesOnTheKey).toStrictEqual(languages)

  })
})

This is just quickest way how to do it and easiest to read for me because the chosen answer is giving me hard time to understand.

Awotism
  • 58
  • 6
  • Good suggestion! It worked for me (v23.5) after adding "done" as an argument: `test('All message has translate', (done) => {...}` I then implemented it with: `try { expect(languagesOnTheKey).toStrictEqual(languages) done() } catch (error) { console.log(key, languagesOnTheKey) done(err) }` Ref: https://archive.jestjs.io/docs/en/23.x/asynchronous – Looi Apr 18 '22 at 03:53
0

I modified siilike's approach and it works pretty well. I still have some straggler console messages that I guess weren't captured by Jest.

Before:

...
➤ YN0000: [premiser-ui]: PASS src/reducers/ui/ui.test.js
➤ YN0000: [premiser-ui]:   ● Console
➤ YN0000: [premiser-ui]:
➤ YN0000: [premiser-ui]:     console.warn
➤ YN0000: [premiser-ui]:       Unsupported extension environment.
➤ YN0000: [premiser-ui]:
➤ YN0000: [premiser-ui]:       143 |   extension = new Extension(window.browser)
➤ YN0000: [premiser-ui]:       144 | } else {
➤ YN0000: [premiser-ui]:     > 145 |   logger.warn("Unsupported extension environment.")
➤ YN0000: [premiser-ui]:           |          ^
➤ YN0000: [premiser-ui]:       146 |   extension = new Extension()
➤ YN0000: [premiser-ui]:       147 | }
➤ YN0000: [premiser-ui]:       148 |
➤ YN0000: [premiser-ui]:
➤ YN0000: [premiser-ui]:       at Object.<anonymous> (howdju-client-common/lib/extension.js:145:10)
➤ YN0000: [premiser-ui]:       at Object.<anonymous> (howdju-client-common/lib/index.js:3:1)
➤ YN0000: [premiser-ui]:
➤ YN0000: [premiser-ui]:
➤ YN0000: [premiser-ui]: Test Suites: 7 passed, 7 total
➤ YN0000: [premiser-ui]: Tests:       27 passed, 27 total
➤ YN0000: [premiser-ui]: Snapshots:   0 total
➤ YN0000: [premiser-ui]: Time:        6.598 s

After:

...
➤ YN0000: [premiser-ui]: PASS src/reducers/ui/ui.test.js
➤ YN0000: [premiser-ui]:
➤ YN0000: [premiser-ui]: Test Suites: 7 passed, 7 total
➤ YN0000: [premiser-ui]: Tests:       27 passed, 27 total
➤ YN0000: [premiser-ui]: Snapshots:   0 total
➤ YN0000: [premiser-ui]: Time:        4.863 s

Jest updates:

// jest.config.js

module.exports = {
  ...
  reporters: [
    '<rootDir>/jest/OutputConsoleOnFailureOnlyReporter.js',
    '<rootDir>/node_modules/@jest/reporters/build/SummaryReporter.js',
  ]
}
// <packageRoot>/jest/OutputConsoleOnFailureOnlyReporter.js

const { DefaultReporter } = require('@jest/reporters')
const chalk = require('chalk')

const TITLE_BULLET = chalk.bold('\u25cf ');

/** A custom Jest reporter that skips console output for passing tests. */
class OutputConsoleOnFailureOnlyReporter extends DefaultReporter {
    constructor() {
        super(...arguments)
    }

  logWithoutConsole(message) {
    // If the message looks like captured console logging from here:
    // https://github.com/facebook/jest/blob/c660c1688d4a1898ba00143abad22ad2785f350b/packages/jest-reporters/src/DefaultReporter.ts#L223
    // then skip it.
    if (message.startsWith(`  ${TITLE_BULLET}Console`)) {
      return
    }
    process.stderr.write(`${message}\n`);
  }

    printTestFileHeader(_testPath, config, result) {
        const originalLog = this.log
        // If the test didn't fail, then don't log its console output.
        if (result.numFailingTests === 0 && !result.testExecError) {
            this.log = this.logWithoutConsole
        }
        super.printTestFileHeader(...arguments)
        // Restore the original method.
        this.log = originalLog
    }
}

module.exports = OutputConsoleOnFailureOnlyReporter

Carl G
  • 17,394
  • 14
  • 91
  • 115