Repository: avajs/ava
Pull request #3149 (2022-12-08 21:22:34)

Unref shared worker when all test workers have deregistered
The symptom of this bug was that when shared workers are used and AVA's global timeout is triggered, `ava` exits with 0 instead of 1 (we make heavy use of shared workers and didn't realize until recently that our test workflow in CI is frequently marked as passing when a test times out). Similar symptom to https://github.com/avajs/ava/issues/3098, however I think the underlying issue is quite different.

Added a test that reproduces the error and a tentative fix.

Potentially related: https://github.com/avajs/ava/issues/3098

novemberborn: The changes look good, but it's unclear what the root cause of the bug is. Is AVA exiting earlier than we can set the exit code?
codetheweb: I still don't completely understand the internals of AVA, so some of this might be wrong but this is what I was experiencing when running the test reproduction:

1. The main process was stalling on https://github.com/avajs/ava/blob/4ecfe7d822785c800f80bbcc2b4b3460f339a84e/lib/api.js#L308
2. The Promise array wasn't resolving because the de-registration Promise here: https://github.com/avajs/ava/blob/4ecfe7d822785c800f80bbcc2b4b3460f339a84e/lib/plugin-support/shared-workers.js#L54 never resolved.
3. This Promise never resolved because the main process sent `{type: "deregister-test-worker"}` to the shared worker loader, but the shared worker loader never sent back `{type: "deregistered-test-worker"}` in response. I believe this was because the shared worker loader was being un-referenced too early and getting unloaded.
4. Because the main process didn't get confirmation that the shared worker was deregistered from the test worker, `registrationCount` remained at `1` and the de-registration Promise never resolved.

My patch fixes the reproduction and doesn't break any other tests, but I'm not completely convinced it's the correct behavior. Shouldn't the main process exit with 1 if it times out for any reason (including getting stuck at https://github.com/avajs/ava/blob/4ecfe7d822785c800f80bbcc2b4b3460f339a84e/lib/api.js#L308?)
novemberborn: The exit code is only set when the run completes:

https://github.com/avajs/ava/blob/4ecfe7d822785c800f80bbcc2b4b3460f339a84e/lib/cli.js#L496

But Node.js will exit even when you're awaiting a pending promise, if there's nothing left in the event loop that would let that promise be resolved.

Therefore we need to make sure Node.js doesn't exit on its own, otherwise we'll never set the exit code.

https://nodejs.org/api/worker_threads.html#workerunref states that the worker thread will exit when the event loop in the main thread is empty. Delaying the `unref()` call would therefore keep the main thread alive.

Shared workers may need to do cleanup, so we want them to (be able to) perform tasks when a test worker "goes away". That's what we're awaiting at the end of the run. (But, note that we're counting registrations of possibly different shared workers _per test file_.)

So the question is, why did the event loop become empty when we were still (potentially) performing cleanup? And I don't know, but it seems to be that this could be a race condition when waiting for the various events from the various worker threads.

Long story short, I think this is the correct fix :smile:
novemberborn: I'll try and release this today or tomorrow.
novemberborn: I'll try and release this today or tomorrow.

Patch:
diff --git a/lib/plugin-support/shared-workers.js b/lib/plugin-support/shared-workers.js
index 94030ced..1a23fa23 100644
--- a/lib/plugin-support/shared-workers.js
+++ b/lib/plugin-support/shared-workers.js
@@ -51,8 +51,13 @@ function launchWorker(filename, initialData) {
 export async function observeWorkerProcess(fork, runStatus) {
 	let registrationCount = 0;
 	let signalDeregistered;
+	let launched;
 	const deregistered = new Promise(resolve => {
-		signalDeregistered = resolve;
+		signalDeregistered = () => {
+			// Only unref the worker once all test workers have been deregistered, otherwise the worker may exit before test workers are deregistered
+			launched?.worker.unref();
+			resolve();
+		};
 	});
 
 	fork.promise.finally(() => {
@@ -62,7 +67,7 @@ export async function observeWorkerProcess(fork, runStatus) {
 	});
 
 	fork.onConnectSharedWorker(async ({filename, initialData, port, signalError}) => {
-		const launched = launchWorker(filename, initialData);
+		launched = launchWorker(filename, initialData);
 
 		const handleWorkerMessage = async message => {
 			if (message.type === 'deregistered-test-worker' && message.id === fork.threadId) {
@@ -104,14 +109,7 @@ export async function observeWorkerProcess(fork, runStatus) {
 			});
 
 			launched.worker.on('message', handleWorkerMessage);
-		} catch {
-			return;
-		} finally {
-			// Attaching listeners has the side-effect of referencing the worker.
-			// Explicitly unreference it now so it does not prevent the main process
-			// from exiting.
-			launched.worker.unref();
-		}
+		} catch {}
 	});
 
 	return deregistered;


Test patch:
diff --git a/test/shared-workers/timeout/fixtures/package.json b/test/shared-workers/timeout/fixtures/package.json
new file mode 100644
index 00000000..3e7bec51
--- /dev/null
+++ b/test/shared-workers/timeout/fixtures/package.json
@@ -0,0 +1,9 @@
+{
+	"type": "module",
+	"ava": {
+		"files": [
+			"*.js"
+		],
+		"timeout": "5s"
+	}
+}
diff --git a/test/shared-workers/timeout/fixtures/test.js b/test/shared-workers/timeout/fixtures/test.js
new file mode 100644
index 00000000..60f7d9e3
--- /dev/null
+++ b/test/shared-workers/timeout/fixtures/test.js
@@ -0,0 +1,14 @@
+import test from 'ava';
+import {registerSharedWorker} from 'ava/plugin';
+import delay from 'delay';
+
+registerSharedWorker({
+	filename: new URL('worker.mjs', import.meta.url),
+	supportedProtocols: ['ava-4'],
+});
+
+test('time out', async t => {
+	await delay(10_000);
+
+	t.pass();
+});
diff --git a/test/shared-workers/timeout/fixtures/worker.mjs b/test/shared-workers/timeout/fixtures/worker.mjs
new file mode 100644
index 00000000..fa2d5cab
--- /dev/null
+++ b/test/shared-workers/timeout/fixtures/worker.mjs
@@ -0,0 +1,3 @@
+export default ({negotiateProtocol}) => {
+	negotiateProtocol(['ava-4']).ready();
+};
diff --git a/test/shared-workers/timeout/test.js b/test/shared-workers/timeout/test.js
new file mode 100644
index 00000000..a90d673e
--- /dev/null
+++ b/test/shared-workers/timeout/test.js
@@ -0,0 +1,9 @@
+import test from '@ava/test';
+
+import {fixture} from '../../helpers/exec.js';
+
+test('times out', async t => {
+	const error = await t.throwsAsync(async () => fixture());
+
+	t.is(error.exitCode, 1);
+});