test_runner: display failed test stack trace with dot reporter

PR-URL: https://github.com/nodejs/node/pull/52655
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Moshe Atlow <moshe@atlow.co.il>
Reviewed-By: Chemi Atlow <chemi@atlow.co.il>

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() {

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);
+    const indentation = indent(data.nesting);
-    return `${this.#formatTestReport(type, data, prefix, indent, hasChildren)}\n`;
+    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);

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,
+};

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: <ref *1> {
+      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'

test/fixtures/test-runner/output/eval_dot.snapshot

@@ -1 +1,13 @@
 .X
+
+Failed tests:
+
+✖ fails (*ms)
+  Error: fail
+      *
+      *
+      *
+      *
+      *
+      *
+      *

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 },

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/);