[Bug]: Async versions of runAllTimers/runOnlyPendingTimers don't run code in the microtask queue

[steveluscher]

Version

29.7.0

Steps to reproduce

function myFn(cb) {
  queueMicrotask(() => cb());
}

it.each([
  async () => await jest.advanceTimersToNextTimerAsync(),
  async () => await jest.advanceTimersByTimeAsync(1),
  async () => await jest.runAllTimersAsync(),
  async () => await jest.runOnlyPendingTimersAsync(),
])('should advance past queued microtasks using %s', async (asyncFastForward) => {
  expect.assertions(1);
  jest.useFakeTimers();
  const cb = jest.fn();
  myFn(cb);
  await asyncFastForward();
  expect(cb).toHaveBeenCalled();
});

it.each([
  () => jest.advanceTimersToNextTimer(),
  () => jest.advanceTimersByTime(1),
  () => jest.runAllTimers(),
  () => jest.runAllTicks(),
  () => jest.runOnlyPendingTimers(),
])('should advance past queued microtasks using %s', (syncFastForward) => {
  jest.useFakeTimers();
  const cb = jest.fn();
  myFn(cb);
  syncFastForward();
  expect(cb).toHaveBeenCalled();
});

Invite to a live sandbox, running this code: https://replit.com/@StevenLuscher/GainsboroAwareCareware#test.js

Expected behavior

The both the async/sync versions of runAllTimers and runOnlyPendingTimers should execute code scheduled with queueMicrotask.

Actual behavior

 FAIL  ./test.js
  ✓ should advance past queued microtasks using async () => await jest.advanceTimersToNextTimerAsync() (55 ms)
  ✓ should advance past queued microtasks using async () => await jest.advanceTimersByTimeAsync(1) (3 ms)
  ✕ should advance past queued microtasks using async () => await jest.runAllTimersAsync() (3 ms)
  ✕ should advance past queued microtasks using async () => await jest.runOnlyPendingTimersAsync() (6 ms)
  ✓ should advance past queued microtasks using () => jest.advanceTimersToNextTimer() (1 ms)
  ✓ should advance past queued microtasks using () => jest.advanceTimersByTime(1) (8 ms)
  ✓ should advance past queued microtasks using () => jest.runAllTimers() (2 ms)
  ✓ should advance past queued microtasks using () => jest.runAllTicks() (1 ms)
  ✓ should advance past queued microtasks using () => jest.runOnlyPendingTimers() (6 ms)

  ● should advance past queued microtasks using async () => await jest.runAllTimersAsync()

    expect(jest.fn()).toHaveBeenCalled()

    Expected number of calls: >= 1
    Received number of calls:    0

      12 |   myFn(cb);
      13 |   await asyncFastForward();
    > 14 |   expect(cb).toHaveBeenCalled();
         |              ^
      15 | });
      16 |
      17 | it.each([

      at toHaveBeenCalled (test.js:14:14)

  ● should advance past queued microtasks using async () => await jest.runOnlyPendingTimersAsync()

    expect(jest.fn()).toHaveBeenCalled()

    Expected number of calls: >= 1
    Received number of calls:    0

      12 |   myFn(cb);
      13 |   await asyncFastForward();
    > 14 |   expect(cb).toHaveBeenCalled();
         |              ^
      15 | });
      16 |
      17 | it.each([

      at toHaveBeenCalled (test.js:14:14)

Test Suites: 1 failed, 1 total
Tests:       2 failed, 7 passed, 9 total
Snapshots:   0 total
Time:        4.841 s

Additional context

No response

Environment

System:
    OS: Linux 6.2 Ubuntu 20.04.2 LTS (Focal Fossa)
    CPU: (8) x64 Intel(R) Xeon(R) CPU @ 2.20GHz
  Binaries:
    Node: 18.16.1 - /nix/store/0g3sc6fhnhsxx8d837kyj06qcbjind1b-nodejs-18.16.1/bin/node
    npm: 9.5.1 - /nix/store/0g3sc6fhnhsxx8d837kyj06qcbjind1b-nodejs-18.16.1/bin/npm
  npmPackages:
    jest: ^29.7.0 => 29.7.0

[SimenB]

Interesting - this is probably a bug in @sinonjs/fake-timers as the logic in Jest just delegates to that.

Would you be up for sending a PR (either here or in https://github.com/sinonjs/fake-timers) to fix it? 🙂

[steveluscher]

I really want to at least file it over there, but I can't possibly right now.

@fatso83, upon first look do you know exactly what the bug is here?

[fatso83]

Looked at it several times now, going back and forth to the docs of what I expect Jest is calling, - without seeing anything in particular wrong.

[steveluscher]

Darn. Was hoping it would jump out.

Well, I have unit tests for Jest above, if that's enough for you to find it. Or do you need me to rewrite those unit tests inside of @sinonjs/fake-timers?

[SimenB]

Here are the calls in Jest, fwiw. We call the same APIs in sync and async

jest/packages/jest-fake-timers/src/modernFakeTimers.ts

Lines 49 to 71 in a640c65

	runAllTimers(): void {
	if (this._checkFakeTimers()) {
	this._clock.runAll();
	}
	}
	async runAllTimersAsync(): Promise<void> {
	if (this._checkFakeTimers()) {
	await this._clock.runAllAsync();
	}
	}
	runOnlyPendingTimers(): void {
	if (this._checkFakeTimers()) {
	this._clock.runToLast();
	}
	}
	async runOnlyPendingTimersAsync(): Promise<void> {
	if (this._checkFakeTimers()) {
	await this._clock.runToLastAsync();
	}
	}

[fatso83]

I think I have recreated this for the timers / time travellers in question, but I cannot get it failing in the same way. See anything wrong?

fatso83/lolex@1ac5cc4

[SimenB]

Interestingly, I get the opposite test failures if I apply this diff to the above test:

diff --git i/test/issue-async.test.js w/test/issue-async.test.js
index d8e5d7e..d605b85 100644
--- i/test/issue-async.test.js
+++ w/test/issue-async.test.js
@@ -14,7 +14,7 @@ function myFn(cb) {
 
 describe("bug", function () {
     let clock;
-    const timers = ["runAll", "runToLast", "runAllAsync", "runToLastAsync"];
+    const timers = ["runAll", "runToLast"];
 
     afterEach(function () {
         clock.uninstall();
@@ -25,10 +25,17 @@ describe("bug", function () {
     });
 
     timers.forEach((fastForward) => {
-        it(`should advance past queued microtasks using ${fastForward}`, async function () {
+        it(`should advance past queued microtasks using ${fastForward}`,  function () {
             const cb = sinon.fake();
             myFn(cb);
-            await clock[fastForward]();
+            clock[fastForward]();
+            assert.equal(cb.callCount, 1);
+        });
+
+        it(`should advance past queued microtasks using ${fastForward}Async`,  async function () {
+            const cb = sinon.fake();
+            myFn(cb);
+            await clock[`${fastForward}Async`]();
             assert.equal(cb.callCount, 1);
         });
     });

$ npx mocha test/issue-async.test.js

  bug
    1) should advance past queued microtasks using runAll
    ✔ should advance past queued microtasks using runAllAsync
    2) should advance past queued microtasks using runToLast
    ✔ should advance past queued microtasks using runToLastAsync


  2 passing (7ms)
  2 failing

  1) bug
       should advance past queued microtasks using runAll:

      AssertionError [ERR_ASSERTION]: 0 == 1
      + expected - actual

      -0
      +1

      at Context.<anonymous> (test/issue-async.test.js:32:20)
      at process.processImmediate (node:internal/timers:476:21)

  2) bug
       should advance past queued microtasks using runToLast:

      AssertionError [ERR_ASSERTION]: 0 == 1
      + expected - actual

      -0
      +1

      at Context.<anonymous> (test/issue-async.test.js:32:20)
      at process.processImmediate (node:internal/timers:476:21)

[SimenB]

Oh, we need to actually fake queueMicrotask 🙈

diff --git i/test/issue-async.test.js w/test/issue-async.test.js
index d605b85..1326355 100644
--- i/test/issue-async.test.js
+++ w/test/issue-async.test.js
@@ -21,7 +21,7 @@ describe("bug", function () {
     });
 
     beforeEach(function setup() {
-        clock = FakeTimers.install();
+        clock = FakeTimers.install({toFake: ['queueMicrotask']});
     });
 
     timers.forEach((fastForward) => {

Then the sync ones passes, and the async ones fail.

[fatso83]

Aaaah, good call. I get the same and pushed the update. Will register bug

[steveluscher]

Oh yay! I glad you got a repro.

[fatso83]

I think I managed to create a fix for this: sinonjs/fake-timers#485. At least the tests are running ... Would love to have a couple of more 👀 on this before merging. As you can see, the diff is very small, but the async time forwarders seem to have missed running the microtasks, so I think this is simply a matter of placing the running of microtasks in the right place.

Apart from placement, I am not quite sure why the job queue of microtasks is not empty after the tests finish, but all the tasks the test cares about has executed, which is the important part. Would still like to know exactly what Node is doing there.

[SimenB]

Fix is in our semver range, so I think we can close this 🙂

[SimenB]

https://github.com/jestjs/jest/releases/tag/v30.0.0-alpha.1 is out with v11

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.