Skip to content

Commit

Permalink
show both collected and uncollected handles
Browse files Browse the repository at this point in the history
  • Loading branch information
SimenB committed Feb 20, 2020
1 parent b868ad1 commit 9ade171
Show file tree
Hide file tree
Showing 7 changed files with 217 additions and 44 deletions.
39 changes: 36 additions & 3 deletions e2e/__tests__/__snapshots__/detectOpenHandles.ts.snap
Original file line number Diff line number Diff line change
@@ -1,5 +1,26 @@
// Jest Snapshot v1, https://goo.gl/fbAQLP

exports[`deals with http servers and promises 1`] = `
Jest has detected the following open 1 handle potentially preventing Jest from exiting:
Of them 1 was collected within 100ms of the tests completing.
These are sometimes useful to look at as they might have spawned other handles that remain open, but that we have lost the origin of.
There were no uncollected handles - this is unexpected if your tests do not exit cleanly.
Collected handles:
● TCPSERVERWRAP
4 | const server = http.createServer();
5 | await new Promise(resolve => {
> 6 | server.listen(resolve);
| ^
7 | });
8 | await new Promise((resolve, reject) => {
9 | server.close(err => {
at listen (__tests__/http.js:6:12)
at Object.<anonymous> (__tests__/http.js:5:9)
`;
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`] = `
Expand All @@ -9,8 +30,20 @@ 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 preventing Jest from exiting:
Jest has detected the following open 3 handles potentially preventing Jest from exiting:
Of them 1 was collected within 100ms of the tests completing.
These are sometimes useful to look at as they might have spawned other handles that remain open, but that we have lost the origin of.
Uncollected handles:
● DNSCHANNEL
● TCPSERVERWRAP
Collected handles:
● GETADDRINFOREQWRAP
12 | const app = new Server();
Expand All @@ -24,8 +57,8 @@ Jest has detected the following 1 open handle potentially preventing Jest from e
`;
exports[`prints out info about open handlers from inside tests 1`] = `
Jest has detected the following 1 open handle potentially preventing Jest from exiting:
Jest has detected the following open 1 handle potentially preventing Jest from exiting:
Uncollected handles:
● Timeout
7 |
Expand Down
16 changes: 14 additions & 2 deletions e2e/__tests__/detectOpenHandles.ts
Original file line number Diff line number Diff line change
Expand Up @@ -68,7 +68,7 @@ it('does not report promises', () => {
]);
const textAfterTest = getTextAfterTest(stderr);

expect(textAfterTest).toBe('');
expect(textAfterTest).toContain('There were no uncollected handles');
});

describe('notify', () => {
Expand All @@ -92,7 +92,7 @@ onNodeVersions('>=11', () => {
]);
const textAfterTest = getTextAfterTest(stderr);

expect(textAfterTest).toBe('');
expect(textAfterTest).toContain('There were no uncollected handles');
});
});

Expand All @@ -107,3 +107,15 @@ it('prints out info about open handlers from inside tests', async () => {

expect(wrap(textAfterTest)).toMatchSnapshot();
});

it('deals with http servers and promises', async () => {
const run = runContinuous('detect-open-handles', [
'http',
'--detectOpenHandles',
]);
await run.waitUntil(({stderr}) => stderr.includes('Jest has detected'));
const {stderr} = await run.end();
const textAfterTest = getTextAfterTest(stderr);

expect(wrap(textAfterTest)).toMatchSnapshot();
});
17 changes: 17 additions & 0 deletions e2e/detect-open-handles/__tests__/http.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,17 @@
const http = require('http');

it('should not timeout', async () => {
const server = http.createServer();
await new Promise(resolve => {
server.listen(resolve);
});
await new Promise((resolve, reject) => {
server.close(err => {
if (err) {
reject(err);
} else {
resolve();
}
});
});
});
52 changes: 43 additions & 9 deletions packages/jest-core/src/cli/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -93,19 +93,53 @@ export async function runCLI(
);
}

const {openHandles} = results;
if (globalConfig.detectOpenHandles) {
const {openHandles} = results;

if (openHandles && openHandles.length) {
const formatted = formatHandleErrors(openHandles, configs[0]);
if (openHandles.length > 0) {
const formatted = formatHandleErrors(openHandles, configs[0]);
const uncollectedHandles = formatted
.filter(({wasCollected}) => !wasCollected)
.map(({stack}) => stack);
const collectedHandles = formatted
.filter(({wasCollected}) => wasCollected)
.map(({stack}) => stack);

const openHandlesString = pluralize('open handle', formatted.length, 's');
const openHandlesString = pluralize('handle', formatted.length, 's');

const message =
chalk.red(
`\nJest has detected the following ${openHandlesString} potentially preventing Jest from exiting:\n\n`,
) + formatted.join('\n\n');
const alreadyCollectedString =
collectedHandles.length === 0
? ''
: collectedHandles.length === 1
? '1 was'
: `${collectedHandles.length} were`;

console.error(message);
let heading = chalk.red(
`Jest has detected the following open ${openHandlesString} potentially preventing Jest from exiting:`,
);

if (alreadyCollectedString) {
heading += chalk.yellow(
`\nOf them ${alreadyCollectedString} collected within 100ms of the tests completing.\nThese are sometimes useful to look at as they might have spawned other handles that remain open, but that we have lost the origin of.`,
);
}

const uncollectedHandlesString =
uncollectedHandles.length > 0
? `Uncollected handles: \n${uncollectedHandles.join('\n')}`
: 'There were no uncollected handles - this is unexpected if your tests do not exit cleanly.';

const collectedHandlesString =
collectedHandles.length > 0
? `\n\nCollected handles: \n${collectedHandles.join('\n')}`
: '';

const message = `\n\n${heading}\n${uncollectedHandlesString}${collectedHandlesString}`;

console.error(message);
} else {
console.error(chalk.red('\nJest was unable to detect any open handles'));
}
}

return {globalConfig, results};
Expand Down
69 changes: 52 additions & 17 deletions packages/jest-core/src/collectHandles.ts
Original file line number Diff line number Diff line change
Expand Up @@ -10,12 +10,25 @@ import {Config} from '@jest/types';
import {formatExecError} from 'jest-message-util';
import {ErrorWithStack} from 'jest-util';
import stripAnsi = require('strip-ansi');
import {AggregatedResult} from '@jest/test-result';

export type OpenHandleError = AggregatedResult['openHandles'][number];

const alwaysActive = () => true;

function isSafeJestInternal(stack: string) {
return stack
.split('\n')
.some(
line =>
line.includes('at Status._debouncedEmit') &&
line.includes('build/Status.js'),
);
}

// 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(): () => Array<Error> {
export default function collectHandles(): (keepOpen: boolean) => Array<Error> {
const activeHandles: Map<
number,
{error: Error; isActive: () => boolean}
Expand All @@ -30,7 +43,12 @@ export default function collectHandles(): () => Array<Error> {
_triggerAsyncId,
resource: {} | NodeJS.Timeout,
) {
if (type === 'PROMISE' || type === 'TIMERWRAP') {
if (
type === 'PROMISE' ||
type === 'TIMERWRAP' ||
type === 'SHUTDOWNWRAP' ||
type === 'TickObject'
) {
return;
}
const error = new ErrorWithStack(type, initHook);
Expand Down Expand Up @@ -58,52 +76,69 @@ export default function collectHandles(): () => Array<Error> {

hook.enable();

return (): Array<Error> => {
hook.disable();
return (keepOpen: boolean): Array<Error> => {
if (!keepOpen) {
hook.disable();
}

// Get errors for every async resource still referenced at this moment
const result = Array.from(activeHandles.values())
.filter(({isActive}) => isActive())
.map(({error}) => error);

activeHandles.clear();
if (!keepOpen) {
activeHandles.clear();
}

return result;
};
}

export function formatHandleErrors(
errors: Array<Error>,
errors: Array<OpenHandleError>,
config: Config.ProjectConfig,
): Array<string> {
): Array<{stack: string; wasCollected: boolean}> {
const stacks = new Set();

return (
errors
.map(err =>
formatExecError(err, config, {noStackTrace: false}, undefined, true),
)
.map(err => {
const stack = formatExecError(
err,
config,
{noStackTrace: false},
undefined,
true,
);

return {stack, wasCollected: err.wasCollected};
})
// E.g. timeouts might give multiple traces to the same line of code
// This hairy filtering tries to remove entries with duplicate stack traces
.filter(handle => {
const ansiFree: string = stripAnsi(handle);
.filter(({stack, wasCollected}) => {
const ansiFree: string = stripAnsi(stack);

if (isSafeJestInternal(ansiFree)) {
return false;
}

const match = ansiFree.match(/\s+at(.*)/);

if (!match || match.length < 2) {
return true;
}

const stack = ansiFree.substr(ansiFree.indexOf(match[1])).trim();
const stackWithoutHeading =
// include `wasCollected` as a "vary"
ansiFree.substr(ansiFree.indexOf(match[1])).trim() + wasCollected;

if (stacks.has(stack)) {
if (stacks.has(stackWithoutHeading)) {
return false;
}

stacks.add(stack);
stacks.add(stackWithoutHeading);

return true;
})
// only keep stacks with at least one frame. `length === 1` means just the heading (normally meaning node internal), which is useless
.filter(stack => stack.trim().split('\n').length > 1)
);
}
Loading

0 comments on commit 9ade171

Please sign in to comment.