[Bug]: Async function with multiple awaits never resolves when using fake timers

[srmagura]

Version

27.2.0

Steps to reproduce

1. Clone my repo: https://github.com/srmagura/jest-timer-repro
2. yarn install
3. yarn test

Code:

import "jest";

beforeEach(() => {
  jest.useFakeTimers();
});

function delay(duration: number): Promise<void> {
  return new Promise((resolve) => setTimeout(resolve, duration));
}

// PASS
it("delays", async () => {
  const p = delay(100);
  jest.runAllTimers();

  expect(await p).toBeUndefined();
});

// PASS
it("delays once in a function", async () => {
  async function f(): Promise<void> {
    await delay(100);
  }

  const p = f();
  jest.runAllTimers();

  expect(await p).toBeUndefined();
});

// FAIL: Exceeded timeout of 5000 ms for a test.
it("delays twice in a function", async () => {
  async function f(): Promise<void> {
    await delay(100);
    await delay(100);
  }

  const p = f();
  jest.runAllTimers();
  jest.runAllTimers();
  jest.runAllTimers();
  jest.runAllTimers();

  expect(await p).toBeUndefined();
});

// PASS
it("delays twice in a function using real timers", async () => {
  jest.useRealTimers();

  async function f(): Promise<void> {
    await delay(100);
    await delay(100);
  }

  const p = f();
  expect(await p).toBeUndefined();
});

Expected behavior

I expect all tests to pass. In the third test, jest.runAllTimers should cause both delays to complete, and the promise returned by f should resolve.

Actual behavior

The third test fails with

thrown: "Exceeded timeout of 5000 ms for a test.
    Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

Additional context

The result is same when using jest.useFakeTimers('legacy').

Environment

System:
    OS: Windows 10 10.0.19043
    CPU: (12) x64 AMD Ryzen 5 2600 Six-Core Processor            
  Binaries:
    Node: 14.17.6 - C:\Program Files\nodejs\node.EXE
    Yarn: 3.0.2 - ~\AppData\Roaming\npm\yarn.CMD
    npm: 7.23.0 - C:\Program Files\nodejs\npm.CMD
  npmPackages:
    jest: ^27.2.0 => 27.2.0

[nikopavlica]

This could be solvable if jest exposed the async counterparts of @sinonjs/fake-timers methods - the 'modern' implementation of fake timers.

Until that happens, it can be solved by using fake-timers directly:

const FakeTimers = require('@sinonjs/fake-timers');
const clock = FakeTimers.install();

it("delays twice in a function", async () => {
    async function f(): Promise<void> {
        await delay(100);
        await delay(100);
    }

    const p = f();
    await clock.runAllAsync(); // note the async method

    expect(await p).toBeUndefined();
});

[ferrao]

I have a similar situation to @nikopavlica, which i believe is the same issue.
I have some code that I want to test which is similar to this one:

timers.js

module.exports = async function () {
    async function timers() {
        console.log('I am executing');
        await Promise.resolve();
        setTimeout(timers, 1000);
    }
    timers();
    return Promise.resolve();
};

My test code is as follows:

const test = require('../src/timers');

describe('testing timers', () => {
    it('tests timers', async () => {
        jest.useFakeTimers();
        jest.spyOn(console, 'log');

        test();

        jest.advanceTimersByTime(4001);
        // jest.runAllTimers();  // result is the same if I replace previous line with this one
        expect(console.log).toHaveBeenCalledTimes(3);
    });
});

And the test fails with the following output:

expect(jest.fn()).toHaveBeenCalledTimes(expected)

    Expected number of calls: 3
    Received number of calls: 2

No matter how much I advance the timers by, or event if I tell just to run all queued code with jest.runAllTimers(), the result is always the same, only 2 calls to console.log.

But replacing jest timers with the actual sinon timers solves the problem:

describe('testing timers', () => {
    it('tests timers', async () => {
        const clock = require('@sinonjs/fake-timers').install();
        jest.spyOn(console, 'log');
        await test();

        await clock.tickAsync(2001);

        expect(console.log).toHaveBeenCalledTimes(3);
    });
});

I now get the 3 console logs as expected and the test to pass. Furthermore, the proper correlation between the argument to tickAsync and the number of console.log calls exists.

[UsAndRufus]

I encountered this issue whilst writing tests this week. Unfortunately, I was unable to get it to work by switching to the sinon timer library and had to tweak my code. I had something like the following:

const withRetries = ({ attempt }) => async (...args) => {
  let retryCount = 0
  do {
    const result = attempt(...args)

    if (result) {
      return result
    }
    await new Promise(resolve => setTimeout(resolve, 2 ** retryCount * 100))
  } while (retryCount++ <= 2)

  return null
}

const productIdentifierWithRetries = withRetries({ attempt: productIdentifier })
await productIdentifierWithRetries()

In short, it's a generic constructor function that wraps any function and retries it multiple times (full credit, modified from SO). The time to wait increases exponentially. Here's where things get weird though.

In a test case where we have to delay some time, Jest's timer mocking works just fine. However, in tests where it should return null after several failed attempts, the test times out. I checked the maths and adjusted the number of attempts so it would fall well under the timer constraint but it still failed.

I managed to fix this by changing

await new Promise(resolve => setTimeout(resolve, 2 ** retryCount * 100))

to

await new Promise(resolve => setTimeout(resolve, 200))

IE waiting a constant time each loop. I really don't understand why this happened, and it's frustrating to have to change implementation to address test concerns, but at least I got it to work.

[SimenB]

OP is fixed via #12572 by using advanceTimers: true. Available in https://github.com/facebook/jest/releases/tag/v28.0.0-alpha.8

[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.