Jest does not exit tests cleanly with Firebase Firestore, an older version does. (Potentially jsdom related, repro *is* included.)

[inf3rnus]

🐛 Bug Report

Jest 27.0.1 does not exit tests cleanly when a call is made with any network based firestore call (see repro) in that it complains of pending asynchronous operations. The pending asynchronous operation when running --detectOpenHandles comes from the grpc client used by Firestore, it does not seem to close its socket, either in time, or it hangs. This may be due to its interaction with jsdom.

Jest 25.5.4 does exit tests cleanly, so I'm inclined to believe this is related to jest-environment-jsdom's interaction with Firestore's GRPC client.

I've alerted the firebase team to this issue here: firebase/firebase-js-sdk#4947

Firebase SDK version: 8.6.2

To Reproduce

1. • Clone this repro repo I've made: https://github.com/inf3rnus/firebase-jest-pending-grpc-connection
2. • Run the following: npm i
3. • Run: npx jest (You'll see the tests do not exit cleanly.)
4. • Run: npx jest --detectOpenHandles (This will show the specific source of the hanging resource.)

Expected behavior

Jest 27.0.1 exits tests using Firestore cleanly like it does on version 25.5.4.

Link to repl or repo (highly encouraged)

https://github.com/inf3rnus/firebase-jest-pending-grpc-connection

envinfo

System:
OS: Linux 5.4 Ubuntu 18.04.5 LTS (Bionic Beaver)
CPU: (12) x64 Intel(R) Core(TM) i7-8750H CPU @ 2.20GHz
Binaries:
Node: 14.17.0 - /usr/local/bin/node
npm: 6.14.13 - /usr/local/bin/npm
npmPackages:
jest: ^27.0.1 => 27.0.1

Pictures!

[joshkel]

Possibly the same root cause as #9982?

[joshkel]

After digging into this some more, I think that the DNSCHANNEL is a false positive. (See here.) I noticed that the firebase-jest-pending-grpc-connection test case does eventually exit; it's just after a delay and after Jest complains.

I tried running it through wtfnode, since Jest's information wasn't helpful, and it was able to provide more information:

[WTF Node?] open handles:
- File descriptors: (note: stdio always exists)
  - fd 1 (tty) (stdio)
  - fd 2 (tty) (stdio)
  - fd 0 (tty)
- Timers:
  - (1586.9881543292286 ~ 1 s) (anonymous) @ /Users/joshkel/src/jest-workspace/firebase-jest-pending-grpc-connection/node_modules/@grpc/grpc-js/build/src/backoff-timeout.js:65

Further digging showed that the gRPC BackoffTimeout was the cause; Jest exits as soon as it finishes.

From what I can tell, Jest doesn't report this timeout because it tries to only show user-created resources; see here. That seems like a bug or design flaw within Jest, since it hides relevant information: I know I'm using Firebase, so if I see that gRPC is causing problems, I can start investigating from there, even if the actual call to gRPC is buried in too deep a stack of asynchronous events for Jest to connect it to my code.

Incidentally, it looks like the reason this wasn't an issue in previous versions of Jest is because of the change from the jsdom to the node test environment. I guess gRPC has different error-handling / backoff behavior if it detects it's running in a Node environment? I'm not sure.

[Mr0grog]

Jest doesn't report this timeout because it tries to only show user-created resources; see here.

FWIW, the code in the block you highlighted is actually trying do something that might catch the timer that’s the problem here: it’s capturing async resources created by other async resources created by …etc… created by user code (I added that just before Jest 27 shipped).

Unfortunately, just a few lines down from that, we fill in the stack trace for those indirectly created resources by using the trace from the user-created resource that kicked it all off (the idea here was to point you to something actionable in your code that is ultimately causing the issue). Later, when Jest formats the open handles, it throws out all the other handles with the same stack trace. So it could be that the DNSCHANNEL is obscruing a message about a timer that would otherwise be printed. 😞 (You can see an example of this in practice in the fix I just filed for #9982: #11470 (comment))

[joshkel]

@Mr0grog Makes sense; thanks for the explanation.

[github-actions]

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]

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.

[github-actions]

This issue 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.