feat: better timeout errors through deadlines (prototype)

[FauxFaux]

Summary

Prototype implementation of #10895, please see there for the main reasoning. This isn't supposed to be a finished implementation, or even a reasonable way to do it.

This is a partial port of this monkey patchy implementation: https://github.com/FauxFaux/jest-fixup-timeouts

Logical idea:

1. When a test function (including hook) starts, store the computed test deadline (now + timeout) in some accessible place
2. Expose this computed deadline as test.deadline(), and through expect.withinDeadline(Promise), which races it against the deadline
3. Add a babel plugin which converts a = await foo() into a = await expect.withinDeadline(foo()).

Deadline location / hooks

In this attempt, the deadline is hidden on the currentlyRunningTest in the global Runner State, which is where the original timeout was stored. An accessor is provided to expect and user code.
This seemed like a reasonable place, but unlike with the hack, it is not available within beforeAll/afterAll, so fails for those. This doesn't matter to the current main timeout implementation, because it has long forgotten about any "jest" concepts, and is only concerned about "running", which is probably reasonable.

I can't see anywhere else to stash it, except as an actual global, i.e. on Runner State, or in a new symbol?

babel plugin

• I didn't add it to the preset. I expect most users want to run it only on their tests, not the rest of their code; not sure how that would work with a preset?

• On a second look, it probably wants to rewrite await foo; as well as await foo();.

Test plan

There's an e2e test for both features which show how it's supposed to be used.

faux@astoria:~/clone/jest/e2e/babel-plugin-jest-deadlines% bash ../../jest
 FAIL  __tests__/typescript.test.ts
  ● exceeded

    deadline exceeded (waited here for 20ms)

      12 | test('exceeded', async () => {
      13 |   await sleep(10);
    > 14 |   await sleep(200);
         |   ^
      15 | }, 50);
      16 | 

      at Object.<anonymous> (__tests__/typescript.test.ts:14:3)

 FAIL  __tests__/plain.test.js
  ● exceeded

    deadline exceeded (waited here for 20ms)

      11 | test('exceeded', async () => {
      12 |   await sleep(10);
    > 13 |   await sleep(200);
         |   ^
      14 | }, 50);
      15 | 

      at Object.<anonymous> (__tests__/plain.test.js:13:3)

Test Suites: 2 failed, 2 total
Tests:       2 failed, 2 total
Snapshots:   0 total
Time:        0.447 s, estimated 1 s
Ran all test suites.

[SimenB]

I think this is pretty clean! I really like this idea and would love to ship it in Jest 27. I wonder if we need some way to opt out - I assume this will add significant overhead to a promise heavy test run. Possibly via some config option? If that's active, then we add the plugin to the babel plugin in babel-jest.

I didn't add it to the preset. I expect most users want to run it only on their tests, not the rest of their code; not sure how that would work with a preset?

Touched on it above, but I think we don't want it in the preset, but babel-jest can activate it based on an option?

---

Also, I wonder if we should somehow apply this within circus as well for tests/hooks that return promises rather than use async-await? I guess we could document the magic only works with async await

[SimenB]

unused?

[FauxFaux]

This started as a copy-paste of the hoist plugin. They are currently unused... however.

In the hoist plugin, these things are used in there to ensure that we have resolved the right globals, and to explicitly call jest's globals' expect, instead of just whatever variable named expect happens to be in scope, like my plugin does.

I wonder if we need to copy (share) the functionality from hoist?

[SimenB]

@jeysal thoughts?

[jeysal]

Yeah I think Jest is used enough that someone will have a shadowing expect that means a different thing and run into this, so we'll need to handle it. It should be relatively easy to insert a const identifierGeneratedByBabel = expect at top level and reference that instead

[FauxFaux]

I made it prepend const generatedByBabelExpect = require("@jest/globals").expect; and reference that, which should cover most usecases? I worry about writing it as const generatedByBabelExpect = expect; that's not going to work in some case, surely.

[jeysal]

Yeah that was written a bit hastily, I suppose that would collide with a var expect declared below or something. Reading the expect from the global this may work. But I think your solution is good.
@SimenB was there some bugs remaining when using certain things from @jest/globals that may be relevant here, or is it fine? Maybe I'm confusing it with the globalThis.expect !== require('expect') thing

[SimenB]

e.g. detox overrides global.expect: #10484 (comment)

not sure how much of an issue in practice that is.

It might make more sense to attach this only to the test runner (on test, or maybe even jest) rather than adding it to expect? Not sure

[SimenB]

should probably guard this behind some check that it actually timed out as accessing the stack is not free

[FauxFaux]

I believe this won't run unless the setTimeout "sleep" above resolves (it's awaited), which doesn't happen in the non-timeout case?

The promise will never resolve most of the time, though. My node isn't quite good enough to know if that's a real problem; whether we leak the closure and some context in it somehow.

[SimenB]

you're correct! I do think we'll be leaking as you mention, though.

Could we do something like

async function timeout<T>(promise: Promise<T>, ms: number): Promise<T> {
  let timeoutId: ReturnType<typeof setTimeout> | undefined;
  let resolvePromise: () => void;

  try {
    return await Promise.race([
      promise,
      new Promise<void>((resolve, reject) => {
        resolvePromise = resolve;

        timeoutId = setTimeout(() => {
          timeoutId = undefined;

          const here = new Error(`deadline exceeded (waited here for ${ms}ms)`);
          here.stack = here.stack
            ?.split('\n')
            .filter(line => !isUs(line))
            .join('\n');

          reject(here);
        }, ms);
      }),
    ]);
  } finally {
    resolvePromise.?();
    if (timeoutId) {
      clearTimeout(timeoutId);
    }
  }
}

?

[FauxFaux]

Apparently not. If you reject/throw from within the Promise there, you lose the stack trace, which messes up the whole purpose of this. p-timeout has the same bug.

I rewrote the old implementation to await something more like your code, but with some booleans for whether it resolved or was cancelled. (pushed)

[FauxFaux]

I wouldn't expect it to add significant overhead to regular tests.

In the happy path case, you're doing an extra setTimeout, clearTimeout and Promise.race.
For the unhappy path, something has already gone wrong, probably in the "seconds" dimension.

For the type of test I imagine writing ("call this webservice, call that webservice, write this db record, read that db record, assert"), none of those things is even close to showing up on a profiling report, and there's only four of them.

If you were to use the plugin to rewrite all of your code, instead of just your tests, then maybe you'll end up with a performance sensitive await inside a performance sensitive loop?

On the other hand, I'm sure there are people writing tests which are actually sub-second in all cases.

[FauxFaux]

Outstanding issues I'd like help with:

• ✔️ where to stash the deadline, so it works in beforeAll, just directly on the runner state as currentlyRunningHookOrTestsDeadline?
• ✔️ are we exposing the deadline to users, and where from?
• can anything inside circus be tested, except as e2e? Many of the other circus tests are quite e2e anyway, just with a custom event listener.
• ✔️ does the babel plugin need to be pedantic about @jest/globals' expect?

Things I would like to look at when I've had more sleep, but aren't critical blockers for merging this / some of this / something like this:

• ✔️ the compile error about deadline, which is something weird with the way circus is defined. It can just be deleted from the global types, and the problem will go away.
• what is a babel preset and what settings could it expose
• what would it look like to handle expect().resolves (including as a promise chain)
• what would an implementation that handles promises in general look like
• what is the other PR doing and what can we share

[SimenB]

do we need this at all? jest-message-util should already handle filtering out unwanted frames. Might be needed, I haven't tested

[FauxFaux]

It's needed for the tests to pass; you end up with at ../../home/faux/clone/jest/packages/jest-circus/build/deadlineTimeout.js:53:22 in the stack otherwise.

I have no idea whether that could/should be fixed in jest-message-util.

[SimenB]

Would have thought this line caught it: https://github.com/facebook/jest/blob/d393800b0358c79998c003b978ef162a71fe01e9/packages/jest-message-util/src/index.ts#L50

Not worth it to dig into I think

[FauxFaux]

https://github.com/facebook/jest/blob/ca47512c77e6a325bca734a35a4ad15a45dee8aa/packages/jest-message-util/src/index.ts#L220-L222

It always keeps the first line, and the first line is going to be inside jest, because we're explicitly throwing.

[FauxFaux]

The test failures with negative times raise an interesting point.

• Should withinDeadline throw immediately if the deadline is exceeded (probably yes)?
• Did I mess up, or is CI really taking 90ms to do a 10ms sleep? I didn't think timer slop was that bad on non-Windows.

Also, sometimes the stack trace is absent (only on node 10?). Maybe the async construction is too complex, or this is not plausible on node 10? I personally don't care about node 10, and it's not harmful. Node 10 is in maintenance until Apr 2021.

[github-actions]

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

[github-actions]

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

[github-actions]

This pull request 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.