Wait for closed resources to actually close before detecting open handles

[Mr0grog]

Summary

Note: this contains two major changes (waiting before detecting open handles, detecting indirectly opened handles), but they affect the same part of the code and one revealed the other as an issue, so it seemed simpler to combine them. I’ve made separate commits for each so it’s a little easier to see here, but am also happy to break them into separate PRs.

Some types of async resources in Node.js are not destroyed until after their close or end or similar callbacks/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 as open even though it has been closed. This is also the main cause of issues people encounter with Supertest (see #8554).

Example:

const {createServer} = require('http');

test('--detectOpenHandles flags this even though the server was properly closed', done => {
  const server = createServer((_, response) => response.end('ok'));
  server.listen(0, () => {
    // Close server and return immediately on callback. During the "close"
    // callback, async hooks usually have not yet been called, leading to Jest
    // flagging the server as an open handle.
    server.close(done);
  });
});

This addresses the issue by adding a short delay before collecting open handles. It’s similar to some work @SimenB implemented (and then unimplemented) here: 74ed376

---

Unfortunately, this got a little bit more complex because the delay caused a test to start failing, which revealed a new issue: It turns out that some arguments to TCPServer.listen() cause the TCPSERVERWRAP async resource for the server to be created indirectly, where its stack trace has no reference to the user code that was ultimately responsible for it, which causes Jest not to track the resource.

I’ve added tracking for those indirectly created resources here. When we track an indirectly created resource, we use the stack trace from the original call that triggered the indirect created it so the user can still see the call in their code that’s causing the problem.

For example, code like:

import {createServer} from 'http';
(function userCode() {
  server.listen(0, () => {
    console.log('ok');
  });
})();

Leads to async resource creation/destruction like:

init ( asyncId: 2, type: "TCPSERVERWRAP", triggerAsyncId: 1 )
  Stack: Error: TCPSERVERWRAP
    at TCP.emitInitNative (node:internal/async_hooks:204:43)
    at createServerHandle (node:net:1230:14)
    at Server.setupListenHandle [as _listen2] (node:net:1273:14)
    at listenInCluster (node:net:1354:12)
    at Server.listen (node:net:1441:7)
    at userCode (/Users/rbrackett/Dev/async-hooks-test/index.js:52:10)

But

(function userCode () {
  const server = http.createServer((_request, response) => response.end('ok'));
  server.listen({host: 'localhost', port: 0}, () => {
    console.log('ok');
  });
})();

Leads to async resource creation/destruction like:

init ( asyncId: 2, type: "DNSCHANNEL", triggerAsyncId: 1 )
  Stack: Error: DNSCHANNEL
    at ChannelWrap.emitInitNative (node:internal/async_hooks:204:43)
    at new Resolver (node:internal/dns/utils:48:20)
    at node:internal/dns/utils:133:23
    at NativeModule.compileForInternalLoader (node:internal/bootstrap/loaders:312:7)
    at nativeModuleRequire (node:internal/bootstrap/loaders:341:14)
    at node:dns:44:5
    at NativeModule.compileForInternalLoader (node:internal/bootstrap/loaders:312:7)
    at nativeModuleRequire (node:internal/bootstrap/loaders:341:14)
    at lookupAndListen (node:net:1486:32)
    at Server.listen (node:net:1437:7)
    at userCode (/Users/rbrackett/Dev/async-hooks-test/index.js:64:10)
init ( asyncId: 3, type: "GETADDRINFOREQWRAP", triggerAsyncId: 1 )
  Stack: Error: GETADDRINFOREQWRAP
    at GetAddrInfoReqWrap.emitInitNative (node:internal/async_hooks:204:43)
    at Object.lookup (node:dns:153:21)
    at lookupAndListen (node:net:1487:7)
    at Server.listen (node:net:1437:7)
    at userCode (/Users/rbrackett/Dev/async-hooks-test/index.js:64:10)
init ( asyncId: 4, type: "TCPSERVERWRAP", triggerAsyncId: 3 )
  Stack: Error: TCPSERVERWRAP
    at TCP.emitInitNative (node:internal/async_hooks:204:43)
    at createServerHandle (node:net:1230:14)
    at Server.setupListenHandle [as _listen2] (node:net:1286:14)
    at listenInCluster (node:net:1354:12)
    at GetAddrInfoReqWrap.doListen [as callback] (node:net:1492:7)
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:71:8)
destroy ( asyncId: 3 )

Note that the TCPSERVERWRAP stack does not have userCode in it, and that the GETADDRINFOREQWRAP resource (which does have userCode in the stack) was destroyed.

The changes here allow us to detect that TCPSERVERWRAP resource and associate it with the same line of user code as the GETADDRINFOREQWRAP resource.

I also increased the size of the stack trace that we check for entrypoints to user code. The V8 default is 10, which caused us not to track resources like the DNSCHANNEL above because it has more than 10 stack frames within node internals, causing the wrapper functions that mark this as user code to get cut off the end of the stack trace.

Fixes #8554
Closes #9532

Test plan

This PR includes several unit and end-to-end tests that should cover the issues this is meant to solve.

[codecov-commenter]

Codecov Report

Merging #11429 (afea019) into master (27bee72) will increase coverage by 0.02%.
The diff coverage is 88.88%.

@@            Coverage Diff             @@
##           master   #11429      +/-   ##
==========================================
+ Coverage   69.26%   69.29%   +0.02%     
==========================================
  Files         311      311              
  Lines       16273    16285      +12     
  Branches     4702     4707       +5     
==========================================
+ Hits        11272    11285      +13     
+ Misses       4973     4972       -1     
  Partials       28       28              

Impacted Files	Coverage Δ
packages/jest-core/src/runJest.ts	68.42% <66.66%> (ø)
packages/jest-util/src/ErrorWithStack.ts	87.50% <75.00%> (-12.50%)	⬇️
packages/jest-core/src/collectHandles.ts	69.69% <100.00%> (+7.62%)	⬆️

---

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 27bee72...afea019. Read the comment docs.

[Mr0grog]

This gist might be useful for playing with or exploring the indirectly created async resources: https://gist.github.com/Mr0grog/f6f3d97a234087ebf247b8faf73822b1

[SimenB]

oh, this is super awesome! 👍 I've tried a few approaches in the same vein as this (#9532, #11278 (see first commit)) without much success. This approach is way better, tho! 👏 Do you think you can include any of the tests from those (and thus close the linked issues)?

[Mr0grog]

I don’t think I have time for this today, but will make the changes you suggested and try to add the relevant tests from #9532 and #11278 sometime in the next few days. 🙌

[SimenB]

Awesome @Mr0grog, thanks! I can probably try myself if you will be busy for the next couple of days 🙂

[SimenB]

The test added here is better than the stuff I was doing in #9532. I pulled in the test from #11278.

This is awesome 😀

EDIT: Hah, I ran the test on node 14 😅 OK, pulling that one out

[Mr0grog]

Whoa, you cleaned this up and merged it in quick! Thanks. 😄 🙌

[SimenB]

Thanks for the awesome PRs for this feature @Mr0grog! It's a really cool one that has had a couple of blemishes for a long time you've smoothed out 👍

This PR is included in 27.0.0-next.11 (stable coming next week)

[Mr0grog]

Woohoo! Glad I could help improve things. 😄

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