From 69f2acea40b2a702911b8ff02444bc108de3214c Mon Sep 17 00:00:00 2001 From: Mihir Bhansali Date: Tue, 23 Apr 2024 12:31:23 -0400 Subject: [PATCH] test_runner: display failed test stack trace with dot reporter PR-URL: https://github.com/nodejs/node/pull/52655 Reviewed-By: Matteo Collina Reviewed-By: Moshe Atlow Reviewed-By: Chemi Atlow --- lib/internal/test_runner/reporter/dot.js | 14 +- lib/internal/test_runner/reporter/spec.js | 89 ++----- lib/internal/test_runner/reporter/utils.js | 93 ++++++++ .../test-runner/output/dot_reporter.snapshot | 221 ++++++++++++++++++ .../test-runner/output/eval_dot.snapshot | 12 + test/parallel/test-runner-output.mjs | 4 +- test/parallel/test-runner-reporters.js | 27 ++- 7 files changed, 376 insertions(+), 84 deletions(-) create mode 100644 lib/internal/test_runner/reporter/utils.js diff --git a/lib/internal/test_runner/reporter/dot.js b/lib/internal/test_runner/reporter/dot.js index 3b8217caf25c9d..e9ba0b8dc7bd11 100644 --- a/lib/internal/test_runner/reporter/dot.js +++ b/lib/internal/test_runner/reporter/dot.js @@ -1,18 +1,22 @@ 'use strict'; - const { + ArrayPrototypePush, MathMax, } = primordials; +const colors = require('internal/util/colors'); +const { formatTestReport } = require('internal/test_runner/reporter/utils'); module.exports = async function* dot(source) { let count = 0; let columns = getLineLength(); - for await (const { type } of source) { + const failedTests = []; + for await (const { type, data } of source) { if (type === 'test:pass') { yield '.'; } if (type === 'test:fail') { yield 'X'; + ArrayPrototypePush(failedTests, data); } if ((type === 'test:fail' || type === 'test:pass') && ++count === columns) { yield '\n'; @@ -23,6 +27,12 @@ module.exports = async function* dot(source) { } } yield '\n'; + if (failedTests.length > 0) { + yield `\n${colors.red}Failed tests:${colors.white}\n\n`; + for (const test of failedTests) { + yield formatTestReport('test:fail', test); + } + } }; function getLineLength() { diff --git a/lib/internal/test_runner/reporter/spec.js b/lib/internal/test_runner/reporter/spec.js index e0335c5bdd3163..2092d22e3fe77f 100644 --- a/lib/internal/test_runner/reporter/spec.js +++ b/lib/internal/test_runner/reporter/spec.js @@ -1,97 +1,35 @@ 'use strict'; - const { ArrayPrototypeJoin, ArrayPrototypePop, ArrayPrototypePush, ArrayPrototypeShift, ArrayPrototypeUnshift, - RegExpPrototypeSymbolSplit, - SafeMap, - StringPrototypeRepeat, - hardenRegExp, } = primordials; const assert = require('assert'); const Transform = require('internal/streams/transform'); -const { inspectWithNoCustomRetry } = require('internal/errors'); const colors = require('internal/util/colors'); const { kSubtestsFailed } = require('internal/test_runner/test'); const { getCoverageReport } = require('internal/test_runner/utils'); const { relative } = require('path'); +const { + formatTestReport, + indent, + reporterColorMap, + reporterUnicodeSymbolMap, +} = require('internal/test_runner/reporter/utils'); -const symbols = { - '__proto__': null, - 'test:fail': '\u2716 ', - 'test:pass': '\u2714 ', - 'test:diagnostic': '\u2139 ', - 'test:coverage': '\u2139 ', - 'arrow:right': '\u25B6 ', - 'hyphen:minus': '\uFE63 ', -}; class SpecReporter extends Transform { #stack = []; #reported = []; - #indentMemo = new SafeMap(); #failedTests = []; #cwd = process.cwd(); - #inspectOptions; - #colors; constructor() { super({ __proto__: null, writableObjectMode: true }); colors.refresh(); - this.#inspectOptions = { __proto__: null, colors: colors.shouldColorize(process.stdout), breakLength: Infinity }; - this.#colors = { - '__proto__': null, - 'test:fail': colors.red, - 'test:pass': colors.green, - 'test:diagnostic': colors.blue, - }; } - #indent(nesting) { - let value = this.#indentMemo.get(nesting); - if (value === undefined) { - value = StringPrototypeRepeat(' ', nesting); - this.#indentMemo.set(nesting, value); - } - - return value; - } - #formatError(error, indent) { - if (!error) return ''; - const err = error.code === 'ERR_TEST_FAILURE' ? error.cause : error; - const message = ArrayPrototypeJoin( - RegExpPrototypeSymbolSplit( - hardenRegExp(/\r?\n/), - inspectWithNoCustomRetry(err, this.#inspectOptions), - ), `\n${indent} `); - return `\n${indent} ${message}\n`; - } - #formatTestReport(type, data, prefix = '', indent = '', hasChildren = false) { - let color = this.#colors[type] ?? colors.white; - let symbol = symbols[type] ?? ' '; - const { skip, todo } = data; - const duration_ms = data.details?.duration_ms ? ` ${colors.gray}(${data.details.duration_ms}ms)${colors.white}` : ''; - let title = `${data.name}${duration_ms}`; - - if (skip !== undefined) { - title += ` # ${typeof skip === 'string' && skip.length ? skip : 'SKIP'}`; - } else if (todo !== undefined) { - title += ` # ${typeof todo === 'string' && todo.length ? todo : 'TODO'}`; - } - const error = this.#formatError(data.details?.error, indent); - if (hasChildren) { - // If this test has had children - it was already reported, so slightly modify the output - const err = !error || data.details?.error?.failureType === 'subtestsFailed' ? '' : `\n${error}`; - return `${prefix}${indent}${color}${symbols['arrow:right']}${colors.white}${title}${err}`; - } - if (skip !== undefined) { - color = colors.gray; - symbol = symbols['hyphen:minus']; - } - return `${prefix}${indent}${color}${symbol}${title}${colors.white}${error}`; - } #handleTestReportEvent(type, data) { const subtest = ArrayPrototypeShift(this.#stack); // This is the matching `test:start` event if (subtest) { @@ -106,15 +44,15 @@ class SpecReporter extends Transform { assert(parent.type === 'test:start'); const msg = parent.data; ArrayPrototypeUnshift(this.#reported, msg); - prefix += `${this.#indent(msg.nesting)}${symbols['arrow:right']}${msg.name}\n`; + prefix += `${indent(msg.nesting)}${reporterUnicodeSymbolMap['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 indent = this.#indent(data.nesting); - return `${this.#formatTestReport(type, data, prefix, indent, hasChildren)}\n`; + const indentation = indent(data.nesting); + return `${formatTestReport(type, data, prefix, indentation, hasChildren)}\n`; } #handleEvent({ type, data }) { switch (type) { @@ -132,9 +70,10 @@ class SpecReporter extends Transform { case 'test:stdout': return data.message; case 'test:diagnostic': - return `${this.#colors[type]}${this.#indent(data.nesting)}${symbols[type]}${data.message}${colors.white}\n`; + return `${reporterColorMap[type]}${indent(data.nesting)}${reporterUnicodeSymbolMap[type]}${data.message}${colors.white}\n`; case 'test:coverage': - return getCoverageReport(this.#indent(data.nesting), data.summary, symbols['test:coverage'], colors.blue, true); + return getCoverageReport(indent(data.nesting), data.summary, + reporterUnicodeSymbolMap['test:coverage'], colors.blue, true); } } _transform({ type, data }, encoding, callback) { @@ -145,10 +84,10 @@ class SpecReporter extends Transform { callback(null, ''); return; } - const results = [`\n${this.#colors['test:fail']}${symbols['test:fail']}failing tests:${colors.white}\n`]; + const results = [`\n${reporterColorMap['test:fail']}${reporterUnicodeSymbolMap['test:fail']}failing tests:${colors.white}\n`]; for (let i = 0; i < this.#failedTests.length; i++) { const test = this.#failedTests[i]; - const formattedErr = this.#formatTestReport('test:fail', test); + const formattedErr = formatTestReport('test:fail', test); if (test.file) { const relPath = relative(this.#cwd, test.file); diff --git a/lib/internal/test_runner/reporter/utils.js b/lib/internal/test_runner/reporter/utils.js new file mode 100644 index 00000000000000..42c4ffa3cdaaec --- /dev/null +++ b/lib/internal/test_runner/reporter/utils.js @@ -0,0 +1,93 @@ +'use strict'; +const { + ArrayPrototypeJoin, + RegExpPrototypeSymbolSplit, + SafeMap, + StringPrototypeRepeat, + hardenRegExp, +} = primordials; +const colors = require('internal/util/colors'); +const { inspectWithNoCustomRetry } = require('internal/errors'); +const indentMemo = new SafeMap(); + +const inspectOptions = { + __proto__: null, + colors: colors.shouldColorize(process.stdout), + breakLength: Infinity, +}; + +const reporterUnicodeSymbolMap = { + '__proto__': null, + 'test:fail': '\u2716 ', + 'test:pass': '\u2714 ', + 'test:diagnostic': '\u2139 ', + 'test:coverage': '\u2139 ', + 'arrow:right': '\u25B6 ', + 'hyphen:minus': '\uFE63 ', +}; + +const reporterColorMap = { + '__proto__': null, + get 'test:fail'() { + return colors.red; + }, + get 'test:pass'() { + return colors.green; + }, + get 'test:diagnostic'() { + return colors.blue; + }, +}; + +function indent(nesting) { + let value = indentMemo.get(nesting); + if (value === undefined) { + value = StringPrototypeRepeat(' ', nesting); + indentMemo.set(nesting, value); + } + return value; +} + +function formatError(error, indent) { + if (!error) return ''; + const err = error.code === 'ERR_TEST_FAILURE' ? error.cause : error; + const message = ArrayPrototypeJoin( + RegExpPrototypeSymbolSplit( + hardenRegExp(/\r?\n/), + inspectWithNoCustomRetry(err, inspectOptions), + ), `\n${indent} `); + return `\n${indent} ${message}\n`; +} + +function formatTestReport(type, data, prefix = '', indent = '', hasChildren = false) { + let color = reporterColorMap[type] ?? colors.white; + let symbol = reporterUnicodeSymbolMap[type] ?? ' '; + const { skip, todo } = data; + const duration_ms = data.details?.duration_ms ? ` ${colors.gray}(${data.details.duration_ms}ms)${colors.white}` : ''; + let title = `${data.name}${duration_ms}`; + + if (skip !== undefined) { + title += ` # ${typeof skip === 'string' && skip.length ? skip : 'SKIP'}`; + } else if (todo !== undefined) { + title += ` # ${typeof todo === 'string' && todo.length ? todo : 'TODO'}`; + } + const error = formatError(data.details?.error, indent); + if (hasChildren) { + // If this test has had children - it was already reported, so slightly modify the output + const err = !error || data.details?.error?.failureType === 'subtestsFailed' ? '' : `\n${error}`; + return `${prefix}${indent}${color}${reporterUnicodeSymbolMap['arrow:right']}${colors.white}${title}${err}`; + } + if (skip !== undefined) { + color = colors.gray; + symbol = reporterUnicodeSymbolMap['hyphen:minus']; + } + return `${prefix}${indent}${color}${symbol}${title}${colors.white}${error}`; +} + +module.exports = { + __proto__: null, + reporterUnicodeSymbolMap, + reporterColorMap, + formatTestReport, + indent, +}; diff --git a/test/fixtures/test-runner/output/dot_reporter.snapshot b/test/fixtures/test-runner/output/dot_reporter.snapshot index 7c6b0ff2356b77..5f2bf18e1d0137 100644 --- a/test/fixtures/test-runner/output/dot_reporter.snapshot +++ b/test/fixtures/test-runner/output/dot_reporter.snapshot @@ -2,3 +2,224 @@ XXX.....X..X...X.... .....X...XXX.XX..... .XXXXXXX...XXXXX + +Failed tests: + +✖ sync fail todo (*ms) # TODO + Error: thrown from sync fail todo + * + * + * + * + * + * + * +✖ sync fail todo with message (*ms) # this is a failing todo + 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) # SKIP + 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 + * { + code: 'ERR_TEST_FAILURE', + failureType: 'multipleCallbackInvocations', + cause: 'callback invoked multiple times' + } +✖ 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 *ms' +✖ timed out callback test (*ms) + 'test timed out after *ms' +✖ rejected thenable (*ms) + 'custom error' +✖ unfinished test with uncaughtException (*ms) + Error: foo + * + * + * +✖ unfinished test with unhandledRejection (*ms) + Error: bar + * + * + * +✖ assertion errors display actual and expected properly (*ms) + AssertionError [ERR_ASSERTION]: Expected values to be loosely deep-equal: + + { + bar: 1, + baz: { + date: 1970-01-01T00:00:00.000Z, + null: null, + number: 1, + string: 'Hello', + undefined: undefined + }, + boo: [ + 1 + ], + foo: 1 + } + + should loosely deep-equal + + { + baz: { + date: 1970-01-01T00:00:00.000Z, + null: null, + number: 1, + string: 'Hello', + undefined: undefined + }, + boo: [ + 1 + ], + circular: { + bar: 2, + c: [Circular *1] + } + } + * { + generatedMessage: true, + code: 'ERR_ASSERTION', + actual: [Object], + expected: [Object], + operator: 'deepEqual' + } +✖ invalid subtest fail (*ms) + 'test could not be started because its parent finished' diff --git a/test/fixtures/test-runner/output/eval_dot.snapshot b/test/fixtures/test-runner/output/eval_dot.snapshot index 901a287a41ebfa..8a22cfd477b15d 100644 --- a/test/fixtures/test-runner/output/eval_dot.snapshot +++ b/test/fixtures/test-runner/output/eval_dot.snapshot @@ -1 +1,13 @@ .X + +Failed tests: + +✖ fails (*ms) + Error: fail + * + * + * + * + * + * + * diff --git a/test/parallel/test-runner-output.mjs b/test/parallel/test-runner-output.mjs index 1c5b078b23b297..d65e14de1fb0cb 100644 --- a/test/parallel/test-runner-output.mjs +++ b/test/parallel/test-runner-output.mjs @@ -93,7 +93,7 @@ const tests = [ { name: 'test-runner/output/abort_hooks.js' }, { name: 'test-runner/output/describe_it.js' }, { name: 'test-runner/output/describe_nested.js' }, - { name: 'test-runner/output/eval_dot.js' }, + { name: 'test-runner/output/eval_dot.js', transform: specTransform }, { name: 'test-runner/output/eval_spec.js', transform: specTransform }, { name: 'test-runner/output/eval_tap.js' }, { name: 'test-runner/output/hooks.js' }, @@ -110,7 +110,7 @@ const tests = [ { name: 'test-runner/output/no_refs.js' }, { name: 'test-runner/output/no_tests.js' }, { name: 'test-runner/output/only_tests.js' }, - { name: 'test-runner/output/dot_reporter.js' }, + { name: 'test-runner/output/dot_reporter.js', transform: specTransform }, { name: 'test-runner/output/junit_reporter.js', transform: junitTransform }, { name: 'test-runner/output/spec_reporter_successful.js', transform: specTransform }, { name: 'test-runner/output/spec_reporter.js', transform: specTransform }, diff --git a/test/parallel/test-runner-reporters.js b/test/parallel/test-runner-reporters.js index 6d1f9ff6be34e7..a412bd099ec68e 100644 --- a/test/parallel/test-runner-reporters.js +++ b/test/parallel/test-runner-reporters.js @@ -25,7 +25,10 @@ describe('node:test reporters', { concurrency: true }, () => { it('should default destination to stdout when passing a single reporter', async () => { const child = spawnSync(process.execPath, ['--test', '--test-reporter', 'dot', testFile]); assert.strictEqual(child.stderr.toString(), ''); - assert.strictEqual(child.stdout.toString(), '.XX.\n'); + assert.match(child.stdout.toString(), /\.XX\.\n/); + assert.match(child.stdout.toString(), /Failed tests:/); + assert.match(child.stdout.toString(), /✖ failing/); + assert.match(child.stdout.toString(), /✖ nested/); }); it('should throw when passing reporters without a destination', async () => { @@ -44,13 +47,19 @@ describe('node:test reporters', { concurrency: true }, () => { const child = spawnSync(process.execPath, ['--test', '--test-reporter', 'dot', '--test-reporter-destination', 'stdout', testFile]); assert.strictEqual(child.stderr.toString(), ''); - assert.strictEqual(child.stdout.toString(), '.XX.\n'); + assert.match(child.stdout.toString(), /\.XX\.\n/); + assert.match(child.stdout.toString(), /Failed tests:/); + assert.match(child.stdout.toString(), /✖ failing/); + assert.match(child.stdout.toString(), /✖ nested/); }); it('should support stderr as a destination', async () => { const child = spawnSync(process.execPath, ['--test', '--test-reporter', 'dot', '--test-reporter-destination', 'stderr', testFile]); - assert.strictEqual(child.stderr.toString(), '.XX.\n'); + assert.match(child.stderr.toString(), /\.XX\.\n/); + assert.match(child.stderr.toString(), /Failed tests:/); + assert.match(child.stderr.toString(), /✖ failing/); + assert.match(child.stderr.toString(), /✖ nested/); assert.strictEqual(child.stdout.toString(), ''); }); @@ -60,7 +69,11 @@ describe('node:test reporters', { concurrency: true }, () => { ['--test', '--test-reporter', 'dot', '--test-reporter-destination', file, testFile]); assert.strictEqual(child.stderr.toString(), ''); assert.strictEqual(child.stdout.toString(), ''); - assert.strictEqual(fs.readFileSync(file, 'utf8'), '.XX.\n'); + const fileContents = fs.readFileSync(file, 'utf8'); + assert.match(fileContents, /\.XX\.\n/); + assert.match(fileContents, /Failed tests:/); + assert.match(fileContents, /✖ failing/); + assert.match(fileContents, /✖ nested/); }); it('should disallow using v8-serializer as reporter', async () => { @@ -81,7 +94,11 @@ describe('node:test reporters', { concurrency: true }, () => { testFile]); assert.match(child.stdout.toString(), /TAP version 13/); assert.match(child.stdout.toString(), /# duration_ms/); - assert.strictEqual(fs.readFileSync(file, 'utf8'), '.XX.\n'); + const fileContents = fs.readFileSync(file, 'utf8'); + assert.match(fileContents, /\.XX\.\n/); + assert.match(fileContents, /Failed tests:/); + assert.match(fileContents, /✖ failing/); + assert.match(fileContents, /✖ nested/); const file2Contents = fs.readFileSync(file2, 'utf8'); assert.match(file2Contents, /▶ nested/); assert.match(file2Contents, /✔ ok/);