From 57a35b3f595c7ff0fac63e3bda6cc642567d35e0 Mon Sep 17 00:00:00 2001 From: Shiba Rin Date: Tue, 21 Mar 2023 18:36:07 +0800 Subject: [PATCH 1/2] test_runner: report failing tests after summary Re-output failing tests after summary has been printed. This behavior follows other popular test runners (e.g. jest, mocha, etc...). Updated SpecReporter: 1. When there is a 'test:fail' event, the test will be stored. 2. After no more input, all the failed tests will be flushed. 3. Extract the logic for formatting a test report into a re-usable function. Fixes: https://github.com/nodejs/node/issues/47110 --- lib/internal/test_runner/reporter/spec.js | 92 +++++--- .../test_runner_output_spec_reporter.out | 209 ++++++++++++++++++ .../test_runner_default_reporter.out | 13 ++ 3 files changed, 279 insertions(+), 35 deletions(-) diff --git a/lib/internal/test_runner/reporter/spec.js b/lib/internal/test_runner/reporter/spec.js index 3637c74111c4b7..c768cde4b98018 100644 --- a/lib/internal/test_runner/reporter/spec.js +++ b/lib/internal/test_runner/reporter/spec.js @@ -3,6 +3,7 @@ const { ArrayPrototypeJoin, ArrayPrototypePop, + ArrayPrototypePush, ArrayPrototypeShift, ArrayPrototypeUnshift, hardenRegExp, @@ -36,6 +37,7 @@ class SpecReporter extends Transform { #stack = []; #reported = []; #indentMemo = new SafeMap(); + #failedTests = []; constructor() { super({ writableObjectMode: true }); @@ -60,54 +62,74 @@ class SpecReporter extends Transform { ), `\n${indent} `); return `\n${indent} ${message}\n`; } - #handleEvent({ type, data }) { + #formatTestReport(type, data, prefix = '', indent = '', hasChildren = false, skippedSubtest = false) { let color = colors[type] ?? white; let symbol = symbols[type] ?? ' '; - + const duration_ms = data.details?.duration_ms ? ` ${gray}(${data.details.duration_ms}ms)${white}` : ''; + const title = `${data.name}${duration_ms}${skippedSubtest ? ' # SKIP' : ''}`; + if (hasChildren) { + // If this test has had children - it was already reported, so slightly modify the output + return `${prefix}${indent}${color}${symbols['arrow:right']}${white}${title}\n`; + } + const error = this.#formatError(data.details?.error, indent); + if (skippedSubtest) { + color = gray; + symbol = symbols['hyphen:minus']; + } + return `${prefix}${indent}${color}${symbol}${title}${error}${white}`; + } + #handleTestReportEvent(type, data) { + const subtest = ArrayPrototypeShift(this.#stack); // This is the matching `test:start` event + if (subtest) { + assert(subtest.type === 'test:start'); + assert(subtest.data.nesting === data.nesting); + assert(subtest.data.name === data.name); + } + let prefix = ''; + while (this.#stack.length) { + // Report all the parent `test:start` events + const parent = ArrayPrototypePop(this.#stack); + assert(parent.type === 'test:start'); + const msg = parent.data; + ArrayPrototypeUnshift(this.#reported, msg); + prefix += `${this.#indent(msg.nesting)}${symbols['arrow:right']}${msg.name}\n`; + } + let hasChildren = false; + if (this.#reported[0] && this.#reported[0].nesting === data.nesting && this.#reported[0].name === data.name) { + ArrayPrototypeShift(this.#reported); + hasChildren = true; + } + const skippedSubtest = subtest && data.skip && data.skip !== undefined; + const indent = this.#indent(data.nesting); + return `${this.#formatTestReport(type, data, prefix, indent, hasChildren, skippedSubtest)}\n`; + } + #handleEvent({ type, data }) { switch (type) { case 'test:fail': - case 'test:pass': { - const subtest = ArrayPrototypeShift(this.#stack); // This is the matching `test:start` event - if (subtest) { - assert(subtest.type === 'test:start'); - assert(subtest.data.nesting === data.nesting); - assert(subtest.data.name === data.name); - } - let prefix = ''; - while (this.#stack.length) { - // Report all the parent `test:start` events - const parent = ArrayPrototypePop(this.#stack); - assert(parent.type === 'test:start'); - const msg = parent.data; - ArrayPrototypeUnshift(this.#reported, msg); - prefix += `${this.#indent(msg.nesting)}${symbols['arrow:right']}${msg.name}\n`; - } - const skippedSubtest = subtest && data.skip && data.skip !== undefined; - const indent = this.#indent(data.nesting); - const duration_ms = data.details?.duration_ms ? ` ${gray}(${data.details.duration_ms}ms)${white}` : ''; - const title = `${data.name}${duration_ms}${skippedSubtest ? ' # SKIP' : ''}`; - if (this.#reported[0] && this.#reported[0].nesting === data.nesting && this.#reported[0].name === data.name) { - // If this test has had children - it was already reported, so slightly modify the output - ArrayPrototypeShift(this.#reported); - return `${prefix}${indent}${color}${symbols['arrow:right']}${white}${title}\n\n`; - } - const error = this.#formatError(data.details?.error, indent); - if (skippedSubtest) { - color = gray; - symbol = symbols['hyphen:minus']; - } - return `${prefix}${indent}${color}${symbol}${title}${error}${white}\n`; - } + ArrayPrototypePush(this.#failedTests, data); + return this.#handleTestReportEvent(type, data); + case 'test:pass': + return this.#handleTestReportEvent(type, data); case 'test:start': ArrayPrototypeUnshift(this.#stack, { __proto__: null, data, type }); break; case 'test:diagnostic': - return `${color}${this.#indent(data.nesting)}${symbol}${data.message}${white}\n`; + return `${colors[type]}${this.#indent(data.nesting)}${symbols[type]}${data.message}${white}\n`; } } _transform({ type, data }, encoding, callback) { callback(null, this.#handleEvent({ type, data })); } + _flush(callback) { + const results = [`\n${colors['test:fail']}${symbols['test:fail']}failing tests:${white}\n`]; + for (let i = 0; i < this.#failedTests.length; i++) { + ArrayPrototypePush(results, this.#formatTestReport( + 'test:fail', + this.#failedTests[i], + )); + } + callback(null, ArrayPrototypeJoin(results, '\n')); + } } module.exports = SpecReporter; diff --git a/test/message/test_runner_output_spec_reporter.out b/test/message/test_runner_output_spec_reporter.out index d5b443010e77cd..b3ca09b0561893 100644 --- a/test/message/test_runner_output_spec_reporter.out +++ b/test/message/test_runner_output_spec_reporter.out @@ -283,3 +283,212 @@ skipped 10 todo 5 duration_ms * + + failing tests: + + sync fail todo (*ms) + Error: thrown from sync fail todo + * + * + * + * + * + * + * + + sync fail todo with message (*ms) + Error: thrown from sync fail todo with message + * + * + * + * + * + * + * + + sync throw fail (*ms) + Error: thrown from sync throw fail + * + * + * + * + * + * + * + + async throw fail (*ms) + Error: thrown from async throw fail + * + * + * + * + * + * + * + + async skip fail (*ms) + Error: thrown from async throw fail + * + * + * + * + * + * + * + + async assertion fail (*ms) + AssertionError [ERR_ASSERTION]: Expected values to be strictly equal: + + true !== false + + * + * + * + * + * + * + * { + generatedMessage: true, + code: 'ERR_ASSERTION', + actual: true, + expected: false, + operator: 'strictEqual' + } + + reject fail (*ms) + Error: rejected from reject fail + * + * + * + * + * + * + * + + +sync throw fail (*ms) + Error: thrown from subtest sync throw fail + * + * + * + * + * + * + * + * + * + * + + subtest sync throw fail (*ms) + '1 subtest failed' + + sync throw non-error fail (*ms) + Symbol(thrown symbol from sync throw non-error fail) + + +long running (*ms) + 'test did not finish before its parent and was cancelled' + + top level (*ms) + '1 subtest failed' + + sync skip option is false fail (*ms) + Error: this should be executed + * + * + * + * + * + * + * + + callback fail (*ms) + Error: callback failure + * + * + + callback also returns a Promise (*ms) + 'passed a callback but also returned a Promise' + + callback throw (*ms) + Error: thrown from callback throw + * + * + * + * + * + * + * + + callback called twice (*ms) + 'callback invoked multiple times' + + callback called twice in future tick (*ms) + Error [ERR_TEST_FAILURE]: callback invoked multiple times + * + failureType: 'multipleCallbackInvocations', + cause: 'callback invoked multiple times', + code: 'ERR_TEST_FAILURE' + } + + callback async throw (*ms) + Error: thrown from callback async throw + * + * + + custom inspect symbol fail (*ms) + customized + + custom inspect symbol that throws fail (*ms) + { foo: 1, [Symbol(nodejs.util.inspect.custom)]: [Function: [nodejs.util.inspect.custom]] } + + sync throw fails at first (*ms) + Error: thrown from subtest sync throw fails at first + * + * + * + * + * + * + * + * + * + * + + sync throw fails at second (*ms) + Error: thrown from subtest sync throw fails at second + * + * + * + * + * + * + * + * + * + * + + subtest sync throw fails (*ms) + '2 subtests failed' + + timed out async test (*ms) + 'test timed out after 5ms' + + timed out callback test (*ms) + 'test timed out after 5ms' + + rejected thenable (*ms) + 'custom error' + + unfinished test with uncaughtException (*ms) + Error: foo + * + * + * + + unfinished test with unhandledRejection (*ms) + Error: bar + * + * + * + + invalid subtest fail (*ms) + 'test could not be started because its parent finished' diff --git a/test/pseudo-tty/test_runner_default_reporter.out b/test/pseudo-tty/test_runner_default_reporter.out index aec99725c61cba..9aa2fbefb9e3ac 100644 --- a/test/pseudo-tty/test_runner_default_reporter.out +++ b/test/pseudo-tty/test_runner_default_reporter.out @@ -18,3 +18,16 @@ [34m* skipped 1[39m [34m* todo 0[39m [34m* duration_ms *[39m + +[31m* failing tests:[39m + +[31m* should fail [90m(*ms)[39m + Error: fail + at * [90m(*)[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m +[39m From c4fd2c75fcb53393c514517dae8aec1de584cf9c Mon Sep 17 00:00:00 2001 From: Shiba Rin Date: Wed, 22 Mar 2023 18:57:07 +0800 Subject: [PATCH 2/2] test_runner: fix improper text color reset Upon 'test:fail', text color is not reset correctly if duration is not printed. --- lib/internal/test_runner/reporter/spec.js | 2 +- .../test_runner_default_reporter.js | 4 ++ .../test_runner_default_reporter.out | 41 +++++++++++++++---- 3 files changed, 39 insertions(+), 8 deletions(-) diff --git a/lib/internal/test_runner/reporter/spec.js b/lib/internal/test_runner/reporter/spec.js index c768cde4b98018..2e3ba834351970 100644 --- a/lib/internal/test_runner/reporter/spec.js +++ b/lib/internal/test_runner/reporter/spec.js @@ -76,7 +76,7 @@ class SpecReporter extends Transform { color = gray; symbol = symbols['hyphen:minus']; } - return `${prefix}${indent}${color}${symbol}${title}${error}${white}`; + return `${prefix}${indent}${color}${symbol}${title}${white}${error}`; } #handleTestReportEvent(type, data) { const subtest = ArrayPrototypeShift(this.#stack); // This is the matching `test:start` event diff --git a/test/pseudo-tty/test_runner_default_reporter.js b/test/pseudo-tty/test_runner_default_reporter.js index 1c6cda0ebbdd51..1596603b217660 100644 --- a/test/pseudo-tty/test_runner_default_reporter.js +++ b/test/pseudo-tty/test_runner_default_reporter.js @@ -9,3 +9,7 @@ const test = require('node:test'); test('should pass', () => {}); test('should fail', () => { throw new Error('fail'); }); test('should skip', { skip: true }, () => {}); +test('parent', () => { + test('should fail', () => { throw new Error('fail'); }); + test('should pass but parent fail', () => {}); +}); diff --git a/test/pseudo-tty/test_runner_default_reporter.out b/test/pseudo-tty/test_runner_default_reporter.out index 9aa2fbefb9e3ac..f032cf0a291562 100644 --- a/test/pseudo-tty/test_runner_default_reporter.out +++ b/test/pseudo-tty/test_runner_default_reporter.out @@ -1,5 +1,5 @@ [32m* should pass [90m(*ms)[39m[39m -[31m* should fail [90m(*ms)[39m +[31m* should fail [90m(*ms)[39m[39m Error: fail at * [90m(*)[39m [90m at *[39m @@ -8,20 +8,34 @@ [90m at *[39m [90m at *[39m [90m at *[39m -** + [90m* should skip [90m(*ms)[39m # SKIP[39m -[34m* tests 3[39m +* parent + [31m* should fail [90m(*ms)[39m[39m + Error: fail + at * [90m(*)[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m + + [31m* should pass but parent fail [90m(*ms)[39m[39m + [32m'test did not finish before its parent and was cancelled'[39m + +[31m* [39mparent [90m(*ms)[39m + +[34m* tests 6[39m [34m* suites 0[39m [34m* pass 1[39m -[34m* fail 1[39m -[34m* cancelled 0[39m +[34m* fail 3[39m +[34m* cancelled 1[39m [34m* skipped 1[39m [34m* todo 0[39m [34m* duration_ms *[39m [31m* failing tests:[39m -[31m* should fail [90m(*ms)[39m +[31m* should fail [90m(*ms)[39m[39m Error: fail at * [90m(*)[39m [90m at *[39m @@ -30,4 +44,17 @@ [90m at *[39m [90m at *[39m [90m at *[39m -[39m + +[31m* should fail [90m(*ms)[39m[39m + Error: fail + at * [90m(*)[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m + [90m at *[39m + +[31m* should pass but parent fail [90m(*ms)[39m[39m + [32m'test did not finish before its parent and was cancelled'[39m + +[31m* parent [90m(*ms)[39m[39m + [32m'2 subtests failed'[39m