Only the first test case respects setting jest.setTimeout()

[thernstig]

For some reason, the second (and third, and fourth and so on) test case does not respect what is set with jest.setTimeout(). Only the first test case does.

I've got a Jest config like this:

module.exports = {
  testSequencer: './tests/e2e/util/jestSequencer.js',
  projects: [
    {
      displayName: 'E2E',
      rootDir: 'tests/e2e',
      preset: 'jest-playwright-preset',
      runner: '<rootDir>/util/serialJestRunner.js',
      setupFilesAfterEnv: [
        '<rootDir>/jest.setup.js',
        '<rootDir>/util/registerAllureReporter',
      ],
      transformIgnorePatterns: [
        '/node_modules/(?!(query-selector-shadow-dom)/)',
      ],
    },
  ],
};

jest.setup.js sets jest.setTimeout(5000);.

When running two test cases where I on purpose delay them (to replicate this), this is what I receive:

 FAIL   E2E  tests/e2e/suite/login/login.e2e.test.js (21.387s)
  \u25cf Login page \u203a has a title

    : Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error:

      22 |   });
      23 | 
    > 24 |   it('has a title', async () => {
         |   ^
      25 |     await sleep(11000);
      26 |     const title = await page.title();
      27 |     expect(title).toBe('Login');

      at new Spec (../../node_modules/jest-jasmine2/build/jasmine/Spec.js:116:22)
      at Suite.<anonymous> (suite/login/login.e2e.test.js:24:3)

 FAIL   E2E  tests/e2e/suite/login/foo.e2e.test.js (15.55s)
  \u25cf Console

    console.error node_modules/jest-jasmine2/build/jasmine/Env.js:248
      Unhandled error
    console.error node_modules/jest-jasmine2/build/jasmine/Env.js:249
      Error: Protocol error (Runtime.callFunctionOn): Session closed. Most likely the page has been closed.
          at CRSession.send (/home/userA/code/projectA/node_modules/playwright-core/lib/chromium/crConnection.js:121:19)
          at CRSession.<anonymous> (/home/userA/code/projectA/node_modules/playwright-core/lib/helper.js:84:31)
          at CRExecutionContext.evaluate (/home/userA/code/projectA/node_modules/playwright-core/lib/chromium/crExecutionContext.js:70:83)
        -- ASYNC --
          at Frame.<anonymous> (/home/userA/code/projectA/node_modules/playwright-core/lib/helper.js:63:23)
          at Page.title (/home/userA/code/projectA/node_modules/playwright-core/lib/page.js:285:33)
          at Page.title (/home/userA/code/projectA/node_modules/playwright-core/lib/helper.js:84:31)
          at Object.<anonymous> (/home/userA/code/projectA/tests/e2e/suite/login/login.e2e.test.js:26:30)

  \u25cf Login page \u203a has a title

    Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.

Notice the 5000ms timeout (which is what I configured) vs the 10000ms, where I have no idea where that comes from.

It can be reproduced by having two tests files with this:

const { promisify } = require('util');

const sleep = promisify(setTimeout);

beforeAll(async () => {
  await page.goto(`http://example.com/`);
}, 10000);

it('sleep', async () => {
  await sleep(11000);
  expect(true).toBe(true);
});

[thernstig]

I have another scenario I expect might be related to the above. I believe there is something really fishy going on. I have 3 it() statements in one test file for 3 different e2e tests on the same page (login page). If I run with headless=false, I can clearly see the first two passing. The third one, which enters proper login details and then gets re-directed to a new page fails (on purpose).

What then happens is that I see this:

 FAIL   E2E  tests/e2e/suite/login/login.e2e.test.js (22.969s)
  Login page
    \u2715 has a title (168ms)
    \u2715 does not allow an unauthorized user (2580ms)
    \u2715 requires a password change the first time a user logs in (3384ms)

  \u25cf Login page \u203a has a title

    Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.

      at mapper (../../node_modules/jest-jasmine2/build/queueRunner.js:25:45)

  \u25cf Login page \u203a does not allow an unauthorized user

    Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.

      at mapper (../../node_modules/jest-jasmine2/build/queueRunner.js:25:45)

  \u25cf Login page \u203a requires a password change the first time a user logs in

    Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.

      at mapper (../../node_modules/jest-jasmine2/build/queueRunner.js:25:45)

Test Suites: 1 failed, 1 total
Tests:       3 failed, 3 total
Snapshots:   0 total
Time:        23.392s, estimated 24s
Ran all test suites matching /e2e/i.

Notice two things here:

1. The first two test cases are marked as failed, even though I can clearly see they pass when viewing them in with headless=false. I have seen this more than once.
2. The timeout says 10000ms but this is not something I set.

Versions I am using:
"jest": "25.1.0",
"jest-playwright-preset": "0.1.1",
"playwright": "0.12.1",

[thernstig]

Ok, updates. I can see the above failure (in the post just above this) happening even if I visually look at it via headless=false and seeing that all three test cases passes i.e. they all execute and close the browser like they should.

This error has most likely existed for a few versions. I've seen colleagues get this on their computer and I just thought they had not installed the npm packages or something properly, but it seems this is a real and serious bug due to that the test cases become unstable.

If we can somehow deduct where the 10000ms comes from that gets printed, then we might have a lead. It is not something I set in my codebase either through jest.setTimeout() nor the config testTimeout.

[mmarkelov]

@thernstig hm..
As I know jest.setTimeout(5000) will set the timeout globally per suite. And for example:

it('sleep', async () => {
  ...
}, 10000)

will set the timeout for specified test.

So 10000 can came from this case.

Not sure about beforeAll, cause for me:

const { promisify } = require('util');

const sleep = promisify(setTimeout);

beforeAll(async () => {
    await page.goto(`http://example.com/`);
}, 10000);

it('sleep', async () => {
    await sleep(11000);
    expect(true).toBe(true);
});

will throw

 Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error:

[thernstig]

I have this that runs before each test.

beforeAll(async () => {
  await page.goto(`${global.TEST_URL}/login.html`);
}, 10000);

But, that part is in a beforeAll and not in each test case, which the timeouts shows above. Also, I can clearly see the test cases passing when I view it in headful mode. There is something really fishy here. Could it be a Jest bug?

[thernstig]

I wonder if jest-circus solves this hmm.

[thernstig]

I noticed a lot of issues on jest on timesout in async beforeAll()/beforeEach() etc. The timeouts in those ended up running test cases anyway looking the the test cases timed out. For example: jestjs/jest#8442, jestjs/jest#9685, jestjs/jest#8688, jestjs/jest#8654 and many more.

I will close this. I am fairly certain this is not a jest-playwright fault. Sorry for taking your time.