Throwing an exception on test reporters silently error the test runner

[piranna]

Version

v20.4.0

Platform

Linux executive 6.2.0-25-generic #25-Ubuntu SMP PREEMPT_DYNAMIC Fri Jun 16 17:05:07 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

test runner

What steps will reproduce the bug?

Write and use a custom test reporter on the test runner that throws an exception.

How often does it reproduce? Is there a required condition?

Always.

What is the expected behavior? Why is that the expected behavior?

Throwed exception should be shown to the user in any way. Crashing the test runner with an unhandled exception would be enough. If it's too much agresive and chaotic, at least print the error instance message before exit.

What do you see instead?

Test runner just only exit with exit code 1, there's no other output that can give a clue of what happened and why the test runner didn't work properly.

Additional information

No response

[rluvaton]

Can you please provide a reproduction so it will be easier for us to fix the issue? 😄

[ocodista]

I would like to work on this one. Please assign

[rluvaton]

You can't assign in GitHub issues as far as I know, you can just start working on this

don't forget to add a test that fails on main and pass with your fix :)

[ocodista]

Created a minimum reproduction for this issue
https://github.com/ocodista/node-issue-48937

[piranna]

Created a minimum reproduction for this issue
ocodista/node-issue-48937

This is not exactly the same as the issue I'm facing... I'm using an Async Iterator, meanwhile at https://github.com/ocodista/node-issue-48937/blob/main/customReporter.js, you are using Stream API and throwing an exception. That would be a different unhandled exception, I think the similar one would be to pass the exception to the callback (I'm not fully sure how exceptions handling should work with async iterators...).

[ocodista]

Created a minimum reproduction for this issue
ocodista/node-issue-48937

This is not exactly the same as the issue I'm facing... I'm using an Async Iterator, meanwhile at https://github.com/ocodista/node-issue-48937/blob/main/customReporter.js, you are using Stream API and throwing an exception. That would be a different unhandled exception, I think the similar one would be to pass the exception to the callback (I'm not fully sure how exceptions handling should work with async iterators...).

I just updated the repo and replaced the customReporter implementation with one that uses a generator function.

[piranna]

Can you please provide a reproduction so it will be easier for us to fix the issue?

I found this issue with https://github.com/Mafalda-SFU/node-test-reporter-json/blob/main/index.js, it seems Node.js recently added test:enqueue and test:dequeue events, and since I was not handling them, the switch when to the default branch, throwing the exception.

OffTopic: by the way, this is a JSON reporter, we can talk about including it in Node.js core if interested :-)

[piranna]

I just updated the repo and replaced the customReporter implementation with one that uses a generator function.

Cool, thank you :-)

[cjihrig]

I think this is going to be somewhat involved to fix properly. The problem is that the error from the reporter ends up in the uncaughtException handler. Inside of the handler, we process errors and send them to... the reporter. This is the right thing to do in most cases since we want to control how the errors are logged.

We currently re-throw the error in the case where the test runner has not finished bootstrapping itself yet. I think that's what we should do in this case as well. The problem is distinguishing errors originating from the reporter from other errors. I don't think we can get away with only adding a try...catch or 'error' event handler somewhere because the reporter could technically do something like setImmediate(() => { throw new Error('boom'); });.

I think to properly identify reporter errors, we need to run the TestsStream.prototype[kEmitMessage]() code in a new async context and leverage the existing async hook in harness.js. Essentially, we would track reporter errors like we track errors from the tests themselves.

Of course, we could also let the test runner break when it encounters an error that originates from somewhere other than a test. It's simpler, but less nice IMO (also technically a breaking change since we test this behavior).

[piranna]

I think this is going to be somewhat involved to fix properly. The problem is that the error from the reporter ends up in the uncaughtException handler. Inside of the handler, we process errors and send them to... the reporter.

Difficult to find a more appropriate situation to give here the most obvious intended pun... who watches the watchmen? 🤡

We currently re-throw the error in the case where the test runner has not finished bootstrapping itself yet. I think that's what we should do in this case as well.

I think the same too.

Of course, we could also let the test runner break when it encounters an error that originates from somewhere other than a test. It's simpler, but less nice IMO (also technically a breaking change since we test this behavior).

As a short term solution, I agree with this idea, it can help us to better understand the problem and find a more correct solution. As far as the errors are not being swallowed and silenced as it's currently happening, it's fine for me.

[cjihrig]

As a short term solution, I agree with this idea

I don't think we should look at it like a short term solution. I think we should look at it as "what is the desired behavior forever if we had to pick." Either solution could be implemented before the next release. However, the proper fix could ship in the next release, while the change to let the test runner break would likely need to wait until October to ship.

[piranna]

As a short term solution, I agree with this idea

I don't think we should look at it like a short term solution. I think we should look at it as "what is the desired behavior forever if we had to pick." Either solution could be implemented before the next release. However, the proper fix could ship in the next release, while the change to let the test runner break would likely need to wait until October to ship.

I would have expected that since I didn't have any error handling, the error would have buble up until it got to be an unhandled exception and crash the test runner. How should be the API to handled it? I don't know.

An alternative although more obscure would have been that the error would be redirected to the reporter as a failing test, but if a new exception is thrown that would lead to an infinite loop, but also we could add a field to the error to know if we have already processed it.

[ocodista]

Couldn't new wrap the event calls to the reporter with a try-catch and log the error as something like "ReporterError: ..."?

I think that would be the best output IMO

[piranna]

Couldn't new wrap the event calls to the reporter with a try-catch and log the error as something like "ReporterError: ..."?

I think that would be the best output IMO

I don't fully understand your proposal, can you elaborate it?

[ocodista]

Couldn't new wrap the event calls to the reporter with a try-catch and log the error as something like "ReporterError: ..."?

I think that would be the best output IMO

I don't fully understand your proposal, can you elaborate it?

For example:

From the test_runner we need to call the events of the custom reporter.

My idea is that, whenever we call the event "start" (and others), we add a try-catch where, whenever the error happens, we write to output of the test_runner a new type of error, like CustomReportError: ${error}

[cjihrig]

I just don't think a try...catch alone is going to be enough because errors can be asynchronous, but you're welcome to try that approach. I had something like this in mind:

diff --git a/lib/internal/test_runner/harness.js b/lib/internal/test_runner/harness.js
index 36c36f2de1..86e614ae4d 100644
--- a/lib/internal/test_runner/harness.js
+++ b/lib/internal/test_runner/harness.js
@@ -20,12 +20,15 @@ const { kEmptyObject } = require('internal/util');
 const { kCancelledByParent, Test, Suite } = require('internal/test_runner/test');
 const {
   parseCommandLine,
+  reporterScope,
   setupTestReporters,
 } = require('internal/test_runner/utils');
 const { bigint: hrtime } = process.hrtime;
 
 const testResources = new SafeMap();
 
+testResources.set(reporterScope.asyncId(), reporterScope);
+
 function createTestTree(options = kEmptyObject) {
   return setup(new Test({ __proto__: null, ...options, name: '<root>' }));
 }
@@ -42,6 +45,10 @@ function createProcessEventHandler(eventName, rootTest) {
     // Check if this error is coming from a test. If it is, fail the test.
     const test = testResources.get(executionAsyncId());
 
+    if (test === reporterScope) {
+      throw err;
+    }
+
     if (!test || test.finished) {
       // If the test is already finished or the resource that created the error
       // is not mapped to a Test, report this as a top level diagnostic.
diff --git a/lib/internal/test_runner/utils.js b/lib/internal/test_runner/utils.js
index fba2c31323..04647e9232 100644
--- a/lib/internal/test_runner/utils.js
+++ b/lib/internal/test_runner/utils.js
@@ -19,6 +19,7 @@ const {
   StringPrototypeSlice,
 } = primordials;
 
+const { AsyncResource } = require('async_hooks');
 const { relative } = require('path');
 const { createWriteStream } = require('fs');
 const { pathToFileURL } = require('internal/url');
@@ -35,6 +36,7 @@ const {
 } = require('internal/errors');
 const { compose } = require('stream');
 
+const reporterScope = new AsyncResource('TestReporterScope');
 const coverageColors = {
   __proto__: null,
   high: green,
@@ -162,14 +164,14 @@ async function getReportersMap(reporters, destinations, rootTest) {
 }
 
 
-async function setupTestReporters(rootTest) {
+const setupTestReporters = reporterScope.bind(async (rootTest) => {
   const { reporters, destinations } = parseCommandLine();
   const reportersMap = await getReportersMap(reporters, destinations, rootTest);
   for (let i = 0; i < reportersMap.length; i++) {
     const { reporter, destination } = reportersMap[i];
     compose(rootTest.reporter, reporter).pipe(destination);
   }
-}
+});
 
 let globalTestOptions;
 
@@ -411,6 +413,7 @@ module.exports = {
   isTestFailureError,
   kDefaultPattern,
   parseCommandLine,
+  reporterScope,
   setupTestReporters,
   getCoverageReport,
 };

That solution is not fully tested though, and unfortunately, it makes the test runner take extra ticks to fully bootstrap itself.