Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Detect open handles with done callbacks #11382

Merged
merged 13 commits into from
May 20, 2021

Conversation

Mr0grog
Copy link
Contributor

@Mr0grog Mr0grog commented May 7, 2021

Summary

When using the Jasmine test runner, the --detectOpenHandles CLI option does not successfully detect handles that were opened in test or lifecycle functions that take a done callback (#11377). Callbacks for async tests are admittedly a lot less common these days, but this can still be pretty frustrating when trying to debug issues in tests that still use that style.

In jest-core, the collectHandles module checks the call stack for each open handle to determine whether it might have been opened from user code, and therefore whether to track it. It does this by looking for the name of the wrapper function that the Jasmine runner uses for test/lifecycle functions that return promises. However, functions that take a done callback never get wrapped or given a recognizable name, and so collectHandles never tracks async handles opened in them.

This fixes the issue by wrapping test/lifecycle functions that take a done callback in a named function that collectHandles will successfully detect.

Fixes #11377.

Test plan

I’ve added a unit test and a couple integration tests to cover scenarios around this issue. Hopefully the integration tests are simple enough to be pretty self-explanatory. You can run them manually to see the output as a user would with:

$ cd e2e/detect-open-handles/
$ JEST_JASMINE=1 node ../../packages/jest-cli/bin/jest.js in-done-function --detectOpenHandles --forceExit
$ JEST_JASMINE=1 node ../../packages/jest-cli/bin/jest.js in-done-lifecycle --detectOpenHandles --forceExit

They should each print a message about a TCPSERVERWRAP handle that was left open during the test.

This adds a unit test and two new integration tests to assert that hanging async handles created in test or lifecycle functions with `done` callbacks are correctly detected and logged when using `--detectOpenHandles`. They all fail when used with the Jasmine runner right now (things work fine with Circus; yay!).
Wrap test and lifecycle functions that take a `done` callback in a named function so that they can be detected as user code in the call stack. This lets the `collectHandles` module in jest-core know to track async resources created in those functions.

Fixes jestjs#11377.
e2e/__tests__/__snapshots__/failures.test.ts.snap Outdated Show resolved Hide resolved
Comment on lines 112 to 123
} else if (typeof fn !== 'function') {
// Pass non-functions to Jest, which throws a nice error.
return originalFn.call(env, specName, fn, timeout);
}

const hasDoneCallback = fn.length > 0;

if (hasDoneCallback) {
return originalFn.call(env, specName, fn, timeout);
// Give the function a name so it can be detected in call stacks, but
// otherwise Jasmine will handle it.
const asyncJestTestWithCallback = (done: DoneFn) => fn(done);
return originalFn.call(env, specName, asyncJestTestWithCallback, timeout);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Technically this changes effect slightly. If you passed in a non-function object with a length property before (e.g. a non-empty string, as in this test), we’d either do what’s happening here if it had a length, or wind up wrapping it with asyncJestTest, which would then cause an error later when the test ran and it tried to call the non-function.

I think this is the right change to make, though, since it seems like it’s addressing those possible other error cases. (There’s an edge-case here: you could have passed an object with a call() method that I think would have worked before, but would not with this change. I’m not sure if that’s really supposed to be supported, though.)

@codecov-commenter
Copy link

codecov-commenter commented May 7, 2021

Codecov Report

Merging #11382 (6eb3969) into master (ba84480) will decrease coverage by 0.00%.
The diff coverage is 0.00%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master   #11382      +/-   ##
==========================================
- Coverage   64.19%   64.18%   -0.01%     
==========================================
  Files         308      308              
  Lines       13519    13527       +8     
  Branches     3293     3294       +1     
==========================================
+ Hits         8678     8682       +4     
- Misses       4126     4132       +6     
+ Partials      715      713       -2     
Impacted Files Coverage Δ
packages/jest-jasmine2/src/jasmineAsyncInstall.ts 0.00% <0.00%> (ø)
packages/jest-core/src/collectHandles.ts 47.91% <0.00%> (+8.33%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update ba84480...6eb3969. Read the comment docs.

const {stderr} = runJest('detect-open-handles', [
'in-done-function',
'--detectOpenHandles',
'--forceExit',
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can you use waitUntil instead of forceExit?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There doesn't seem to be any text that comes after the message about the open handle(s), so the best I could think to do with waitUntil() was to wait for the message that tests were done, then wait a few more ticks for the open handles to be printed. If I wait for the actual message about the open handles, the test would time out waiting in the error case when the handles aren't printed. --forceExit seemed cleaner and more reliable than that. Is there a better approach I'm missing?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it makes more sense to match the style of the other tests which will all time out if the message is not printed.

One thing we could do in general I guess is to add a timeout to waitUntil and first wait for tests to complete, then wait for the handle text with a timeout. But regardless, for consistency now I prefer not using forceExit

Copy link
Member

@SimenB SimenB left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you update the changelog as well? 🙂

@Mr0grog
Copy link
Contributor Author

Mr0grog commented May 8, 2021

I'll improve the typing and add a changelog entry when I’m back in front of a keyboard later today.

@Mr0grog Mr0grog requested a review from SimenB May 9, 2021 05:26
@Mr0grog
Copy link
Contributor Author

Mr0grog commented May 9, 2021

I think I’ve addressed everything except the waitUntil issue, which I wasn’t sure how to accomplish in a better way.

@Mr0grog
Copy link
Contributor Author

Mr0grog commented May 15, 2021

Just checking in again here — anything I still need to do or can do to help move this along?

@SimenB
Copy link
Member

SimenB commented May 19, 2021

For some reason circus as and extra Object. - just do a .replace to make them identical?

@Mr0grog
Copy link
Contributor Author

Mr0grog commented May 19, 2021

Ah, sorry, I didn’t see your comment while I was poking at this! That seems like a better solution than what I did (changed the implementation to get the same result in both runners, at the cost of questionable this behavior for Jasmine), which I was going to ask about. I’ll change to your recommendation.

@Mr0grog
Copy link
Contributor Author

Mr0grog commented May 19, 2021

For some reason circus as and extra Object.

FWIW, it looks like this is because Circus does not provide a testContext for beforeAll/afterAll hooks: https://github.com/facebook/jest/blob/2047a360b02504ea1ab9ea974b40f150660625f6/packages/jest-circus/src/run.ts#L40-L42

Vs. beforeEach/afterEach, where it does: https://github.com/facebook/jest/blob/2047a360b02504ea1ab9ea974b40f150660625f6/packages/jest-circus/src/run.ts#L119-L126

Not sure if that’s intentional or a bug.

@Mr0grog
Copy link
Contributor Author

Mr0grog commented May 19, 2021

Either way, I think this should be good to go, unless there are any new issues you’ve noticed.

Mr0grog added a commit to Mr0grog/jest that referenced this pull request May 20, 2021
Some types of async resources in Node.js are not destroyed until *after* their `close` or `end` or similar callbacks and events run, leading to a situation where the `--detectOpenHandles` option can falsely flag resources that have been cleaned up in user code and are already scheduled for destruction. For example, if a test ends from the callback to `TCPServer.close()` and no other tests or lifecycle functions impose additional delays, `--detectOpenHandles` will flag the server even though it has been closed. This is the main cause of issues people encounter with Supertest (see jestjs#8554).

This addresses the issue by adding a short delay before collecting open handles.

Depends on jestjs#11382.
@SimenB
Copy link
Member

SimenB commented May 20, 2021

Not sure if that’s intentional or a bug

Intentional I think, there is no this in hooks that are not connected to a single test

@SimenB SimenB merged commit 57e32e9 into jestjs:master May 20, 2021
@SimenB
Copy link
Member

SimenB commented May 20, 2021

Thanks!

@Mr0grog Mr0grog deleted the detect-open-handles-with-done-callbacks branch May 20, 2021 15:30
Mr0grog added a commit to Mr0grog/jest that referenced this pull request May 20, 2021
Some types of async resources in Node.js are not destroyed until *after* their `close` or `end` or similar callbacks and events run, leading to a situation where the `--detectOpenHandles` option can falsely flag resources that have been cleaned up in user code and are already scheduled for destruction. For example, if a test ends from the callback to `TCPServer.close()` and no other tests or lifecycle functions impose additional delays, `--detectOpenHandles` will flag the server even though it has been closed. This is the main cause of issues people encounter with Supertest (see jestjs#8554).

This addresses the issue by adding a short delay before collecting open handles.

Depends on jestjs#11382.
@github-actions
Copy link

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jun 20, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

--detectOpenHandles does not detect handles opened in test function with done callback
4 participants