beforeAll async hook hides errors

[iyobo]

🐛 Bug Report

The beforeAll hook hides errors.

To Reproduce

beforeAll(async () => {
    throw new Error('Y U NO SHOW?!')
});

Expected behavior

Errors thrown in beforeAll hooks should be thrown and not get swallowed up. Such a failure should also kill further testing for that file/parallel process given that whatever failed in beforeAll would be crucial for continued testing of that parallel.

Run npx envinfo --preset jest

Paste the results here:

npx: installed 1 in 0.736s

  System:
    OS: macOS 10.14.1
    CPU: (12) x64 Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz
  Binaries:
    Node: 12.6.0 - ~/.nvm/versions/node/v12.6.0/bin/node
    npm: 6.9.0 - ~/.nvm/versions/node/v12.6.0/bin/npm
  npmPackages:
    jest: ^24.8.0 => 24.8.0 

[lucasfcosta]

Hi @iyobo,

This issue is somewhat related to https://github.com/facebook/jest/pull/8654.

It's great that you've raised this issue, but I'd suggest changing the description a bit since it's not an accurate description of the actual problem.

The actual problem is not that the error in beforeAll gets hidden, the problem is that even though beforeAll fails, the subsequent tests still run. This problem is the same as the one we've had with beforeEach in https://github.com/facebook/jest/issues/2867.

Reproducible

You can see a minimal reproducible version on top of the current master in here and run it with yarn repro.

beforeAll(async () => {
  throw new Error('Error in beforeAll');
});

describe('tests', () => {
  it('test 1', () => {
    console.log('first: runs!');
  });

  it('test 2', () => {
    console.log('second: runs!');
  });
});

The behaviour in jest-jasmine2

In jest-jasmine2 the error thrown by beforeAll will be used as the error for the subsequent tests and they will still run.

Current log of the reproducible in `jest-jasmine2`

➜ yarn repro
yarn run v1.15.0
$ yarn jest e2e/__tests__/beforeAllAbortsTests.test.ts
$ node ./packages/jest-cli/bin/jest.js e2e/__tests__/beforeAllAbortsTests.test.ts
 FAIL  e2e/__tests__/beforeAllAbortsTests.test.ts
  tests
    ✕ test 1 (5ms)
    ✕ test 2 (1ms)

  ● tests › test 1

    Error in beforeAll

      1 | beforeAll(async () => {
    > 2 |   throw new Error('Error in beforeAll');
        |         ^
      3 | });
      4 |
      5 | describe('tests', () => {

      at Object.<anonymous> (e2e/__tests__/beforeAllAbortsTests.test.ts:2:9)
      at asyncGeneratorStep (e2e/__tests__/beforeAllAbortsTests.test.ts:3:103)
      at _next (e2e/__tests__/beforeAllAbortsTests.test.ts:5:194)
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:364
      at Object.<anonymous> (e2e/__tests__/beforeAllAbortsTests.test.ts:5:97)

  ● tests › test 2

    Error in beforeAll

      1 | beforeAll(async () => {
    > 2 |   throw new Error('Error in beforeAll');
        |         ^
      3 | });
      4 |
      5 | describe('tests', () => {

      at Object.<anonymous> (e2e/__tests__/beforeAllAbortsTests.test.ts:2:9)
      at asyncGeneratorStep (e2e/__tests__/beforeAllAbortsTests.test.ts:3:103)
      at _next (e2e/__tests__/beforeAllAbortsTests.test.ts:5:194)
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:364
      at Object.<anonymous> (e2e/__tests__/beforeAllAbortsTests.test.ts:5:97)

  console.log e2e/__tests__/beforeAllAbortsTests.test.ts:7
    first: runs!

  console.log e2e/__tests__/beforeAllAbortsTests.test.ts:11
    second: runs!

Test Suites: 1 failed, 1 total
Tests:       2 failed, 2 total
Snapshots:   0 total
Time:        1.126s, estimated 2s
Ran all test suites matching /e2e\/__tests__\/beforeAllAbortsTests.test.ts/i.
error Command failed with exit code 1.

The behaviour in jest-circus

In jest-circus the error thrown by beforeAll will be used as the error for the subsequent tests and they will not be executed.

Current log of the reproducible in `jest-circus`

➜ JEST_CIRCUS=1 yarn repro
yarn run v1.15.0
$ yarn jest e2e/__tests__/beforeAllAbortsTests.test.ts
$ node ./packages/jest-cli/bin/jest.js e2e/__tests__/beforeAllAbortsTests.test.ts
 FAIL  e2e/__tests__/beforeAllAbortsTests.test.ts
  tests
    ✕ test 1 (3ms)
    ✕ test 2

  ● tests › test 1

    Error in beforeAll

      1 | beforeAll(async () => {
    > 2 |   throw new Error('Error in beforeAll');
        |         ^
      3 | });
      4 |
      5 | describe('tests', () => {

      at e2e/__tests__/beforeAllAbortsTests.test.ts:2:9
      at asyncGeneratorStep (e2e/__tests__/beforeAllAbortsTests.test.ts:3:103)
      at _next (e2e/__tests__/beforeAllAbortsTests.test.ts:5:194)
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:364
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:97

  ● tests › test 2

    Error in beforeAll

      1 | beforeAll(async () => {
    > 2 |   throw new Error('Error in beforeAll');
        |         ^
      3 | });
      4 |
      5 | describe('tests', () => {

      at e2e/__tests__/beforeAllAbortsTests.test.ts:2:9
      at asyncGeneratorStep (e2e/__tests__/beforeAllAbortsTests.test.ts:3:103)
      at _next (e2e/__tests__/beforeAllAbortsTests.test.ts:5:194)
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:364
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:97

Test Suites: 1 failed, 1 total
Tests:       2 failed, 2 total
Snapshots:   0 total
Time:        1.036s
Ran all test suites matching /e2e\/__tests__\/beforeAllAbortsTests.test.ts/i.
error Command failed with exit code 1.

Multiple failing beforeAll hooks

Both in jest-circus and jest-jasmine2, if there are multiple beforeAll hooks and one of them fails, all the subsequent beforeAll and afterAll hooks will still run. The same behaviour is valid for afterAll: all of them will still run even if one fails.

beforeAll(async () => {
  throw new Error('Error in beforeAll');
});

beforeAll(async () => {
  throw new Error('Error in second beforeAll');
});

describe('tests', () => {
  it('test 1', () => {
    console.log('first: runs!');
  });

  it('test 2', () => {
    console.log('second: runs!');
  });
});

afterAll(async () => {
  throw new Error('Error in first afterAll');
});

afterAll(async () => {
  console.log('second afterAll still runs');
});

Actual Desired Behaviour (?)

I was planning on also tackling this since it's very related to that PR I've recently done, but I think it would be helpful to agree on the actual desired behaviour for the edge-case described above before starting to implement it (the same we have run into in the other PR).

IMO all beforeAll hooks should run regardless of whether the previous beforeAll hooks have failed. If a beforeAll hook has failed, none of the subsequent beforeEach, tests, or afterEach should run, but the afterAll hooks should.

The suggestion above would make the behaviour more similar to beforeEach and afterAll, which would be more consistent (IMO).

[iyobo]

@lucasfcosta No. The issue here is that the errors thrown in beforeAll are getting swallowed, particularly when using an async function.

They come in as hidden unhandled promise exceptions instead.

I want to actually see the error that gets thrown in beforeAll when I'm using an async function as that would give an indicator as to the actual problem why the test parallel failed.

[lucasfcosta]

Hi @iyobo 😊,

I see what you mean. I'm sorry if I'm misunderstanding the issue but I've tried the following (as per your description) and the failure didn't get swallowed (both in jest-jasmine2 and jest-circus):

beforeAll(async () => {
  throw new Error('Error in beforeAll');
});

it('first test', () => {});

Current log of the code above

 FAIL  e2e/__tests__/beforeAllAbortsTests.test.ts
  ✕ first test

  ● first test

    Error in beforeAll

      1 | beforeAll(async () => {
    > 2 |   throw new Error('Error in beforeAll');
        |         ^
      3 | });
      4 |
      5 | it('first test', () => {});

      at e2e/__tests__/beforeAllAbortsTests.test.ts:2:9
      at asyncGeneratorStep (e2e/__tests__/beforeAllAbortsTests.test.ts:3:103)
      at _next (e2e/__tests__/beforeAllAbortsTests.test.ts:5:194)
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:364
      at e2e/__tests__/beforeAllAbortsTests.test.ts:5:97

Test Suites: 1 failed, 1 total
Tests:       1 failed, 1 total
Snapshots:   0 total
Time:        0.409s, estimated 1s
Ran all test suites matching /e2e\/__tests__\/beforeAllAbortsTests.test.ts/i.

Watch Usage: Press w to show more.

Perhaps I'm missing something or I misunderstood what you meant? What exactly do you mean by being "swallowed"? Does it mean they are not shown at all?

Again, sorry if I missed any details. Perhaps if you could share a reproducible and indicate which part of the output contains the desired behaviour we could debug this together? I've recently touched that part of the codebase so it's still fresh in my mind (which is why I jumped into this issue).

[philiiiiiipp]

I am seing the same, in my case occasionally, "swallowing" behaviour in my CI/CD tests,

    ✕ sendMessage and handle webhooks in perfect order (1639ms)
    ✓ Message of the non sender is synced first (4086ms)
    ✓ Message with an attachement (1739ms)

  ● Message Deduplication Test › sendMessage and handle webhooks in perfect order



      46 |   });
      47 | 
    > 48 |   beforeEach(async () => {
         |   ^
      49 |     setTestMode();
      50 |     sendMessage(sendMessage);
      51 | 

      at Env.beforeEach (node_modules/jest-jasmine2/build/jasmineAsyncInstall.js:41:24)
      at Suite.beforeEach (src/api/functions/message/queueMessage/__test__/messageCreated.test.js:48:3)
      at Object.describe (src/api/functions/message/queueMessage/__test__/messageCreated.test.js:24:1)

I tried to reproduce this, but throwing an error or generating a timeout is printed just fine, both in my CI/CD environment and my local environment.

The only difference I noticed is that when throwing an error myself (in this case generating a timeout) the error looks like this:

  Message Deduplication Test
    ✕ sendMessage and handle webhooks in perfect order (5006ms)
    ✕ Message of the non sender is synced first (5005ms)
    ✕ Message with an attachement (5001ms)

  ● Message Deduplication Test › sendMessage and handle webhooks in perfect order

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

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

The error which is printing the mssage comes fron

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

The one that is not printing anything comes from

at Env.beforeEach (node_modules/jest-jasmine2/build/jasmineAsyncInstall.js:41:24)
at Suite.beforeEach (src/api/functions/message/queueMessage/__test__/messageCreated.test.js:48:3)
at Object.describe (src/api/functions/message/queueMessage/__test__/messageCreated.test.js:24:1)

looking at the code there it seems like some optimisation was done there

    const extraError = new Error(); // Without this line v8 stores references to all closures
    // in the stack in the Error object. This line stringifies the stack
    // property to allow garbage-collecting objects on the stack
    // https://crbug.com/v8/7142

    extraError.stack = extraError.stack; // We make *all* functions async and run `done` right away if they
    // didn't return a promise.

[philiiiiiipp]

@lucasfcosta I am wondering if it already breaks somewhere before the async keyword is handled if you are running a heavy load of tests. I could never reproduce this by only running one at a time.

[philiiiiiipp]

I do believe that the issue lies here. I am not sure why this error swapping is done, but just forwarding the original error gives me the correct underlying error message.

I suppose that everything which does not adhere to the [isError](https://github.com/facebook/jest/blob/master/packages/jest-jasmine2/src/isError.ts check, e.g. a rejected promise, will actually be given out as an empty error message.

[philiiiiiipp]

I added a repo to reproduce this, its not only a beforeAll issue. Its a general issue with rejected promises https://github.com/philiiiiiipp/jest-async-beforeall-error

[lucasfcosta]

Hi @philiiiiiipp, thanks for your reproducible, it was extremely helpful 😊

I managed to reproduce the error by running your example using Node v12.6 (as described by the issue's author).

That error, however, only happens on Jest v24.8, not in the current state of master.

It's possible to verify this by running yarn install and yarn test in your repo (which uses v24.8) and then running the same tests using the current version of master.

The reason why this happened is that _addMissingMessageToStack would not combine the message with the stack due to this regex.test check failing.

This has been fixed by adding a :? to the regex, here. The if condition for doing the replace also changed, but just changing the regex so that the test passes will be enough to fix this.

You can verify this by opening the node_modules file and changing jest-jasmine2/build/reporter.js to use the same value that is in master for ERROR_REGEX and then you will start seeing the promise rejection message.

This happened 26 days ago, so that's why it's not present in the last release.

Given the above I believe this issue can be closed.

Thanks again @philiiiiiipp for the reproducible 💖

[philiiiiiipp]

Cool :-)

I tried it by changing the jest-jasmine2 ERROR_REGEX and now it shows perfectly fine. ( node v10.16.0 )

I also noticed that using jest-circus this works too. Which, I guess makes sense since it replaces jest-jasmine2.

[krzkaczor]

This is still unreleased/fixed. My dirty workaround:

// setup-after-env.js
const _beforeEach = global.beforeEach;
global.beforeEach = fn => {
  _beforeEach(async () => {
    try {
      await fn();
    } catch (e) {
      console.error(e);
      throw e;
    }
  });
};

EDIT: my current workaround is to use mocha + earl 😆

[khitrenovich]

The "dirty workaround" from above didn't work for me, but switching to circus runner did - https://github.com/facebook/jest/blob/master/packages/jest-circus/README.md.

[sonic1981]

When you combine this issue with this one https://github.com/facebook/jest/issues/2441 Things get real fun

:raised_eyebrow:

[FrederikP]

Upgrading jest to the latest version fixed this issue for me (probably due to the new circus runner).

[github-actions[bot]]

This issue is stale because it has been open for 1 year with no activity. Remove stale label or comment or this will be closed in 30 days.

[github-actions[bot]]

This issue was closed because it has been stalled for 30 days with no activity. Please open a new issue if the issue is still relevant, linking to this one.