From 3b253f83b7500f2d5b627f4ab5f6971e7ef8349c Mon Sep 17 00:00:00 2001 From: Rob Brackett Date: Thu, 20 May 2021 15:24:20 -0700 Subject: [PATCH] Wait for closed resources to actually close before detecting open handles (#11429) --- CHANGELOG.md | 1 + .../__snapshots__/detectOpenHandles.ts.snap | 4 +- e2e/__tests__/detectOpenHandles.ts | 12 ++++ .../__tests__/recently-closed.js | 20 ++++++ .../src/__tests__/collectHandles.test.js | 68 +++++++++++++++---- packages/jest-core/src/collectHandles.ts | 32 +++++++-- packages/jest-core/src/runJest.ts | 6 +- packages/jest-util/src/ErrorWithStack.ts | 9 +++ 8 files changed, 128 insertions(+), 24 deletions(-) create mode 100644 e2e/detect-open-handles/__tests__/recently-closed.js diff --git a/CHANGELOG.md b/CHANGELOG.md index dac3fa0e83f6..379ffedfd027 100644 --- a/CHANGELOG.md +++ b/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)) diff --git a/e2e/__tests__/__snapshots__/detectOpenHandles.ts.snap b/e2e/__tests__/__snapshots__/detectOpenHandles.ts.snap index f679a6e076f5..40aeef9d4529 100644 --- a/e2e/__tests__/__snapshots__/detectOpenHandles.ts.snap +++ b/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 | diff --git a/e2e/__tests__/detectOpenHandles.ts b/e2e/__tests__/detectOpenHandles.ts index 6e7ec474812f..cd6cdfa17225 100644 --- a/e2e/__tests__/detectOpenHandles.ts +++ b/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(); +}); diff --git a/e2e/detect-open-handles/__tests__/recently-closed.js b/e2e/detect-open-handles/__tests__/recently-closed.js new file mode 100644 index 000000000000..3ce6b0cfc9ca --- /dev/null +++ b/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); + }); +}); diff --git a/packages/jest-core/src/__tests__/collectHandles.test.js b/packages/jest-core/src/__tests__/collectHandles.test.js index 7192709d9350..9e97b8c64498 100644 --- a/packages/jest-core/src/__tests__/collectHandles.test.js +++ b/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'}), + ); + }); }); diff --git a/packages/jest-core/src/collectHandles.ts b/packages/jest-core/src/collectHandles.ts index 05f2ea481936..c98543d647c1 100644 --- a/packages/jest-core/src/collectHandles.ts +++ b/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; +export type HandleCollectionResult = () => Promise>; 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 diff --git a/packages/jest-core/src/runJest.ts b/packages/jest-core/src/runJest.ts index 90d68275ed8c..b6088007235a 100644 --- a/packages/jest-core/src/runJest.ts +++ b/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, diff --git a/packages/jest-util/src/ErrorWithStack.ts b/packages/jest-util/src/ErrorWithStack.ts index cbdcf7fa8058..9ccac1c8aa44 100644 --- a/packages/jest-util/src/ErrorWithStack.ts +++ b/packages/jest-util/src/ErrorWithStack.ts @@ -9,10 +9,19 @@ export default class ErrorWithStack extends Error { constructor( message: string | undefined, callsite: (...args: Array) => 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; } }