Wait for closed resources to actually close before detecting open handles (#11429)

Author: Mr0grog

CHANGELOG.md

@@ -71,6 +71,7 @@
 - `[jest-core]` Use `WeakRef` to hold timers when detecting open handles ([#11277](https://github.com/facebook/jest/pull/11277))
 - `[jest-core]` Correctly detect open handles that were created in test functions using `done` callbacks ([#11382](https://github.com/facebook/jest/pull/11382))
 - `[jest-core]` Do not collect `RANDOMBYTESREQUEST` as open handles ([#11278](https://github.com/facebook/jest/pull/11278))
+- `[jest-core]` Wait briefly for open handles to close before flagging them when using `--detectOpenHandles` ([#11429](https://github.com/facebook/jest/pull/11429))
 - `[jest-diff]` [**BREAKING**] Use only named exports ([#11371](https://github.com/facebook/jest/pull/11371))
 - `[jest-each]` [**BREAKING**] Ignore excess words in headings ([#8766](https://github.com/facebook/jest/pull/8766))
 - `[jest-each]` Support array index with template strings ([#10763](https://github.com/facebook/jest/pull/10763))

e2e/__tests__/__snapshots__/detectOpenHandles.ts.snap

@@ -1,5 +1,7 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
+exports[`does not print info about open handlers for a server that is already closed 1`] = ``;
+
 exports[`prints message about flag on forceExit 1`] = `Force exiting Jest: Have you considered using \`--detectOpenHandles\` to detect async operations that kept running after all tests finished?`;
 
 exports[`prints message about flag on slow tests 1`] = `
@@ -11,7 +13,7 @@ This usually means that there are asynchronous operations that weren't stopped i
 exports[`prints out info about open handlers 1`] = `
 Jest has detected the following 1 open handle potentially keeping Jest from exiting:
 
-  ●  GETADDRINFOREQWRAP
+  ●  DNSCHANNEL
 
       12 | const app = new Server();
       13 |

e2e/__tests__/detectOpenHandles.ts

@@ -166,3 +166,15 @@ it('prints out info about open handlers from lifecycle functions with a `done` c
 
   expect(wrap(textAfterTest)).toMatchSnapshot();
 });
+
+it('does not print info about open handlers for a server that is already closed', async () => {
+  const run = runContinuous('detect-open-handles', [
+    'recently-closed',
+    '--detectOpenHandles',
+  ]);
+  await run.waitUntil(({stderr}) => stderr.includes('Ran all test suites'));
+  const {stderr} = await run.end();
+  const textAfterTest = getTextAfterTest(stderr);
+
+  expect(wrap(textAfterTest)).toMatchSnapshot();
+});

e2e/detect-open-handles/__tests__/recently-closed.js

@@ -0,0 +1,20 @@
+/**
+ * Copyright (c) Facebook, Inc. and its affiliates. All Rights Reserved.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ */
+
+import {createServer} from 'http';
+
+test('a recently closed server should not be detected by --detectOpenHandles', done => {
+  const server = createServer((_, response) => response.end('ok'));
+  server.listen(0, () => {
+    expect(true).toBe(true);
+
+    // Close server and return immediately on callback. During the "close"
+    // callback, async hooks usually have not yet been called, but we want to
+    // make sure Jest can figure out that this server is closed.
+    server.close(done);
+  });
+});

packages/jest-core/src/__tests__/collectHandles.test.js

@@ -11,27 +11,30 @@ import {PerformanceObserver} from 'perf_hooks';
 import collectHandles from '../collectHandles';
 
 describe('collectHandles', () => {
-  it('should collect Timeout', () => {
+  it('should collect Timeout', async () => {
     const handleCollector = collectHandles();
 
     const interval = setInterval(() => {}, 100);
 
-    const openHandles = handleCollector();
+    const openHandles = await handleCollector();
 
-    expect(openHandles).toHaveLength(1);
-    expect(openHandles[0].message).toContain('Timeout');
+    expect(openHandles).toContainEqual(
+      expect.objectContaining({message: 'Timeout'}),
+    );
 
     clearInterval(interval);
   });
 
-  it('should not collect the PerformanceObserver open handle', () => {
+  it('should not collect the PerformanceObserver open handle', async () => {
     const handleCollector = collectHandles();
     const obs = new PerformanceObserver((list, observer) => {});
     obs.observe({entryTypes: ['mark']});
 
-    const openHandles = handleCollector();
+    const openHandles = await handleCollector();
 
-    expect(openHandles).toHaveLength(0);
+    expect(openHandles).not.toContainEqual(
+      expect.objectContaining({message: 'PerformanceObserver'}),
+    );
     obs.disconnect();
   });
 
@@ -40,14 +43,49 @@ describe('collectHandles', () => {
     const server = http.createServer((_, response) => response.end('ok'));
     server.listen(0, () => {
       // Collect results while server is still open.
-      const openHandles = handleCollector();
-
-      server.close(() => {
-        expect(openHandles).toContainEqual(
-          expect.objectContaining({message: 'TCPSERVERWRAP'}),
-        );
-        done();
-      });
+      handleCollector()
+        .then(openHandles => {
+          server.close(() => {
+            expect(openHandles).toContainEqual(
+              expect.objectContaining({message: 'TCPSERVERWRAP'}),
+            );
+            done();
+          });
+        })
+        .catch(done);
     });
   });
+
+  it('should not collect handles that have been queued to close', async () => {
+    const handleCollector = collectHandles();
+    const server = http.createServer((_, response) => response.end('ok'));
+
+    // Start and stop server.
+    await new Promise(r => server.listen(0, r));
+    await new Promise(r => server.close(r));
+
+    const openHandles = await handleCollector();
+    expect(openHandles).toHaveLength(0);
+  });
+
+  it('should collect handles indirectly triggered by user code', async () => {
+    const handleCollector = collectHandles();
+
+    // Calling `server.listen` with just a port (e.g. `server.listen(0)`)
+    // creates a `TCPSERVERWRAP` async resource. However, including a `host`
+    // option instead creates a `GETADDRINFOREQWRAP` resource that only
+    // lasts for the lifetime of the `listen()` call, but which *indirectly*
+    // creates a long-lived `TCPSERVERWRAP` resource. We want to make sure we
+    // capture that long-lived resource.
+    const server = new http.Server();
+    await new Promise(r => server.listen({host: 'localhost', port: 0}, r));
+
+    const openHandles = await handleCollector();
+
+    await new Promise(r => server.close(r));
+
+    expect(openHandles).toContainEqual(
+      expect.objectContaining({message: 'TCPSERVERWRAP'}),
+    );
+  });
 });

packages/jest-core/src/collectHandles.ts

@@ -8,12 +8,13 @@
 /* eslint-disable local/ban-types-eventually */
 
 import * as asyncHooks from 'async_hooks';
+import {promisify} from 'util';
 import stripAnsi = require('strip-ansi');
 import type {Config} from '@jest/types';
 import {formatExecError} from 'jest-message-util';
 import {ErrorWithStack} from 'jest-util';
 
-export type HandleCollectionResult = () => Array<Error>;
+export type HandleCollectionResult = () => Promise<Array<Error>>;
 
 function stackIsFromUser(stack: string) {
   // Either the test file, or something required by it
@@ -42,6 +43,8 @@ const alwaysActive = () => true;
 // @ts-expect-error: doesn't exist in v10 typings
 const hasWeakRef = typeof WeakRef === 'function';
 
+const asyncSleep = promisify(setTimeout);
+
 // Inspired by https://github.com/mafintosh/why-is-node-running/blob/master/index.js
 // Extracted as we want to format the result ourselves
 export default function collectHandles(): HandleCollectionResult {
@@ -56,7 +59,7 @@ export default function collectHandles(): HandleCollectionResult {
     init: function initHook(
       asyncId,
       type,
-      _triggerAsyncId,
+      triggerAsyncId,
       resource: {} | NodeJS.Timeout,
     ) {
       if (
@@ -68,9 +71,21 @@ export default function collectHandles(): HandleCollectionResult {
       ) {
         return;
       }
-      const error = new ErrorWithStack(type, initHook);
+      const error = new ErrorWithStack(type, initHook, 100);
+      let fromUser = stackIsFromUser(error.stack || '');
+
+      // If the async resource was not directly created by user code, but was
+      // triggered by another async resource from user code, track it and use
+      // the original triggering resource's stack.
+      if (!fromUser) {
+        const triggeringHandle = activeHandles.get(triggerAsyncId);
+        if (triggeringHandle) {
+          fromUser = true;
+          error.stack = triggeringHandle.error.stack;
+        }
+      }
 
-      if (stackIsFromUser(error.stack || '')) {
+      if (fromUser) {
         let isActive: () => boolean;
 
         if (type === 'Timeout' || type === 'Immediate') {
@@ -102,7 +117,14 @@ export default function collectHandles(): HandleCollectionResult {
 
   hook.enable();
 
-  return () => {
+  return async () => {
+    // Wait briefly for any async resources that have been queued for
+    // destruction to actually be destroyed.
+    // For example, Node.js TCP Servers are not destroyed until *after* their
+    // `close` callback runs. If someone finishes a test from the `close`
+    // callback, we will not yet have seen the resource be destroyed here.
+    await asyncSleep(100);
+
     hook.disable();
 
     // Get errors for every async resource still referenced at this moment

packages/jest-core/src/runJest.ts

@@ -75,7 +75,7 @@ type ProcessResultOptions = Pick<
   outputStream: NodeJS.WriteStream;
 };
 
-const processResults = (
+const processResults = async (
   runResults: AggregatedResult,
   options: ProcessResultOptions,
 ) => {
@@ -89,7 +89,7 @@ const processResults = (
   } = options;
 
   if (collectHandles) {
-    runResults.openHandles = collectHandles();
+    runResults.openHandles = await collectHandles();
   } else {
     runResults.openHandles = [];
   }
@@ -282,7 +282,7 @@ export default async function runJest({
     await runGlobalHook({allTests, globalConfig, moduleName: 'globalTeardown'});
   }
 
-  processResults(results, {
+  await processResults(results, {
     collectHandles,
     json: globalConfig.json,
     onComplete,

packages/jest-util/src/ErrorWithStack.ts

@@ -9,10 +9,19 @@ export default class ErrorWithStack extends Error {
   constructor(
     message: string | undefined,
     callsite: (...args: Array<any>) => unknown,
+    stackLimit?: number,
   ) {
+    // Ensure we have a large stack length so we get full details.
+    const originalStackLimit = Error.stackTraceLimit;
+    if (stackLimit) {
+      Error.stackTraceLimit = Math.max(stackLimit, originalStackLimit || 10);
+    }
+
     super(message);
     if (Error.captureStackTrace) {
       Error.captureStackTrace(this, callsite);
     }
+
+    Error.stackTraceLimit = originalStackLimit;
   }
 }