Test runner: spurious "Promise resolution is still pending but the event loop has already resolved" when a callback tests fails

[domenic]

Version

v21.4.0

Platform

Microsoft Windows NT 10.0.22621.0 x64

Subsystem

test

What steps will reproduce the bug?

Run the following code with node --test test.js:

"use strict";
const { describe, test } = require("node:test");
const assert = require("node:assert");

describe("describe wrapper", () => {
  test("callback test", (t, done) => {
    setTimeout(() => {
      assert.ok(false, "oh no an assert failed");
      done();
    });
  });

  test("promise test", async () => {
    assert.ok(true, "this assert will pass");
  });
});

describe("another describe block", () => {
  test("sync test", () => {
    assert.ok(true, "this assert will pass 2");
  });
});

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

Always

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

It should tell me that "callback test" alone is failing

What do you see instead?

It shows four failure messages: one for callback test (correct), one for describe wrapper, one for sync test, and one for another describe block. The latter three have a (green??) 'Promise resolution is still pending but the event loop has already resolved' failure reason.

$ node --test test.js
▶ describe wrapper
  ✖ callback test (2.4042ms)
    AssertionError [ERR_ASSERTION]: oh no an assert failed
        at Timeout._onTimeout (C:\Users\d\OneDrive - domenic.me\Code\GitHub\jsdom\jsdom\test.js:8:14)
        at listOnTimeout (node:internal/timers:573:17)
        at process.processTimers (node:internal/timers:514:7) {
      generatedMessage: false,
      code: 'ERR_ASSERTION',
      actual: false,
      expected: true,
      operator: '=='
    }

  ✔ promise test (0.2519ms)
▶ describe wrapper (5.4167ms)

  'Promise resolution is still pending but the event loop has already resolved'

▶ another describe block
  ✖ sync test
    'Promise resolution is still pending but the event loop has already resolved'

▶ another describe block

  'Promise resolution is still pending but the event loop has already resolved'

ℹ tests 3
ℹ suites 2
ℹ pass 1
ℹ fail 1
ℹ cancelled 1
ℹ skipped 0
ℹ todo 0
ℹ duration_ms 47.7459

✖ failing tests:

test at test.js:6:3
✖ callback test (2.4042ms)
  AssertionError [ERR_ASSERTION]: oh no an assert failed
      at Timeout._onTimeout (C:\Users\d\OneDrive - domenic.me\Code\GitHub\jsdom\jsdom\test.js:8:14)
      at listOnTimeout (node:internal/timers:573:17)
      at process.processTimers (node:internal/timers:514:7) {
    generatedMessage: false,
    code: 'ERR_ASSERTION',
    actual: false,
    expected: true,
    operator: '=='
  }

test at test.js:5:1
✖ describe wrapper (5.4167ms)
  'Promise resolution is still pending but the event loop has already resolved'

test at test.js:19:3
✖ sync test
  'Promise resolution is still pending but the event loop has already resolved'

test at test.js:18:1
✖ another describe block
  'Promise resolution is still pending but the event loop has already resolved'

Additional information

There isn't a lot of documentation about callback-style tests...

[marco-ippolito]

You can just remove done and it will work as expected.

  test("callback test", () => {
    setTimeout(() => {
      assert.ok(false, "oh no an assert failed");
    });
  });

AFAIK done is useful when you have function thats take a callback and you want to check that it is called or when for some reason can't use assertions:

const { describe, it } = require("node:test");
const assert = require("node:assert");
const fs = require('node:fs');

describe("describe wrapper", async () => {
    it("callback test", (t, done) => {
        fs.readFile('package.json', (err, data) => {
            if (err) done(err); // will fail with [Error: ENOENT: no such file or directory
            else assert.ok(data);
        });
    }, 0);
});

PRs to improve the documentation are always welcomed

[domenic]

That doesn't quite work as expected. In that case, the error gets thrown disconnected from any test, so it looks like all tests are passing, but then there's a mysterious 'test failed' (again, in green?) and a discussion about generating async activity.

Modified script

"use strict";
const { describe, test } = require("node:test");
const assert = require("node:assert");

describe("describe wrapper", () => {
  test("callback test", () => {
    setTimeout(() => {
      assert.ok(false, "oh no an assert failed");
    });
  });

  test("promise test", async () => {
    assert.ok(true, "this assert will pass");
  });
});

describe("another describe block", () => {
  test("sync test", () => {
    assert.ok(true, "this assert will pass 2");
  });
});

Output:

$ node --test test.js
▶ describe wrapper
  ✔ callback test (0.3599ms)
  ✔ promise test (0.1025ms)
▶ describe wrapper (1.6332ms)

▶ another describe block
  ✔ sync test (0.0629ms)
▶ another describe block (0.193ms)

ℹ Warning: Test "callback test" generated asynchronous activity after the test ended. This activity created the error "AssertionError [ERR_ASSERTION]: oh no an
assert failed" and would have caused the test to fail, but instead triggered an uncaughtException event.
✖ test.js (41.915ms)
  'test failed'

ℹ tests 4
ℹ suites 2
ℹ pass 3
ℹ fail 1
ℹ cancelled 0
ℹ skipped 0
ℹ todo 0
ℹ duration_ms 47.6652

✖ failing tests:

test at test.js:1:1
✖ test.js (41.915ms)
  'test failed'

My expectation is that callback tests wait on the callback to be called, or an error to be thrown, in order to tie any thrown errors to the in-progress test. That's how they work in other test frameworks.

[benjamingr]

@nodejs/test_runner @MoLow I think in any case the callback test failing shouldn't interfere with any of the other tests.

Re: the second example - The "fail the test file for an uncaught error" behavior actually seems reasonable to me.

[MoLow]

@nodejs/test_runner @MoLow I think in any case the callback test failing shouldn't interfere with any of the other tests.

Re: the second example - The "fail the test file for an uncaught error" behavior actually seems reasonable to me.

I agree with both these statments

[marco-ippolito]

If the test goes in 'uncaughtException' it's not possible to recover, so it will interfere with other test.

The correct use of 'uncaughtException' is to perform synchronous cleanup of allocated resources
(e.g. file descriptors, handles, etc) before shutting down the process.
It is not safe to resume normal operation after 'uncaughtException'.

I agree with the second statement

[domenic]

In other test frameworks, the framework is responsible for catching the exception, so it never reaches uncaughtException.

[cjihrig]

This seems to fix the issue. The problem is that this never finishes.

diff --git a/lib/internal/test_runner/harness.js b/lib/internal/test_runner/harness.js
index 469ca903c7..b62d4dded6 100644
--- a/lib/internal/test_runner/harness.js
+++ b/lib/internal/test_runner/harness.js
@@ -74,7 +74,7 @@ function createProcessEventHandler(eventName, rootTest) {
     }
 
     test.fail(new ERR_TEST_FAILURE(err, eventName));
-    test.postRun();
+    test.abortController.abort();
   };
 }

It might also be worth considering ref()'ing this timer or implementing another waiting technique, because currently, the following code does not honor its timeout.

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

test({ timeout: 3000 }, (t, done) => {
  // done() is not called but there are no ref()'ed handles so we exit.
});

It might also be worth considering setting a reasonable default test timeout instead of Infinity for the same reason.

Speaking of test timeouts, the new --test-timeout CLI flag behaves surprisingly. Consider the following code run with --test-timeout=2000. It correctly times out when used with --test, but passes without --test. I believe that's because it is not incorporated into parseCommandLine() and the logic that uses it.

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

test((t, done) => {
  setTimeout(done, 3000);
});