test_runner: incorrect unwrapping of errors in after() when using the tap reporter

[mcollina]

Consider this test:

const test = require('node:test')

test('should print the error', (t) => {
  t.after(async () => {
    throw new Error('kaboom')
  })
})

If I run it normally, I get:

✖ should print the error (0.880917ms)
  Error: kaboom
      at TestContext.<anonymous> (/Users/matteo/tmp/bug.js:5:11)
      at TestHook.runInAsyncScope (node:async_hooks:206:9)
      at TestHook.run (node:internal/test_runner/test:580:25)
      at TestHook.run (node:internal/test_runner/test:759:18)
      at TestHook.run (node:internal/util:500:12)
      at node:internal/test_runner/test:516:20
      at async Test.runHook (node:internal/test_runner/test:514:7)
      at async after (node:internal/test_runner/test:542:9)
      at async Test.run (node:internal/test_runner/test:590:7)
      at async startSubtest (node:internal/test_runner/harness:204:3)

ℹ tests 1
ℹ suites 0
ℹ pass 0
ℹ fail 1
ℹ cancelled 0
ℹ skipped 0
ℹ todo 0
ℹ duration_ms 40.280833

✖ failing tests:

✖ should print the error (0.880917ms)
  Error: kaboom
      at TestContext.<anonymous> (/Users/matteo/tmp/bug.js:5:11)
      at TestHook.runInAsyncScope (node:async_hooks:206:9)
      at TestHook.run (node:internal/test_runner/test:580:25)
      at TestHook.run (node:internal/test_runner/test:759:18)
      at TestHook.run (node:internal/util:500:12)
      at node:internal/test_runner/test:516:20
      at async Test.runHook (node:internal/test_runner/test:514:7)
      at async after (node:internal/test_runner/test:542:9)
      at async Test.run (node:internal/test_runner/test:590:7)
      at async startSubtest (node:internal/test_runner/harness:204:3)

If I run in a non-interactive process such as node --test bug.js | less, I get the error detail scrambled:

TAP version 13
# Subtest: should print the error
not ok 1 - should print the error
  ---
  duration_ms: 0.974875
  failureType: 'hookFailed'
  error: 'failed running after hook'
  code: 'ERR_TEST_FAILURE'
  stack: |-
    TestContext.<anonymous> (/Users/matteo/tmp/bug.js:5:11)
    TestHook.runInAsyncScope (node:async_hooks:206:9)
    TestHook.run (node:internal/test_runner/test:580:25)
    TestHook.run (node:internal/test_runner/test:759:18)
    TestHook.run (node:internal/util:500:12)
    node:internal/test_runner/test:516:20
    async Test.runHook (node:internal/test_runner/test:514:7)
    async after (node:internal/test_runner/test:542:9)
    async Test.run (node:internal/test_runner/test:590:7)
    async startSubtest (node:internal/test_runner/harness:204:3)
  ...
1..1
# tests 1
# suites 0
# pass 0
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 43.341875

This shows specifically during CI runs, where the pretty reporter is not engaged.

[mcollina]

Closing. I was using v18.16.1 and in v18.17.0 is fixed.

[mcollina]

Actually it's a problem, updating the report.

[cjihrig]

This appears to be a bug with the TAP reporter.

[cjihrig]

This seems to fix it:

diff --git a/lib/internal/test_runner/reporter/tap.js b/lib/internal/test_runner/reporter/tap.js
index 4aec4ba072..e22c647669 100644
--- a/lib/internal/test_runner/reporter/tap.js
+++ b/lib/internal/test_runner/reporter/tap.js
@@ -198,15 +198,14 @@ function jsToYaml(indent, name, value, seen) {
       errStack = cause?.stack ?? errStack;
       errCode = cause?.code ?? errCode;
       errName = cause?.name ?? errName;
+      errMsg = cause?.message ?? errMsg;
+
       if (isAssertionLike(cause)) {
         errExpected = cause.expected;
         errActual = cause.actual;
         errOperator = cause.operator ?? errOperator;
         errIsAssertion = true;
       }
-      if (failureType === kTestCodeFailure) {
-        errMsg = cause?.message ?? errMsg;
-      }
     }
 
     result += jsToYaml(indent, 'error', errMsg, seen);

[cjihrig]

Proposed fix in #48942