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
PR-URL: https://github.com/nodejs/node/pull/47164
Reviewed-By: Moshe Atlow <moshe@atlow.co.il>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

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}${white}${error}`;
+  }
+  #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;

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'

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', () => {});
+});

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,13 +8,53 @@
   [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[39m
+  Error: fail
+      at * [90m(*)[39m
+  [90m    at *[39m
+  [90m    at *[39m
+  [90m    at *[39m
+  [90m    at *[39m
+  [90m    at *[39m
+  [90m    at *[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