Jest detects open handle from bindAsync

[christopher-watanabe-snkeos]

Problem description

My jest tests complain that an open handle is generated by the call to bindAsync on a Grpc Server I use during the tests.

Reproduction steps

I've made a simple example that creates starts a grpc server before all tests in this repo https://github.com/christopher-watanabe-snkeos/jest-open-handle-bindAsync.

To reproduce the error:

1. Clone the repo
2. Run jest --detectOpenHandles
3. Observe the following error:

Jest has detected the following 1 open handle potentially keeping Jest from exiting:

● TCPSERVERWRAP

  3 | function startServer() {
  4 |   const testServer = new grpc.Server();
> 5 |   testServer.bindAsync(
    |              ^
  6 |     "127.0.0.1:12345",
  7 |     grpc.ServerCredentials.createInsecure(),
  8 |     () => {

  at DnsResolver.startResolution (node_modules/@grpc/grpc-js/src/resolver-dns.ts:167:7)
  at Object.startServer (mock-service.js:5:14)
  at test.js:7:28

Environment

• Win 10
• Node 18.14.2
• "@grpc/grpc-js": "^1.8.7",

Additional context

I can avoid this with the --forceExit option of Jest, but I would like to understand why / how this open handle is generated.

[murgatroid99]

In my current version of resolver-dns.ts, that line points to a setImmediate call. If you wait for bindAsync to finish, that setImmediate should be closed. On the other hand, Jest mentions a TCPSERVERWRAP handle, which would correspond to the actual server that is being opened by bindAsync. Are you shutting down the server when you are done with it? Doing so should unbind all open servers.

[alenon]

Same issue I have since updated @grpc/grpc-js from 1.9.2 to 1.9.3. Nothing else changed.
Can be easily reproducible here: https://github.com/alenon/grpc-mock-server
npm run test

Again it worked before version 1.9.3

Here is the error:
`Jest has detected the following 1 open handle potentially keeping Jest from exiting:

● HTTP2SESSION

  46 |
  47 |     await new Promise<number>((resolve, reject) => {
> 48 |       this.server.bindAsync(
     |                   ^
  49 |         this.serverAddress,
  50 |         grpc.ServerCredentials.createInsecure(),
  51 |         (error, port) => error ? reject(error) : resolve(port)

  at DnsResolver.startResolution (node_modules/@grpc/grpc-js/src/resolver-dns.ts:167:7)
  at DnsResolver.startResolutionWithBackoff (node_modules/@grpc/grpc-js/src/resolver-dns.ts:345:12)
  at DnsResolver.updateResolution (node_modules/@grpc/grpc-js/src/resolver-dns.ts:363:14)
  at Server.bindAsync (node_modules/@grpc/grpc-js/src/server.ts:691:14)
  at src/GrpcMockServer.ts:48:19
  at GrpcMockServer.start (src/GrpcMockServer.ts:47:11)
  at Object.<anonymous> (tests/integration.test.ts:34:18)

`

[murgatroid99]

You said that it started when upgrading from 1.9.2 to 1.9.3, so it seems unlikely that it was caused by changes between 1.9.1 and 1.9.2.

The most local item in the reported call stack is node_modules/@grpc/grpc-js/src/resolver-dns.ts:167, which is a line containing a call to setImmediate. It is very unlikely that this is actually the source of the open handle, because the handle created by setImmediate is resolved after a single event loop iteration. As a result, I assume the actual problematic handle is created elsewhere, but there's nothing in the jest output to clearly indicate where.

On the other hand, the change from 1.9.2 to 1.9.3 did actually touch code in close proximity to that line, but the primary change was actually to stop running timers that were sometimes left running due to a bug, so if anything it should have eliminated some open handles.

[murgatroid99]

I just published grpc-js version 1.9.4 with a fix for one bug that was keeping a handle reffed incorrectly. Please try it out and see if it fixes the issue in jest.

[christopher-watanabe-snkeos]

Hi @murgatroid99,

In my example reproduction of the problem, I do shutdown the server when I am done with it https://github.com/christopher-watanabe-snkeos/jest-open-handle-bindAsync/blob/27b05ad0ccd6b15cbe2a6920de5043daa3aa00da/test.js#L11. This I do once all my jest tests are finished.

Updating to 1.9.4 continues to show the issue.

[murgatroid99]

Your test isn't waiting for the server to start before running the rest of the test. I think you're running into a race condition where you call forceShutdown while the bindAsync call is still pending, so the listening socket created by bindAsync never gets shut down. If you modify your startServer to take a callback and call it after calling testServer.start, and modify your before call to use a done parameter, and pass that along to startServer, the error from jest goes away.

[christopher-watanabe-snkeos]

@murgatroid99: You are absolutely right. I wasn't aware of this jest convention with the done callback, but it solves my problem. Thank you very much!

@alenon: I don't know if this will also correct your issue, but I'll leave this issue open for the time being and defer the closing of the issue to @murgatroid99 or yourself.

[christopher-watanabe-snkeos]

Same issue I have since updated @grpc/grpc-js from 1.9.2 to 1.9.3. Nothing else changed. Can be easily reproducible here: https://github.com/alenon/grpc-mock-server npm run test

Again it worked before version 1.9.3

Here is the error: `Jest has detected the following 1 open handle potentially keeping Jest from exiting:

● HTTP2SESSION

  46 |
  47 |     await new Promise<number>((resolve, reject) => {
> 48 |       this.server.bindAsync(
     |                   ^
  49 |         this.serverAddress,
  50 |         grpc.ServerCredentials.createInsecure(),
  51 |         (error, port) => error ? reject(error) : resolve(port)

  at DnsResolver.startResolution (node_modules/@grpc/grpc-js/src/resolver-dns.ts:167:7)
  at DnsResolver.startResolutionWithBackoff (node_modules/@grpc/grpc-js/src/resolver-dns.ts:345:12)
  at DnsResolver.updateResolution (node_modules/@grpc/grpc-js/src/resolver-dns.ts:363:14)
  at Server.bindAsync (node_modules/@grpc/grpc-js/src/server.ts:691:14)
  at src/GrpcMockServer.ts:48:19
  at GrpcMockServer.start (src/GrpcMockServer.ts:47:11)
  at Object.<anonymous> (tests/integration.test.ts:34:18)

`

@murgatroid99, @alenon : Interestingly, following the pattern that I followed for my test project in another project with more extensive testing, I'm now getting the same HTTP2SESSION error that @alenon is experiencing.

[murgatroid99]

I think I will need to see a full test that produces that error to understand what might be happening. With the fix I mentioned in 1.9.4, my own tests terminate immediately after completing.

[murgatroid99]

I published a change in version 1.9.5 to automatically handle that race between bindAsync and shutdown.

[christopher-watanabe-snkeos]

@murgatroid99 : Thanks for the change! I've been out for a few weeks, but I will have a look at whether the update fixes my issue.

[christopher-watanabe-snkeos]

@murgatroid99 : I can confirm that updating the package to 1.9.5 solves the issue of the binding and shutdown. However, updating to 1.9.6 and above reintroduces the problem.

[murgatroid99]

There were no changes from 1.9.5 to 1.9.6 that I can identify as affecting any behavior related to asynchronous operations. Can you please share the text of the error you are seeing in the most recent versions of the library?

[christopher-watanabe-snkeos]

Thanks for the reply. The message from jest is the following after running my tests:

Jest did not exit one second after the test run has completed.
This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with --detectOpenHandles to troubleshoot this issue.

Interestingly, I'm seeing the following behavior for the following versions:

grpc-js version	jest closes successfully without async errors
1.9.5	✔
1.9.6	✔
1.9.7	❌
1.9.8	❌
1.9.9	✔

[murgatroid99]

OK, that makes more sense. Updating to 1.9.6 didn't introduce any problem, as I expected. There was a bug introduced in 1.9.7 that was fixed in 1.9.9, so I expect that bug was also the cause of the open handle you were seeing. It looks like the problem has been resolved, so I'll close this issue.