Test runner executes after() in declared order

[ghost]

Version

v18.16.0

Platform

Linux tester 5.15.0-75-generic #82-Ubuntu SMP Tue Jun 6 23:10:23 UTC 2023 x86_64 GNU/Linux

Subsystem

test_runner

What steps will reproduce the bug?

test("mytest", async (t) => {
	t.after(async () => { console.log("this is declared first"); });
	t.after(async () => { console.log("this is declared next"); });
	t.after(async () => { console.log("this is declared last"); });
});

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

Always.

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

I would expect the after functions to be executed in reverse order:
ℹ this is declared last
ℹ this is declared next
ℹ this is declared first
✔ mytest (3.16807ms)

What do you see instead?

ℹ this is declared first
ℹ this is declared next
ℹ this is declared last
✔ mytest (3.16807ms)

Additional information

Various frameworks provide setup / teardown before and after a test. Usually its desired to perform setup in declared order but teardown in reverse order. This is very convenient because there maybe inter-dependencies. Consider the contrived example of:

1. Create browser instance.
2. Create incognito context.
3. Create browser tab.
4. Do tests inside tab.

Once the test ends, regardless of success/failure these should then be torn down in reverse order:

1. Destroy browser tab.
2. Destroy incognito context.
3. Destroy browser instance.

If after() was executed in reverse order, setup and teardown could be conveniently written as below, providing clean teardown regardless at which point setup failed:

test("mytest", async (t) => {
	const browser = await create_browser_instance();
	t.after(() => destroy_browser_instance(browser));
	const context = await create_incognito_context(browser); // if this fails, browser will still be terminated.
	t.after(() => destroy_incognito_context(context));
	const tab = await create_browser_tab(context); // if this fails, context will still be destroyed and browser terminated.
	t.after(() => destroy_browser_tab(tab));
	// your test here
});

However, not only is after() executed in declared order, subsequent after() are skipped entirely. I also discovered after() eating the reported error, leaving a very confused developer as to why his test failed with nothing but this as output:
▶ Mytest
✔ subtest 1 (17.906258ms)
✔ subtest 2 (32.88647ms)
✔ subtest 3 (21.395154ms)
✔ subtest 4 (27.778948ms)
▶ Mytest (242.726795ms) <-- Red triangle, nothing else.

ℹ tests 1
ℹ pass 0
ℹ fail 1
ℹ cancelled 0
ℹ skipped 0
ℹ todo 0
ℹ duration_ms 361.519968

It took a lot of digging to figure out that the first after() was trying to destroy something that was still in use.

To perform teardown in the correct order I'll have to do it manually:

test("mytest", async (t) => {
	const ctx = {};
	t.after(async () => {
		if (ctx.tab) {
			await destroy_browser_tab(ctx.tab);
		}
		if (ctx.context) {
			await destroy_incognito_context(ctx.context);
		}
		if (ctx.browser) {
			await destroy_browser_instance(ctx.browser);
		}
	});
	ctx.browser = await create_browser_instance();
	ctx.context = await create_incognito_context(ctx.browser);
	ctx.tab = await create_browser_tab(ctx.context);
	// your test here
});

Which makes me wonder why even bother with after() since try {} catch {} finally {} provides the same functionality.

[ghost]

Following monkey patch changes behavior of after() so that:

• Statements are executed in reverse order.
• Exceptions thrown during execution are not eaten.
• Exceptions thrown during execution do not affect remaining statements.

const test = ((originalfn) => {
	return (name, testfn) => {
		originalfn(name, async (t) => {
			const afters = [];
			t.after = (fn) => afters.push(fn);
			try {
				await testfn(t);
			} finally {
				for (const afterfn of afters.reverse()) {
					try {
						await afterfn();
					} catch (err) {
						console.warn(err);
					}
				}
			}
		});
	};
})(require("node:test"));

[pulkit-30]

Hey @MoLow ,
I would like to work on this issue of changing the order of the after() hook in the test_runner. I understand that this is a relatively simple change, but I would like to make sure that I am doing it correctly.
Is there anything I need to keep in mind while working on this?

[MoLow]

I am not sure this is a simple change
and I am not convinced changing the current behavior is the correct thing to do

[ghost]

I am not sure this is a simple change and I am not convinced changing the current behavior is the correct thing to do

If backwards-compatibility is an issue, adding a configuration option similar to how you can specify "only", "concurrency" would solve that problem.

[benjamingr]

I'm hesitant to add this rather than just ship a defer utility on top of Symbol.dispose/asyncDispose

[ghost]

Adding defer() or teardown() would also work.

Note that reverse execution order is not something new, other test frameworks provide reverse execution in various forms.

Mocha runs afterEach hooks in reverse order:
https://github.com/mochajs/mocha/blob/37deed262d4bc0788d32c66636495d10038ad398/lib/runner.js#L598

Run 'afterEach' hooks from bottom up.

Jest's jasmine2 runner executes after in reverse order (https://jestjs.io/docs/setup-teardown):

If you are using jasmine2 test runner, take into account that it calls the after* hooks in the reverse order of declaration.

Ava runs teardown hooks in reverse order (https://github.com/avajs/ava/blob/main/docs/02-execution-context.md#tteardownfn):

Registers the fn function to be run after the test has finished. You can register multiple functions. They'll run in reverse order, so the last registered function is run first. You can use asynchronous functions: only one will run at a time.

[benjamingr]

Mocha runs afterEach hooks in reverse order:

Mocha runs after in fifo order though:

describe("something", () => {
    after(() => console.log(1))
    after(() => console.log(2))
    after(() => console.log(3))
    it("foos", () => {});
})

Would log 1,2,3 and not 3,2,1

And so does Jest (with afterAll, in a much slower fashion and with more verbose output) with the default modern runner. The legacy runner (and jasmine in standalone) does log 3,2,1 but it doesn't seem to be the standard order.

[cjihrig]

I don't think we should change this. Running them in reverse order is, IMO, more mental overhead for users.

[ghost]

Mocha runs afterEach hooks in reverse order:

Mocha runs after in fifo order though:

Need to call afterEach, not after. Calling after executes in forward order as you indicated.

And so does Jest with the default modern runner.

Need to use the jasmine2 runner as stated in Jest's documentation. I'm not sure what the default "modern" runner is as I don't use Jest.

I just wanted to point out that there are various testing frameworks that provide/perform teardown in reverse order. This includes the custom testing framework I developed for my application. Other languages rely on destructors doing things in the right order.

I don't think we should change this. Running them in reverse order is, IMO, more mental overhead for users.

If I cannot use t.after, how to perform test-specific cleanup / teardown? Wrap the entire test in a try ... finally? Performing teardown inside the actually test introduces non-test related overhead to timing results.

[cjihrig]

If I cannot use t.after, how to perform test-specific cleanup / teardown?

I don't understand this. I use the test runner's hooks to clean up after my tests all the time. If the issue is that you're expecting the after()s to be run in reverse order, then you can reverse the order of the after()s in your code and that should solve the problem?

[MoLow]

also, you can use a single after and run code inside it in whatever order you want. that is inherent to the language, and depending on hooks running in a specific order (that is documented nowhere) seems a lot more magical to me than a single hook running code in whatever order it desires

[benjamingr]

If I cannot use t.after, how to perform test-specific cleanup / teardown? Wrap the entire test in a try ... finally? Performing teardown inside the actually test introduces non-test related overhead to timing results.

I'm wondering if we should abort a test context's AbortController on test completion and not just cancellation to allow this:

test("mytest", async ({ signal }) => {
	const browser = await createBrowserInstance({ signal });
	const context = await createIncognitoContext(browser, { signal });
	const tab = await createBrowserTab(context, { signal });
	// your test here
});

Not entirely related to this issue. (Also it's kind of besides the point but in that specific case it's fine to just close the browser since it owns the context and the tab which would also be closed with it.)

[ghost]

If I cannot use t.after, how to perform test-specific cleanup / teardown?

I don't understand this. I use the test runner's hooks to clean up after my tests all the time. If the issue is that you're expecting the after()s to be run in reverse order, then you can reverse the order of the after()s in your code and that should solve the problem?

How would you reverse the provided example? Like this?

test("mytest", async (t) => {
	const browser = await create_browser_instance();
	const context = await create_incognito_context(browser);
	const tab = await create_browser_tab(context);
	t.after(() => destroy_browser_tab(tab));
	t.after(() => destroy_incognito_context(context));
	t.after(() => destroy_browser_instance(browser));
});

Ah but now for reasons the creation of the tab failed. So now you have a browser and incognito context lingering around until the process terminates. Fine if its just one, not so much if there are several hundreds. One cannot assume setup always succeeds.

also, you can use a single after and run code inside it in whatever order you want. that is inherent to the language, and depending on hooks running in a specific order (that is documented nowhere) seems a lot more magical to me than a single hook running code in whatever order it desires

That means that the user needs to keep track of what should and what shouldn't be torn down. It can be done, yes. But adds lots of boilerplate.

I'm wondering if we should abort a test context's AbortController on test completion and not just cancellation to allow this:
-snip-
Not entirely related to this issue. (Also it's kind of besides the point but in that specific case it's fine to just close the browser since it owns the context and the tab which would also be closed with it.)

Interesting and yes the example is a bit contrived. Obviously killing the browser would kill everything else too. The objects I'm creating are not aware of each other and I'd have to add a lot of extra boilerplate to add dependency tracking. One-liners that say "oh, when this test is done, please kill this for me" are for me easy to write and understand. And it works fine until there's a dependency chain involved.

[cjihrig]

I see what you mean now. Essentially, you want to write your test like this and have the after() hooks run in reverse order:

test("mytest", async (t) => {
  const browser = await create_browser_instance();
  t.after(() => destroy_browser_instance(browser));
  const context = await create_incognito_context(browser);
  t.after(() => destroy_incognito_context(context));
  const tab = await create_browser_tab(context);
  t.after(() => destroy_browser_tab(tab));
});

It's still not a change that I would make, but I guess we can see how others feel.

[ghost]

I see what you mean now. Essentially, you want to write your test like this and have the after() hooks run in reverse order

Yes, exactly. I've since amended the monkey patch I posted earlier to support nested tests and the options parameter which turned it into an unpleasant 60-line hack I rather not have to maintain.

Asking to change the default behavior is probably asking too much but to have some way of telling the runner to execute hooks in reverse would be nice and probably not too much effort.

[benjamingr]

It's still not a change that I would make, but I guess we can see how others feel.

Both mocha and Jest do it the same way we do with Jest even switching from reverse-order to fifo order so I doubt we should change it but I do see the use case and think we should address it.

How would you feel about the abort signal being passed to the test context always aborting when a test (or suite) completes and not just when they are cancelled? ( also cc @MoLow )

[cjihrig]

How would you feel about the abort signal being passed to the test context always aborting when a test (or suite) completes and not just when they are cancelled?

I think it makes sense. If anything was listening to that signal, it should abort at that point anyway.

[rluvaton]

How would you feel about the abort signal being passed to the test context always aborting when a test (or suite) completes and not just when they are cancelled?

@benjamingr how would it solve the problem outlined here?

[benjamingr]

@benjamingr how would it solve the problem outlined here?

You would use the signal for cleanup instead of after hooks like so #48736 (comment)

[rluvaton]

Yeah, I realized it later 😅

[ghost]

I'm not sure why this issue was closed, #48827 doesn't really solve the original problem as (in my experience) event handlers are executed in registration order. So you'd still need to DYI reverse-order cleanup.

[ghost]

I decided to abandon using the built-in test runner for running my tests entirely. Reasons being:

1. Not possible to perform global setup before the first test.
2. Not possible to perform global cleanup after the last test.
3. Suites are executed sequentially, always.
4. Errors thrown in after() prevents execution of subsequent after() calls.
5. All forms of after() are executed in declared order.

Problems 1 means one has to start Puppeteer on-demand and put it behind some kind of synchronization mechanism. Otherwise node would report various leaks due to having more than 8-10 browsers.

Problem 2 makes closing the browser complicated. Not closing the browser properly causes the entire script to hang forever. #48877 doesn't solve the termination problem because the test runner believes tests are still running.

I ended up solving problem 1 & 2 with reference counting but problem 3 then causes the browser to be terminated after each suite as there are no tests running in-between suites. The browser is then re-launched for the next suite. Not a show-stopper but when you have dozens of suites to categorize thousands of tests it starts to hurt performance quite a bit. Having more suites with fewer tests would make the performance impact worse.

Problem 4 means that any and all forms of "kill browser after test" are by definition be unreliable. I had to specifically modify this behavior to prevent scripts from hanging forever due to the browser still being live.

Problem 5 is the reason I opened this issue.

So I'm reverting back to my hand-rolled test runner that exhibits none of these problems and is ironically fewer lines than all the workarounds I had to write to fix the built-in runner. Perhaps I'll revisit the built-in test runner in a couple years but in its current state it is simply not practical for anything but basic tests.

[benjamingr]

Not possible to perform global setup before the first test.
Not possible to perform global cleanup after the last test.

Does --import not work for that case? Or putting it in a global after/before?

Would docs/a guide showing how to run setupTests like logic help?

#48877 doesn't solve the termination problem because the test runner believes tests are still running.

Can you repro?

Suites are executed sequentially, always.

What do you mean sequentially?

Errors thrown in after() prevents execution of subsequent after() calls.

Happy to discuss this, I don't think it was raised before?

All forms of after() are executed in declared order.

Sure, though did the workaround with signal we changed not solve the problem?

[ghost]

Not possible to perform global setup before the first test.
Not possible to perform global cleanup after the last test.

Does --import not work for that case? Or putting it in a global after/before?

--import is not documented. Global before/after operate on a per-file basis. So if you want to organize your tests into multiple files and also want global before/after all tests start/finish, not going to happen.

Would docs/a guide showing how to run setupTests like logic help?

#48877 doesn't solve the termination problem because the test runner believes tests are still running.

Can you repro?

If you don't terminate the browser instance running in the background, the test runner hangs forever. If there is no hard guarantee that termination is performed no matter what... you're going to spend a lot of time SSH-ing into your test server and killing browser instances.

As far as I understand, #48877 is merely an alternative to after().

const puppeteer = require("puppeteer-core");
const { describe, before, test, } = require('node:test');

describe("suite", () => {
	before(async () => {
		browser = await puppeteer.launch({
			dumpio: false,
			pipe: true,
			executablePath: "/usr/bin/chromium",
			ignoreDefaultArgs: [ "about:blank" ],
			waitForInitialPage: false,
			args: [
				"--no-sandbox",
				"--disable-setuid-sandbox",
				"--disable-web-security",
				"--disable-gpu",
				"--font-render-hinting=none",
				`--window-size=1600,900`,
				"--ignore-certificate-errors",
			],
		});
	});
	// simulate termination failure by intentionally not calling await browser.close();
	test("test", async () => {});
});

Suites are executed sequentially, always.

What do you mean sequentially?

Note total duration below being 2 seconds. If I add run({ concurrency: true }); at the end the script just hangs forever.

const { describe, test } = require('node:test');

function sleepFor(ms) {
	return new Promise((resolve) => setTimeout(resolve, ms));
}

describe("first suite", { concurrency: true }, () => {
	test("test 2", async () => {
		await sleepFor(1000);
	});
});

describe("second suite", { concurrency: true }, () => {
	test("test 2", async () => {
		await sleepFor(1000);
	});
})

▶ first suite
  ✔ test 2 (1003.059605ms)
▶ first suite (1006.82399ms)

▶ second suite
  ✔ test 2 (1000.822128ms)
▶ second suite (1001.266743ms)

ℹ tests 2
ℹ pass 2
ℹ fail 0
ℹ cancelled 0
ℹ skipped 0
ℹ todo 0
ℹ duration_ms 2489.708811

Errors thrown in after() prevents execution of subsequent after() calls.

Happy to discuss this, I don't think it was raised before?

Mentioned in submitted issue and also here. Example below. Note that output does not mention the error itself, only "Error: failed running after hook".

const { describe, after, test } = require('node:test');

describe("suite", () => {
	test("test", async () => {
		after(() => {
			throw new Error("oops");
		});
		after(() => {
			console.log("This is never executed");
		});
	});
});

All forms of after() are executed in declared order.

Sure, though did the workaround with signal we changed not solve the problem?

As I mentioned previously, in my experience event listeners are executed in registration order so it doesn't change anything because declared order == registration order.