From f413adec5d07afc192af799d8df0b335322551a8 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Fri, 19 Jun 2026 13:34:49 -0400 Subject: [PATCH 01/12] chore: midwork --- packages/aws-cdk/lib/cli/cli.ts | 21 ++ packages/aws-cdk/lib/cli/debug-handles.ts | 279 ++++++++++++++++++ .../aws-cdk/test/cli/debug-handles.test.ts | 84 ++++++ 3 files changed, 384 insertions(+) create mode 100644 packages/aws-cdk/lib/cli/debug-handles.ts create mode 100644 packages/aws-cdk/test/cli/debug-handles.test.ts diff --git a/packages/aws-cdk/lib/cli/cli.ts b/packages/aws-cdk/lib/cli/cli.ts index 6966f1420..75c6ec280 100644 --- a/packages/aws-cdk/lib/cli/cli.ts +++ b/packages/aws-cdk/lib/cli/cli.ts @@ -6,6 +6,7 @@ import * as chalk from 'chalk'; import { guessLanguage } from '../util'; import { CdkToolkit, AssetBuildTime } from './cdk-toolkit'; import { ciSystemIsStdErrSafe } from './ci-systems'; +import { enableHandleTracking, reportLeakedHandles } from './debug-handles'; import { displayVersionMessage, shouldDisplayVersionMessage } from './display-version'; import type { IoMessageLevel } from './io-host'; import { CliIoHost } from './io-host'; @@ -42,12 +43,23 @@ import { findUnknownOptions } from './util/check-unknown-options'; import { isCI } from './util/ci'; import { guessAgent } from './util/guess-agent'; +// Grace period before the --debug-cli handle dump fires. unref'd, so it never +// fires when Node exits cleanly within this window. +const HANDLE_DUMP_GRACE_MS = 1000; + export async function exec(args: string[], synthesizer?: Synthesizer): Promise { // This is the very first code that runs, but libraries have been loaded already and that also costs time. // Measure that. const libraryLoadTime = performance.now(); const argv = await parseCommandLineArguments(args); + + if (argv.debugCli) { + // Start tracking async resources as early as possible, so we can identify + // the ones still alive at exit time. + enableHandleTracking(); + } + argv.language = getLanguageFromAlias(argv.language) ?? argv.language; // Handle color output settings @@ -258,6 +270,15 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise notices.display()); } + + if (argv.debugCli) { + // If the process is still alive after the grace period, something is + // keeping the event loop busy. Dump the leaked handles so the user can + // see why. .unref() so this timer itself doesn't keep us alive. + setTimeout(() => { + void reportLeakedHandles(ioHelper); + }, HANDLE_DUMP_GRACE_MS).unref(); + } } async function main(command: string, args: any): Promise { diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts new file mode 100644 index 000000000..8c8220c1f --- /dev/null +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -0,0 +1,279 @@ +import { createHook } from 'node:async_hooks'; +import { readFileSync } from 'node:fs'; +import { basename, relative } from 'node:path'; +import { fileURLToPath } from 'node:url'; +import * as chalk from 'chalk'; +import type { IoHelper } from '../../lib/api-private'; + +// WeakRef exists at runtime on all supported Node versions; reach it via +// globalThis since the package's ES2020 lib predates its type. +type WeakRefConstructor = new (value: T) => { deref(): T | undefined }; +const WeakRefImpl = (globalThis as unknown as { WeakRef: WeakRefConstructor }).WeakRef; + +/** + * async_hooks resource types that are noise in a "why won't the process exit" + * report: created in large numbers and effectively never the handle a user can + * act on. + */ +const SKIP_TYPES: ReadonlySet = new Set([ + 'PROMISE', + 'PerformanceObserver', + 'RANDOMBYTESREQUEST', +]); + +/** + * Plain-language descriptions for Node's async resource types (the fixed set in + * V8/libuv's async_wrap providers). The raw type is always shown; a description + * is appended when we have one, so any future/unknown type still reports + * truthfully. + */ +const TYPE_DESCRIPTIONS: Readonly> = { + TCPWRAP: 'open network connection', + TCPSERVERWRAP: 'listening TCP server', + TCPSOCKETWRAP: 'open network connection', + TCPCONNECTWRAP: 'pending outbound TCP connection', + PIPEWRAP: 'open pipe', + PIPESERVERWRAP: 'listening pipe server', + PIPECONNECTWRAP: 'pending pipe connection', + UDPWRAP: 'open UDP socket', + UDPSENDWRAP: 'pending UDP send', + TLSWRAP: 'open TLS connection', + TTYWRAP: 'open terminal stream', + TIMERWRAP: 'timer', + Timeout: 'timer from setTimeout or setInterval', + Immediate: 'pending setImmediate callback', + FSREQCALLBACK: 'pending file-system operation', + FSREQPROMISE: 'pending file-system operation', + FSEVENTWRAP: 'file-system watcher', + STATWATCHER: 'file-system stat watcher', + PROCESSWRAP: 'child process', + ChildProcess: 'child process', + GETADDRINFOREQWRAP: 'pending DNS lookup', + GETNAMEINFOREQWRAP: 'pending DNS reverse lookup', + QUERYWRAP: 'pending DNS query', + HTTPCLIENTREQUEST: 'in-flight HTTP request', + HTTPINCOMINGMESSAGE: 'incoming HTTP message', + HTTP2SESSION: 'HTTP/2 session', + HTTP2STREAM: 'HTTP/2 stream', + HTTP2PING: 'pending HTTP/2 ping', + HTTP2SETTINGS: 'pending HTTP/2 settings', + WRITEWRAP: 'pending stream write', + SHUTDOWNWRAP: 'pending stream shutdown', + SIGNALWRAP: 'signal handler', + WORKER: 'worker thread', + MESSAGEPORT: 'message port', + ZLIB: 'zlib (de)compression stream', + DNSCHANNEL: 'DNS resolver channel', + ELDHISTOGRAM: 'event-loop-delay histogram', + FILEHANDLE: 'open file handle', + FILEHANDLECLOSEREQ: 'pending file-handle close', + HEAPSNAPSHOT: 'heap snapshot stream', + JSSTREAM: 'JavaScript stream', + JSUDPWRAP: 'JavaScript UDP wrapper', + KEYPAIRGENREQUEST: 'pending key-pair generation', + KEYGENREQUEST: 'pending key generation', + KEYEXPORTREQUEST: 'pending key export', + CIPHERREQUEST: 'pending cipher operation', + DERIVEBITSREQUEST: 'pending key-derivation', + HASHREQUEST: 'pending hash operation', + SIGNREQUEST: 'pending sign operation', + VERIFYREQUEST: 'pending verify operation', + HTTPPARSER: 'HTTP parser', + INSPECTORJSBINDING: 'inspector binding', + SCRYPTREQUEST: 'pending scrypt operation', + PBKDF2REQUEST: 'pending PBKDF2 operation', +}; + +/** + * Basename (without extension) of this module, so we can drop our own frames + * from reported stacks. + */ +const SELF_MODULE = 'debug-handles'; + +interface SourceFrame { + readonly file: string; + readonly line: number; +} + +/** + * A resource we are watching: a weak reference to the handle (so tracking does + * not itself keep it alive) and the stack of where it was created. + */ +interface WatchedResource { + readonly type: string; + readonly handleRef: { deref(): { hasRef?(): boolean } | undefined }; + readonly creationStack: SourceFrame[]; +} + +/** + * Tracks async resources via async_hooks and, on demand, reports the ones still + * keeping the event loop alive together with where they were created. + * + * The cost lands only when opted in: tracking is off until `start()` is called. + */ +class LeakedHandleTracker { + private readonly watched = new Map(); + + private readonly hook = createHook({ + init: (asyncId, type, _triggerAsyncId, resource) => { + if (SKIP_TYPES.has(type)) { + return; + } + this.watched.set(asyncId, { + type, + handleRef: new WeakRefImpl(resource as { hasRef?(): boolean }), + creationStack: captureCreationStack(), + }); + }, + destroy: (asyncId) => { + this.watched.delete(asyncId); + }, + }); + + /** + * Begin watching async resources. Must run before the resources we care about + * are created, and only when the user opted in — the hook adds a small + * per-resource cost. + */ + public start = (): void => { + this.hook.enable(); + }; + + /** + * Stop watching and discard all tracked state. + * + * @internal exposed only so tests can isolate the shared singleton. + */ + public reset = (): void => { + this.hook.disable(); + this.watched.clear(); + }; + + /** + * Report every resource still holding the event loop open, each with the + * source location where it was created. Call at the very end of execution, by + * which point only genuinely leaked handles should remain. + */ + public report = async (ioHelper: IoHelper): Promise => { + this.hook.disable(); + + const leaks = [...this.watched.values()].filter((r) => { + const handle = r.handleRef.deref(); + // Already garbage collected, so no longer keeping the loop alive. + if (handle === undefined) { + return false; + } + return handle.hasRef?.() ?? true; + }); + this.watched.clear(); + + await ioHelper.defaults.info(`${leaks.length} handle(s) still keeping the CLI process alive:`); + for (const leak of leaks) { + await this.describe(leak, ioHelper); + } + }; + + private async describe(leak: WatchedResource, ioHelper: IoHelper): Promise { + const frames = actionableFrames(leak.creationStack); + + await ioHelper.defaults.info(''); + const description = TYPE_DESCRIPTIONS[leak.type]; + const heading = description ? `# ${leak.type} (${description})` : `# ${leak.type}`; + await ioHelper.defaults.info(chalk.bold(heading)); + + if (frames.length === 0) { + await ioHelper.defaults.info(' (no application stack frames)'); + return; + } + + // The first frame is where the handle was created; the rest is the call + // path that led there. + const [origin, ...callers] = frames; + await ioHelper.defaults.info(` created at ${describeLocation(origin)}`); + const source = sourceAt(origin); + if (source) { + await ioHelper.defaults.info(` ${source}`); + } + for (const caller of callers) { + await ioHelper.defaults.info(` called from ${describeLocation(caller)}`); + } + } +} + +/** + * Capture the call site of the current async resource as structured frames. + * + * We install a structured `prepareStackTrace` formatter, capture (using this + * function as the cut-off so neither it nor the async hook appears), then + * restore the previous formatter so we don't disturb anyone else's stacks. + */ +function captureCreationStack(): SourceFrame[] { + const carrier: { stack?: SourceFrame[] } = {}; + + // `Error.prepareStackTrace` is a V8 formatting hook we save and restore, not a + // method we invoke, so the unbound-method concern does not apply here. + // eslint-disable-next-line @typescript-eslint/unbound-method + const previous = Error.prepareStackTrace; + Error.prepareStackTrace = (_error, callSites) => callSites.map((site) => { + const file = site.getFileName() ?? ''; + return { + file: file.startsWith('file://') ? fileURLToPath(file) : file, + line: site.getLineNumber() ?? 0, + }; + }); + try { + Error.captureStackTrace(carrier, captureCreationStack); + return carrier.stack ?? []; + } finally { + Error.prepareStackTrace = previous; + } +} + +/** + * Keep only frames the user can act on: drop Node internals and our own module. + */ +function actionableFrames(frames: SourceFrame[]): SourceFrame[] { + return frames.filter((frame) => { + if (!frame.file || frame.file.startsWith('node:')) { + return false; + } + // basename so the match holds regardless of path separator (e.g. Windows). + return !basename(frame.file).startsWith(`${SELF_MODULE}.`); + }); +} + +function describeLocation(frame: SourceFrame): string { + const fromCwd = relative(process.cwd(), frame.file); + // A leading '..' means the file is outside cwd, where the absolute path reads better. + const shown = fromCwd.startsWith('..') ? frame.file : fromCwd; + return `${shown}:${frame.line}`; +} + +function sourceAt(frame: SourceFrame): string | undefined { + try { + return readFileSync(frame.file, 'utf-8').split(/\r?\n/)[frame.line - 1]?.trim() || undefined; + } catch { + // The source file may not be readable (e.g. a bundled or eval'd frame). + // The location is still useful on its own, so reporting continues without it. + return undefined; + } +} + +const tracker = new LeakedHandleTracker(); + +/** + * Start tracking async resources. See {@link LeakedHandleTracker.start}. + */ +export const enableHandleTracking = tracker.start; + +/** + * Report handles still keeping the loop alive. See {@link LeakedHandleTracker.report}. + */ +export const reportLeakedHandles = tracker.report; + +/** + * Stop tracking and discard all state. + * + * @internal exposed only so tests can isolate the shared singleton. + */ +export const resetHandleTracking = tracker.reset; diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts new file mode 100644 index 000000000..9403b9d80 --- /dev/null +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -0,0 +1,84 @@ +import { once } from 'node:events'; +import * as net from 'node:net'; +import { setTimeout as delay } from 'node:timers/promises'; +import { enableHandleTracking, reportLeakedHandles, resetHandleTracking } from '../../lib/cli/debug-handles'; +import { TestIoHost } from '../_helpers/io-host'; + +let ioHost: TestIoHost; + +beforeEach(() => { + // The tracker is a module singleton; reset it so each test starts clean. + resetHandleTracking(); + ioHost = new TestIoHost(); +}); + +afterEach(() => { + resetHandleTracking(); +}); + +// The text of every message the report emitted, in order. +function reportedLines(): string[] { + return ioHost.notifySpy.mock.calls.map((call) => call[0].message as string); +} + +test('reports a leaked timer with its type, plain-language description, and creation site', async () => { + enableHandleTracking(); + + const leaked = setInterval(() => { + }, 60_000); + await reportLeakedHandles(ioHost.asHelper()); + clearInterval(leaked); + + const lines = reportedLines(); + expect(lines[0]).toMatch(/^\d+ handle\(s\) still keeping the CLI process alive:$/); + expect(lines).toContainEqual('# Timeout (timer from setTimeout or setInterval)'); + // A creation site is reported as `file:line`. Which frame ends up on top of the + // stack depends on the async call path, so we assert the shape, not the file. + expect(lines.some((l) => /^ {2}created at .+:\d+$/.test(l))).toBe(true); +}); + +test('reports a leaked TCP connection as an open network connection', async () => { + const server = net.createServer(); + await once(server.listen(0), 'listening'); + const { port } = server.address() as net.AddressInfo; + + // Tracking must start before the connection is created, otherwise the socket + // is never seen — this mirrors how the flag is enabled at CLI startup. + enableHandleTracking(); + const client = net.connect(port, '127.0.0.1'); + try { + await once(client, 'connect'); + await reportLeakedHandles(ioHost.asHelper()); + + expect(reportedLines().some((l) => l.includes('(open network connection)'))).toBe(true); + } finally { + client.destroy(); + server.close(); + await once(server, 'close'); + } +}); + +test('excludes handles that have been unref()ed', async () => { + enableHandleTracking(); + + // unref() means the handle is not keeping the loop alive, so it must be excluded. + const unrefed = setInterval(() => { + }, 60_000); + unrefed.unref(); + await reportLeakedHandles(ioHost.asHelper()); + clearInterval(unrefed); + + expect(reportedLines()).toEqual(['0 handle(s) still keeping the CLI process alive:']); +}); + +test('does not report promises, which are filtered as noise', async () => { + enableHandleTracking(); + + // Every await creates promises; none of them should show up in the report. + for (let i = 0; i < 50; i++) { + await delay(1); + } + await reportLeakedHandles(ioHost.asHelper()); + + expect(reportedLines().some((l) => l.includes('PROMISE'))).toBe(false); +}); From c18381ea65cd820e03228e6d159d8525c41ffdd4 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Fri, 19 Jun 2026 14:49:31 -0400 Subject: [PATCH 02/12] chore: mid work --- packages/aws-cdk/test/cli/debug-handles.test.ts | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index 9403b9d80..7a2d56090 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -1,6 +1,7 @@ import { once } from 'node:events'; import * as net from 'node:net'; import { setTimeout as delay } from 'node:timers/promises'; +import * as chalk from 'chalk'; import { enableHandleTracking, reportLeakedHandles, resetHandleTracking } from '../../lib/cli/debug-handles'; import { TestIoHost } from '../_helpers/io-host'; @@ -31,7 +32,9 @@ test('reports a leaked timer with its type, plain-language description, and crea const lines = reportedLines(); expect(lines[0]).toMatch(/^\d+ handle\(s\) still keeping the CLI process alive:$/); - expect(lines).toContainEqual('# Timeout (timer from setTimeout or setInterval)'); + // The type heading is emitted via chalk.bold, so match it the same way to stay + // independent of whether color is active in the test environment. + expect(lines).toContainEqual(chalk.bold('# Timeout (timer from setTimeout or setInterval)')); // A creation site is reported as `file:line`. Which frame ends up on top of the // stack depends on the async call path, so we assert the shape, not the file. expect(lines.some((l) => /^ {2}created at .+:\d+$/.test(l))).toBe(true); From 795aa67448f7d9201f0eae68d49a1df5201a4276 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Mon, 22 Jun 2026 16:20:38 -0400 Subject: [PATCH 03/12] chore: midwork --- packages/aws-cdk/lib/cli/debug-handles.ts | 42 +++++++++++-------- .../aws-cdk/test/cli/debug-handles.test.ts | 12 +++++- 2 files changed, 36 insertions(+), 18 deletions(-) diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index 8c8220c1f..f12d338f4 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -39,37 +39,37 @@ const TYPE_DESCRIPTIONS: Readonly> = { UDPSENDWRAP: 'pending UDP send', TLSWRAP: 'open TLS connection', TTYWRAP: 'open terminal stream', - TIMERWRAP: 'timer', + TIMERWRAP: 'internal timer holding the loop open', Timeout: 'timer from setTimeout or setInterval', Immediate: 'pending setImmediate callback', FSREQCALLBACK: 'pending file-system operation', FSREQPROMISE: 'pending file-system operation', FSEVENTWRAP: 'file-system watcher', STATWATCHER: 'file-system stat watcher', - PROCESSWRAP: 'child process', - ChildProcess: 'child process', + PROCESSWRAP: 'spawned child process still running', + ChildProcess: 'spawned child process still running', GETADDRINFOREQWRAP: 'pending DNS lookup', GETNAMEINFOREQWRAP: 'pending DNS reverse lookup', QUERYWRAP: 'pending DNS query', HTTPCLIENTREQUEST: 'in-flight HTTP request', HTTPINCOMINGMESSAGE: 'incoming HTTP message', - HTTP2SESSION: 'HTTP/2 session', - HTTP2STREAM: 'HTTP/2 stream', + HTTP2SESSION: 'open HTTP/2 connection', + HTTP2STREAM: 'open HTTP/2 request stream', HTTP2PING: 'pending HTTP/2 ping', HTTP2SETTINGS: 'pending HTTP/2 settings', WRITEWRAP: 'pending stream write', SHUTDOWNWRAP: 'pending stream shutdown', - SIGNALWRAP: 'signal handler', - WORKER: 'worker thread', - MESSAGEPORT: 'message port', - ZLIB: 'zlib (de)compression stream', - DNSCHANNEL: 'DNS resolver channel', - ELDHISTOGRAM: 'event-loop-delay histogram', + SIGNALWRAP: 'OS signal handler still registered', + WORKER: 'worker thread still running', + MESSAGEPORT: 'open worker-thread message channel', + ZLIB: 'open (de)compression stream', + DNSCHANNEL: 'DNS resolver holding sockets open', + ELDHISTOGRAM: 'event-loop-delay monitor (perf_hooks)', FILEHANDLE: 'open file handle', FILEHANDLECLOSEREQ: 'pending file-handle close', - HEAPSNAPSHOT: 'heap snapshot stream', - JSSTREAM: 'JavaScript stream', - JSUDPWRAP: 'JavaScript UDP wrapper', + HEAPSNAPSHOT: 'heap snapshot being written', + JSSTREAM: 'custom JavaScript-backed stream', + JSUDPWRAP: 'custom JavaScript-backed UDP socket', KEYPAIRGENREQUEST: 'pending key-pair generation', KEYGENREQUEST: 'pending key generation', KEYEXPORTREQUEST: 'pending key export', @@ -78,8 +78,8 @@ const TYPE_DESCRIPTIONS: Readonly> = { HASHREQUEST: 'pending hash operation', SIGNREQUEST: 'pending sign operation', VERIFYREQUEST: 'pending verify operation', - HTTPPARSER: 'HTTP parser', - INSPECTORJSBINDING: 'inspector binding', + HTTPPARSER: 'HTTP parser for an open connection', + INSPECTORJSBINDING: 'debugger/inspector session attached', SCRYPTREQUEST: 'pending scrypt operation', PBKDF2REQUEST: 'pending PBKDF2 operation', }; @@ -90,6 +90,10 @@ const TYPE_DESCRIPTIONS: Readonly> = { */ const SELF_MODULE = 'debug-handles'; +/** + * A single location in a stack trace: the file a frame points to and the line + * within it. + */ interface SourceFrame { readonly file: string; readonly line: number; @@ -251,7 +255,11 @@ function describeLocation(frame: SourceFrame): string { function sourceAt(frame: SourceFrame): string | undefined { try { - return readFileSync(frame.file, 'utf-8').split(/\r?\n/)[frame.line - 1]?.trim() || undefined; + const line = readFileSync(frame.file, 'utf-8').split(/\r?\n/)[frame.line - 1]?.trim() || undefined; + // The shipped CLI is one bundled file where a few lines are huge minified + // blobs (one is ~600k chars). Truncate so a creation site on such a line + // doesn't dump the whole blob; the location alone is still useful. + return line && line.length > 200 ? `${line.slice(0, 200)}…` : line; } catch { // The source file may not be readable (e.g. a bundled or eval'd frame). // The location is still useful on its own, so reporting continues without it. diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index 7a2d56090..282c026bf 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -46,7 +46,7 @@ test('reports a leaked TCP connection as an open network connection', async () = const { port } = server.address() as net.AddressInfo; // Tracking must start before the connection is created, otherwise the socket - // is never seen — this mirrors how the flag is enabled at CLI startup. + // is never seen. This mirrors how the flag is enabled at CLI startup. enableHandleTracking(); const client = net.connect(port, '127.0.0.1'); try { @@ -74,6 +74,16 @@ test('excludes handles that have been unref()ed', async () => { expect(reportedLines()).toEqual(['0 handle(s) still keeping the CLI process alive:']); }); +test('reports zero handles on a clean exit with nothing left open', async () => { + enableHandleTracking(); + + // Nothing is created after tracking starts, so nothing should be holding the + // loop open: the report is just the header with a count of zero. + await reportLeakedHandles(ioHost.asHelper()); + + expect(reportedLines()).toEqual(['0 handle(s) still keeping the CLI process alive:']); +}); + test('does not report promises, which are filtered as noise', async () => { enableHandleTracking(); From 57938192a7dcde7d464ed07564197e2c82b11350 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Mon, 22 Jun 2026 18:31:35 -0400 Subject: [PATCH 04/12] chore: midwork --- .../cdk-debug-cli-handle-report.integtest.ts | 16 +++++++++++ packages/aws-cdk/lib/cli/debug-handles.ts | 28 ++++++++----------- 2 files changed, 28 insertions(+), 16 deletions(-) create mode 100644 packages/@aws-cdk-testing/cli-integ/tests/cli-integ-tests/output/cdk-debug-cli-handle-report.integtest.ts diff --git a/packages/@aws-cdk-testing/cli-integ/tests/cli-integ-tests/output/cdk-debug-cli-handle-report.integtest.ts b/packages/@aws-cdk-testing/cli-integ/tests/cli-integ-tests/output/cdk-debug-cli-handle-report.integtest.ts new file mode 100644 index 000000000..18cf4fae8 --- /dev/null +++ b/packages/@aws-cdk-testing/cli-integ/tests/cli-integ-tests/output/cdk-debug-cli-handle-report.integtest.ts @@ -0,0 +1,16 @@ +import { integTest, withDefaultFixture } from '../../../lib'; + +integTest( + 'debug-cli prints no handle report on a clean exit', + withDefaultFixture(async (fixture) => { + // synth exits cleanly, so the handle tracker's grace timer (which is + // unref'd) must never fire. Exercises the cli.ts wiring end to end: the + // flag enables tracking at startup, and the report stays silent unless the + // process is genuinely still alive after the work is done. + const output = await fixture.cdk(['synth', fixture.fullStackName('test-1'), '--debug-cli'], { + captureStderr: true, + }); + + expect(output).not.toContain('keeping the CLI process alive'); + }), +); diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index f12d338f4..f8b0e18ec 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -1,6 +1,6 @@ import { createHook } from 'node:async_hooks'; import { readFileSync } from 'node:fs'; -import { basename, relative } from 'node:path'; +import { relative } from 'node:path'; import { fileURLToPath } from 'node:url'; import * as chalk from 'chalk'; import type { IoHelper } from '../../lib/api-private'; @@ -84,12 +84,6 @@ const TYPE_DESCRIPTIONS: Readonly> = { PBKDF2REQUEST: 'pending PBKDF2 operation', }; -/** - * Basename (without extension) of this module, so we can drop our own frames - * from reported stacks. - */ -const SELF_MODULE = 'debug-handles'; - /** * A single location in a stack trace: the file a frame points to and the line * within it. @@ -210,6 +204,11 @@ class LeakedHandleTracker { * We install a structured `prepareStackTrace` formatter, capture (using this * function as the cut-off so neither it nor the async hook appears), then * restore the previous formatter so we don't disturb anyone else's stacks. + * + * `captureStackTrace` removes this function and everything above it, but the + * caller is the tracker's own `init` hook, which sits just below it and would + * otherwise show up as the top frame. We drop that one frame by position rather + * than by filename, since after bundling every frame shares the same file name. */ function captureCreationStack(): SourceFrame[] { const carrier: { stack?: SourceFrame[] } = {}; @@ -227,23 +226,20 @@ function captureCreationStack(): SourceFrame[] { }); try { Error.captureStackTrace(carrier, captureCreationStack); - return carrier.stack ?? []; + // Drop the `init` hook frame (always the top one) so reports point at the + // application code that created the resource, not at this tracker. + return carrier.stack?.slice(1) ?? []; } finally { Error.prepareStackTrace = previous; } } /** - * Keep only frames the user can act on: drop Node internals and our own module. + * Keep only frames the user can act on by dropping Node internals. Our own + * `init` frame is already removed at capture time (see captureCreationStack). */ function actionableFrames(frames: SourceFrame[]): SourceFrame[] { - return frames.filter((frame) => { - if (!frame.file || frame.file.startsWith('node:')) { - return false; - } - // basename so the match holds regardless of path separator (e.g. Windows). - return !basename(frame.file).startsWith(`${SELF_MODULE}.`); - }); + return frames.filter((frame) => frame.file && !frame.file.startsWith('node:')); } function describeLocation(frame: SourceFrame): string { From cdd319ad817b361959bc28a68f03429a08c43e13 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Mon, 22 Jun 2026 19:02:32 -0400 Subject: [PATCH 05/12] chore: midwork --- packages/aws-cdk/lib/cli/debug-handles.ts | 2 +- packages/aws-cdk/test/cli/debug-handles.test.ts | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index f8b0e18ec..20a2ab860 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -165,7 +165,7 @@ class LeakedHandleTracker { }); this.watched.clear(); - await ioHelper.defaults.info(`${leaks.length} handle(s) still keeping the CLI process alive:`); + await ioHelper.defaults.info(`${leaks.length} ${leaks.length === 1 ? 'handle' : 'handles'} still keeping the CLI process alive:`); for (const leak of leaks) { await this.describe(leak, ioHelper); } diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index 282c026bf..bbcb5629e 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -31,7 +31,7 @@ test('reports a leaked timer with its type, plain-language description, and crea clearInterval(leaked); const lines = reportedLines(); - expect(lines[0]).toMatch(/^\d+ handle\(s\) still keeping the CLI process alive:$/); + expect(lines[0]).toMatch(/^\d+ handles? still keeping the CLI process alive:$/); // The type heading is emitted via chalk.bold, so match it the same way to stay // independent of whether color is active in the test environment. expect(lines).toContainEqual(chalk.bold('# Timeout (timer from setTimeout or setInterval)')); @@ -71,7 +71,7 @@ test('excludes handles that have been unref()ed', async () => { await reportLeakedHandles(ioHost.asHelper()); clearInterval(unrefed); - expect(reportedLines()).toEqual(['0 handle(s) still keeping the CLI process alive:']); + expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); }); test('reports zero handles on a clean exit with nothing left open', async () => { @@ -81,7 +81,7 @@ test('reports zero handles on a clean exit with nothing left open', async () => // loop open: the report is just the header with a count of zero. await reportLeakedHandles(ioHost.asHelper()); - expect(reportedLines()).toEqual(['0 handle(s) still keeping the CLI process alive:']); + expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); }); test('does not report promises, which are filtered as noise', async () => { From 1013a6e773ada5a808d8e6a31d8e30c1e2d12c1b Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Tue, 23 Jun 2026 18:20:34 -0400 Subject: [PATCH 06/12] chore: midwork --- packages/aws-cdk/lib/cli/debug-handles.ts | 11 ++++++++--- packages/aws-cdk/test/cli/debug-handles.test.ts | 7 ++++--- 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index 20a2ab860..ebb21a874 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -85,10 +85,12 @@ const TYPE_DESCRIPTIONS: Readonly> = { }; /** - * A single location in a stack trace: the file a frame points to and the line - * within it. + * A single location in a stack trace: the function name plus the file and line + * it points to. The function name matters in the shipped CLI, where everything + * is bundled into one file, so the file:line alone can't tell two frames apart. */ interface SourceFrame { + readonly func: string; readonly file: string; readonly line: number; } @@ -220,6 +222,7 @@ function captureCreationStack(): SourceFrame[] { Error.prepareStackTrace = (_error, callSites) => callSites.map((site) => { const file = site.getFileName() ?? ''; return { + func: site.getFunctionName() ?? '', file: file.startsWith('file://') ? fileURLToPath(file) : file, line: site.getLineNumber() ?? 0, }; @@ -246,7 +249,9 @@ function describeLocation(frame: SourceFrame): string { const fromCwd = relative(process.cwd(), frame.file); // A leading '..' means the file is outside cwd, where the absolute path reads better. const shown = fromCwd.startsWith('..') ? frame.file : fromCwd; - return `${shown}:${frame.line}`; + // Lead with the function name: in the bundled CLI every frame shares one file, + // so the name is what tells two frames apart. + return `${frame.func} (${shown}:${frame.line})`; } function sourceAt(frame: SourceFrame): string | undefined { diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index bbcb5629e..f35862d56 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -35,9 +35,10 @@ test('reports a leaked timer with its type, plain-language description, and crea // The type heading is emitted via chalk.bold, so match it the same way to stay // independent of whether color is active in the test environment. expect(lines).toContainEqual(chalk.bold('# Timeout (timer from setTimeout or setInterval)')); - // A creation site is reported as `file:line`. Which frame ends up on top of the - // stack depends on the async call path, so we assert the shape, not the file. - expect(lines.some((l) => /^ {2}created at .+:\d+$/.test(l))).toBe(true); + // A creation site is reported as `func (file:line)`. Which frame ends up on + // top of the stack depends on the async call path, so we assert the shape, + // not the specific function or file. + expect(lines.some((l) => /^ {2}created at .+ \(.+:\d+\)$/.test(l))).toBe(true); }); test('reports a leaked TCP connection as an open network connection', async () => { From 66dbfbbdf4143a40f906832d08d8c7c0ec96b075 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Tue, 23 Jun 2026 19:56:49 -0400 Subject: [PATCH 07/12] chore: midwork --- packages/aws-cdk/lib/cli/debug-handles.ts | 18 +++++------------- .../aws-cdk/test/cli/debug-handles.test.ts | 6 +++--- 2 files changed, 8 insertions(+), 16 deletions(-) diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index ebb21a874..e3210cb12 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -1,6 +1,5 @@ import { createHook } from 'node:async_hooks'; import { readFileSync } from 'node:fs'; -import { relative } from 'node:path'; import { fileURLToPath } from 'node:url'; import * as chalk from 'chalk'; import type { IoHelper } from '../../lib/api-private'; @@ -187,15 +186,17 @@ class LeakedHandleTracker { } // The first frame is where the handle was created; the rest is the call - // path that led there. + // path that led there. We show the function name and the line of code, not + // the file: the shipped CLI is bundled into a single file, so the file name + // is always the same and tells the reader nothing. const [origin, ...callers] = frames; - await ioHelper.defaults.info(` created at ${describeLocation(origin)}`); + await ioHelper.defaults.info(` created in ${origin.func}()`); const source = sourceAt(origin); if (source) { await ioHelper.defaults.info(` ${source}`); } for (const caller of callers) { - await ioHelper.defaults.info(` called from ${describeLocation(caller)}`); + await ioHelper.defaults.info(` called from ${caller.func}()`); } } } @@ -245,15 +246,6 @@ function actionableFrames(frames: SourceFrame[]): SourceFrame[] { return frames.filter((frame) => frame.file && !frame.file.startsWith('node:')); } -function describeLocation(frame: SourceFrame): string { - const fromCwd = relative(process.cwd(), frame.file); - // A leading '..' means the file is outside cwd, where the absolute path reads better. - const shown = fromCwd.startsWith('..') ? frame.file : fromCwd; - // Lead with the function name: in the bundled CLI every frame shares one file, - // so the name is what tells two frames apart. - return `${frame.func} (${shown}:${frame.line})`; -} - function sourceAt(frame: SourceFrame): string | undefined { try { const line = readFileSync(frame.file, 'utf-8').split(/\r?\n/)[frame.line - 1]?.trim() || undefined; diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index f35862d56..9e36ef9c0 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -35,10 +35,10 @@ test('reports a leaked timer with its type, plain-language description, and crea // The type heading is emitted via chalk.bold, so match it the same way to stay // independent of whether color is active in the test environment. expect(lines).toContainEqual(chalk.bold('# Timeout (timer from setTimeout or setInterval)')); - // A creation site is reported as `func (file:line)`. Which frame ends up on + // A creation site is reported as `created in ()`. Which frame ends up on // top of the stack depends on the async call path, so we assert the shape, - // not the specific function or file. - expect(lines.some((l) => /^ {2}created at .+ \(.+:\d+\)$/.test(l))).toBe(true); + // not the specific function. + expect(lines.some((l) => /^ {2}created in .+\(\)$/.test(l))).toBe(true); }); test('reports a leaked TCP connection as an open network connection', async () => { From 7e6f7947c67e64815ecf1fb67bb1068ca921c27f Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Tue, 23 Jun 2026 21:22:56 -0400 Subject: [PATCH 08/12] chore: midwork --- packages/aws-cdk/lib/cli/debug-handles.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index e3210cb12..bd81fde74 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -193,7 +193,8 @@ class LeakedHandleTracker { await ioHelper.defaults.info(` created in ${origin.func}()`); const source = sourceAt(origin); if (source) { - await ioHelper.defaults.info(` ${source}`); + // Dim it so it reads as secondary detail under the frame. + await ioHelper.defaults.info(` ${chalk.dim(source)}`); } for (const caller of callers) { await ioHelper.defaults.info(` called from ${caller.func}()`); From fcd2d18c183a9ed09aaf8cd31cb4e3efd493a826 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Wed, 24 Jun 2026 00:13:46 -0400 Subject: [PATCH 09/12] chore: midwork --- packages/aws-cdk/lib/cli/debug-handles.ts | 24 +++++++++---------- .../aws-cdk/test/cli/debug-handles.test.ts | 7 +++--- 2 files changed, 15 insertions(+), 16 deletions(-) diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index bd81fde74..2105f94a5 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -185,19 +185,19 @@ class LeakedHandleTracker { return; } - // The first frame is where the handle was created; the rest is the call - // path that led there. We show the function name and the line of code, not - // the file: the shipped CLI is bundled into a single file, so the file name - // is always the same and tells the reader nothing. - const [origin, ...callers] = frames; - await ioHelper.defaults.info(` created in ${origin.func}()`); - const source = sourceAt(origin); - if (source) { - // Dim it so it reads as secondary detail under the frame. - await ioHelper.defaults.info(` ${chalk.dim(source)}`); + // Headline the function only when it has a real name; sockets often open + // from anonymous internal callbacks where the name says nothing. + const [origin] = frames; + if (origin.func && origin.func !== '') { + await ioHelper.defaults.info(` created in ${origin.func}()`); } - for (const caller of callers) { - await ioHelper.defaults.info(` called from ${caller.func}()`); + + await ioHelper.defaults.info(' call stack:'); + for (const frame of frames) { + const source = sourceAt(frame); + if (source) { + await ioHelper.defaults.info(` ${chalk.dim(source)}`); + } } } } diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index 9e36ef9c0..265606663 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -35,10 +35,9 @@ test('reports a leaked timer with its type, plain-language description, and crea // The type heading is emitted via chalk.bold, so match it the same way to stay // independent of whether color is active in the test environment. expect(lines).toContainEqual(chalk.bold('# Timeout (timer from setTimeout or setInterval)')); - // A creation site is reported as `created in ()`. Which frame ends up on - // top of the stack depends on the async call path, so we assert the shape, - // not the specific function. - expect(lines.some((l) => /^ {2}created in .+\(\)$/.test(l))).toBe(true); + // The report shows a call stack with the line of code that created the handle. + expect(lines).toContain(' call stack:'); + expect(lines.some((l) => l.includes('setInterval'))).toBe(true); }); test('reports a leaked TCP connection as an open network connection', async () => { From 0e259af8abed8a7bae757dfbb0acf671c34c293c Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Wed, 24 Jun 2026 00:34:45 -0400 Subject: [PATCH 10/12] chore: midwork --- packages/aws-cdk/lib/cli/debug-handles.ts | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index 2105f94a5..4b54ed9dc 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -84,9 +84,9 @@ const TYPE_DESCRIPTIONS: Readonly> = { }; /** - * A single location in a stack trace: the function name plus the file and line - * it points to. The function name matters in the shipped CLI, where everything - * is bundled into one file, so the file:line alone can't tell two frames apart. + * A single stack frame: the function name (used for the report heading), plus + * the file and line, which we read to show the line of code that created the + * handle. */ interface SourceFrame { readonly func: string; @@ -250,9 +250,8 @@ function actionableFrames(frames: SourceFrame[]): SourceFrame[] { function sourceAt(frame: SourceFrame): string | undefined { try { const line = readFileSync(frame.file, 'utf-8').split(/\r?\n/)[frame.line - 1]?.trim() || undefined; - // The shipped CLI is one bundled file where a few lines are huge minified - // blobs (one is ~600k chars). Truncate so a creation site on such a line - // doesn't dump the whole blob; the location alone is still useful. + // Truncate so an unexpectedly long line (e.g. a generated or packed file) + // doesn't flood the report. return line && line.length > 200 ? `${line.slice(0, 200)}…` : line; } catch { // The source file may not be readable (e.g. a bundled or eval'd frame). From b723fb33b4cd43f43539dd56a77cc841a5215ca5 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Thu, 10 Sep 2026 10:26:30 -0400 Subject: [PATCH 11/12] chore:midwork --- packages/aws-cdk/lib/cli/cli.ts | 33 ++-- packages/aws-cdk/lib/cli/debug-handles.ts | 74 +++++---- .../aws-cdk/test/cli/debug-handles.test.ts | 146 ++++++++++++++++-- 3 files changed, 187 insertions(+), 66 deletions(-) diff --git a/packages/aws-cdk/lib/cli/cli.ts b/packages/aws-cdk/lib/cli/cli.ts index 61cf307e5..1d008d0c0 100644 --- a/packages/aws-cdk/lib/cli/cli.ts +++ b/packages/aws-cdk/lib/cli/cli.ts @@ -6,7 +6,7 @@ import * as chalk from 'chalk'; import { guessLanguage } from '../util'; import { CdkToolkit, AssetBuildTime } from './cdk-toolkit'; import { ciSystemIsStdErrSafe } from './ci-systems'; -import { enableHandleTracking, reportLeakedHandles } from './debug-handles'; +import { trackLeakedHandles } from './debug-handles'; import { displayVersionMessage, shouldDisplayVersionMessage } from './display-version'; import type { IoMessageLevel } from './io-host'; import { CliIoHost } from './io-host'; @@ -43,10 +43,6 @@ import { findUnknownOptions } from './util/check-unknown-options'; import { isCI } from './util/ci'; import { guessAgent } from './util/guess-agent'; -// Grace period before the --debug-cli handle dump fires. unref'd, so it never -// fires when Node exits cleanly within this window. -const HANDLE_DUMP_GRACE_MS = 1000; - export async function exec(args: string[], synthesizer?: Synthesizer): Promise { // This is the very first code that runs, but libraries have been loaded already and that also costs time. // Measure that. @@ -54,11 +50,9 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise notices.display()); } - if (argv.debugCli) { - // If the process is still alive after the grace period, something is - // keeping the event loop busy. Dump the leaked handles so the user can - // see why. .unref() so this timer itself doesn't keep us alive. - setTimeout(() => { - void reportLeakedHandles(ioHelper); - }, HANDLE_DUMP_GRACE_MS).unref(); - } + // If the process is still alive after the grace period, something is keeping + // the event loop busy. Dump the leaked handles so the user can see why. + handleTracker?.scheduleReport(ioHelper); } async function main(command: string, args: any): Promise { diff --git a/packages/aws-cdk/lib/cli/debug-handles.ts b/packages/aws-cdk/lib/cli/debug-handles.ts index 4b54ed9dc..f6541b2f2 100644 --- a/packages/aws-cdk/lib/cli/debug-handles.ts +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -104,13 +104,20 @@ interface WatchedResource { readonly creationStack: SourceFrame[]; } +/** + * Grace period before the handle report fires. The timer is unref'd, so it + * never fires when Node exits cleanly within this window. + */ +const HANDLE_DUMP_GRACE_MS = 1000; + /** * Tracks async resources via async_hooks and, on demand, reports the ones still * keeping the event loop alive together with where they were created. * - * The cost lands only when opted in: tracking is off until `start()` is called. + * The cost lands only when opted in: nothing is tracked until `start()` is + * called, which `trackLeakedHandles()` does. */ -class LeakedHandleTracker { +export class LeakedHandleTracker { private readonly watched = new Map(); private readonly hook = createHook({ @@ -134,26 +141,36 @@ class LeakedHandleTracker { * are created, and only when the user opted in — the hook adds a small * per-resource cost. */ - public start = (): void => { + public start(): void { this.hook.enable(); - }; + } /** * Stop watching and discard all tracked state. - * - * @internal exposed only so tests can isolate the shared singleton. */ - public reset = (): void => { + public stop(): void { this.hook.disable(); this.watched.clear(); - }; + } + + /** + * Report the leaked handles once the grace period has passed, which is the + * only way this report should ever be triggered: if the process exits cleanly + * within the window the timer never fires, and because it is unref'd it does + * not hold the process open itself. + */ + public scheduleReport(ioHelper: IoHelper): void { + setTimeout(() => { + void this.report(ioHelper); + }, HANDLE_DUMP_GRACE_MS).unref(); + } /** * Report every resource still holding the event loop open, each with the * source location where it was created. Call at the very end of execution, by * which point only genuinely leaked handles should remain. */ - public report = async (ioHelper: IoHelper): Promise => { + public async report(ioHelper: IoHelper): Promise { this.hook.disable(); const leaks = [...this.watched.values()].filter((r) => { @@ -166,22 +183,22 @@ class LeakedHandleTracker { }); this.watched.clear(); - await ioHelper.defaults.info(`${leaks.length} ${leaks.length === 1 ? 'handle' : 'handles'} still keeping the CLI process alive:`); + await ioHelper.defaults.debug(`${leaks.length} ${leaks.length === 1 ? 'handle' : 'handles'} still keeping the CLI process alive:`); for (const leak of leaks) { await this.describe(leak, ioHelper); } - }; + } private async describe(leak: WatchedResource, ioHelper: IoHelper): Promise { const frames = actionableFrames(leak.creationStack); - await ioHelper.defaults.info(''); + await ioHelper.defaults.debug(''); const description = TYPE_DESCRIPTIONS[leak.type]; const heading = description ? `# ${leak.type} (${description})` : `# ${leak.type}`; - await ioHelper.defaults.info(chalk.bold(heading)); + await ioHelper.defaults.debug(chalk.bold(heading)); if (frames.length === 0) { - await ioHelper.defaults.info(' (no application stack frames)'); + await ioHelper.defaults.debug(' (no application stack frames)'); return; } @@ -189,14 +206,14 @@ class LeakedHandleTracker { // from anonymous internal callbacks where the name says nothing. const [origin] = frames; if (origin.func && origin.func !== '') { - await ioHelper.defaults.info(` created in ${origin.func}()`); + await ioHelper.defaults.debug(` created in ${origin.func}()`); } - await ioHelper.defaults.info(' call stack:'); + await ioHelper.defaults.debug(' call stack:'); for (const frame of frames) { const source = sourceAt(frame); if (source) { - await ioHelper.defaults.info(` ${chalk.dim(source)}`); + await ioHelper.defaults.debug(` ${chalk.dim(source)}`); } } } @@ -260,21 +277,14 @@ function sourceAt(frame: SourceFrame): string | undefined { } } -const tracker = new LeakedHandleTracker(); - -/** - * Start tracking async resources. See {@link LeakedHandleTracker.start}. - */ -export const enableHandleTracking = tracker.start; - /** - * Report handles still keeping the loop alive. See {@link LeakedHandleTracker.report}. - */ -export const reportLeakedHandles = tracker.report; - -/** - * Stop tracking and discard all state. + * Start watching async resources and return the tracker doing so. * - * @internal exposed only so tests can isolate the shared singleton. + * Call this as early as possible, and only when the user asked for it: the + * tracker can only report on resources created after it starts. */ -export const resetHandleTracking = tracker.reset; +export function trackLeakedHandles(): LeakedHandleTracker { + const tracker = new LeakedHandleTracker(); + tracker.start(); + return tracker; +} diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index 265606663..2b45c28e3 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -2,19 +2,22 @@ import { once } from 'node:events'; import * as net from 'node:net'; import { setTimeout as delay } from 'node:timers/promises'; import * as chalk from 'chalk'; -import { enableHandleTracking, reportLeakedHandles, resetHandleTracking } from '../../lib/cli/debug-handles'; -import { TestIoHost } from '../_helpers/io-host'; +import type { LeakedHandleTracker } from '../../lib/cli/debug-handles'; +import { trackLeakedHandles } from '../../lib/cli/debug-handles'; +import { TestIoHost, expectIoMsg } from '../_helpers/io-host'; let ioHost: TestIoHost; +let tracker: LeakedHandleTracker; beforeEach(() => { - // The tracker is a module singleton; reset it so each test starts clean. - resetHandleTracking(); - ioHost = new TestIoHost(); + // The report is emitted at debug level, which the host filters out at its + // default of 'info'. + ioHost = new TestIoHost('debug'); }); afterEach(() => { - resetHandleTracking(); + // Leave no hook enabled behind, even if the test failed before reporting. + tracker?.stop(); }); // The text of every message the report emitted, in order. @@ -22,12 +25,41 @@ function reportedLines(): string[] { return ioHost.notifySpy.mock.calls.map((call) => call[0].message as string); } +/** + * Put a resource into the tracker's watch list directly. + * + * Some report branches cannot be reached by creating real handles: the resource + * types are Node internals we can't conjure, or the state (a garbage collected + * handle, an unreadable source file) can't be forced from a test. + */ +function injectWatched(into: LeakedHandleTracker, resource: { + type: string; + deref?: () => { hasRef?(): boolean } | undefined; + creationStack?: Array<{ func: string; file: string; line: number }>; +}): void { + const internals = into as unknown as { watched: Map }; + internals.watched.set(-1 - internals.watched.size, { + type: resource.type, + handleRef: { deref: resource.deref ?? (() => ({ hasRef: () => true })) }, + creationStack: resource.creationStack ?? [], + }); +} + +// Let an already-started async report run to completion. The report awaits once +// per line emitted, and `scheduleReport` discards the promise, so there is +// nothing to await directly. +async function drainMicrotasks(): Promise { + for (let i = 0; i < 100; i++) { + await Promise.resolve(); + } +} + test('reports a leaked timer with its type, plain-language description, and creation site', async () => { - enableHandleTracking(); + tracker = trackLeakedHandles(); const leaked = setInterval(() => { }, 60_000); - await reportLeakedHandles(ioHost.asHelper()); + await tracker.report(ioHost.asHelper()); clearInterval(leaked); const lines = reportedLines(); @@ -47,11 +79,11 @@ test('reports a leaked TCP connection as an open network connection', async () = // Tracking must start before the connection is created, otherwise the socket // is never seen. This mirrors how the flag is enabled at CLI startup. - enableHandleTracking(); + tracker = trackLeakedHandles(); const client = net.connect(port, '127.0.0.1'); try { await once(client, 'connect'); - await reportLeakedHandles(ioHost.asHelper()); + await tracker.report(ioHost.asHelper()); expect(reportedLines().some((l) => l.includes('(open network connection)'))).toBe(true); } finally { @@ -62,36 +94,118 @@ test('reports a leaked TCP connection as an open network connection', async () = }); test('excludes handles that have been unref()ed', async () => { - enableHandleTracking(); + tracker = trackLeakedHandles(); // unref() means the handle is not keeping the loop alive, so it must be excluded. const unrefed = setInterval(() => { }, 60_000); unrefed.unref(); - await reportLeakedHandles(ioHost.asHelper()); + await tracker.report(ioHost.asHelper()); clearInterval(unrefed); expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); }); test('reports zero handles on a clean exit with nothing left open', async () => { - enableHandleTracking(); + tracker = trackLeakedHandles(); // Nothing is created after tracking starts, so nothing should be holding the // loop open: the report is just the header with a count of zero. - await reportLeakedHandles(ioHost.asHelper()); + await tracker.report(ioHost.asHelper()); expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); }); test('does not report promises, which are filtered as noise', async () => { - enableHandleTracking(); + tracker = trackLeakedHandles(); // Every await creates promises; none of them should show up in the report. for (let i = 0; i < 50; i++) { await delay(1); } - await reportLeakedHandles(ioHost.asHelper()); + await tracker.report(ioHost.asHelper()); expect(reportedLines().some((l) => l.includes('PROMISE'))).toBe(false); }); + +test('emits the report at debug level, not info', async () => { + tracker = trackLeakedHandles(); + + await tracker.report(ioHost.asHelper()); + + // The whole report is debug output. Emitting at info would print it during + // ordinary runs of any command that happens to leave a handle open. + expect(ioHost.notifySpy).toHaveBeenCalledWith(expectIoMsg(expect.any(String), 'debug')); + expect(ioHost.notifySpy).not.toHaveBeenCalledWith(expectIoMsg(expect.any(String), 'info')); +}); + +test('reports nothing until tracking is started', async () => { + // Importing the module must not enable the hook: a resource created before + // trackLeakedHandles() runs is invisible to the tracker. + const before = setInterval(() => { + }, 60_000); + tracker = trackLeakedHandles(); + await tracker.report(ioHost.asHelper()); + clearInterval(before); + + expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); +}); + +test('describes an unknown resource type without a description', async () => { + tracker = trackLeakedHandles(); + + // Node's set of async resource types grows over time. An unrecognised type + // must still be reported, just without the plain-language explanation. + injectWatched(tracker, { type: 'SOMETHINGNEW' }); + await tracker.report(ioHost.asHelper()); + + const lines = reportedLines(); + expect(lines).toContainEqual(chalk.bold('# SOMETHINGNEW')); + expect(lines).toContain(' (no application stack frames)'); +}); + +test('excludes handles that have already been garbage collected', async () => { + tracker = trackLeakedHandles(); + + // We hold handles weakly so tracking doesn't keep them alive. A collected + // handle is by definition no longer keeping the loop open. + injectWatched(tracker, { type: 'TCPWRAP', deref: () => undefined }); + await tracker.report(ioHost.asHelper()); + + expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); +}); + +test('still reports a handle whose source file cannot be read', async () => { + tracker = trackLeakedHandles(); + + // Bundled and eval'd frames have file names that don't exist on disk. The + // location is worth reporting even when we can't show the line of code. + injectWatched(tracker, { + type: 'TCPWRAP', + creationStack: [{ func: 'openSocket', file: '/does/not/exist.ts', line: 1 }], + }); + await tracker.report(ioHost.asHelper()); + + const lines = reportedLines(); + expect(lines).toContain(' created in openSocket()'); + expect(lines).toContain(' call stack:'); +}); + +test('scheduleReport stays silent until the grace period has passed', async () => { + jest.useFakeTimers(); + try { + tracker = trackLeakedHandles(); + tracker.scheduleReport(ioHost.asHelper()); + + // A CLI that exits within the grace period must print nothing at all. + await drainMicrotasks(); + expect(ioHost.notifySpy).not.toHaveBeenCalled(); + + jest.advanceTimersByTime(1000); + await drainMicrotasks(); + + expect(reportedLines()[0]).toMatch(/still keeping the CLI process alive:$/); + } finally { + jest.useRealTimers(); + } +}); From 2db3ebc0fd225c031cf9acae6eb86b52e5ba5a13 Mon Sep 17 00:00:00 2001 From: Sai Ray Date: Thu, 10 Sep 2026 12:41:25 -0400 Subject: [PATCH 12/12] chore: mid work --- packages/aws-cdk/lib/cli/cli.ts | 13 +- packages/aws-cdk/lib/cli/debug-handles.ts | 189 +++++++++++------- .../aws-cdk/test/cli/debug-handles.test.ts | 105 +++++++--- 3 files changed, 195 insertions(+), 112 deletions(-) diff --git a/packages/aws-cdk/lib/cli/cli.ts b/packages/aws-cdk/lib/cli/cli.ts index 1d008d0c0..517ab2892 100644 --- a/packages/aws-cdk/lib/cli/cli.ts +++ b/packages/aws-cdk/lib/cli/cli.ts @@ -84,12 +84,13 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise(value: T) => { deref(): T | und const WeakRefImpl = (globalThis as unknown as { WeakRef: WeakRefConstructor }).WeakRef; /** - * async_hooks resource types that are noise in a "why won't the process exit" - * report: created in large numbers and effectively never the handle a user can - * act on. - */ -const SKIP_TYPES: ReadonlySet = new Set([ - 'PROMISE', - 'PerformanceObserver', - 'RANDOMBYTESREQUEST', -]); - -/** - * Plain-language descriptions for Node's async resource types (the fixed set in - * V8/libuv's async_wrap providers). The raw type is always shown; a description - * is appended when we have one, so any future/unknown type still reports - * truthfully. + * The async resource types we track, mapped to a plain-language description. + * + * This is an allowlist of libuv *handles* — the things that can actually hold + * the event loop open — and it deliberately excludes *requests* (a pending DNS + * lookup, a stream write) and bookkeeping resources. Two reasons: + * + * - Requests are transient. By the time the report runs they have completed, so + * tracking them costs a stack capture per resource and reports nothing. + * - The volume is the cost. `PROMISE` and `TickObject` alone are created tens of + * thousands of times in a single synth, and a stack capture is ~60x the cost + * of the bookkeeping around it. + * + * The trade-off of an allowlist is that a handle type we don't know about is + * invisible. That is the right way round for this tool: a missed exotic handle + * costs one unexplained hang, whereas tracking everything makes the flag too + * slow to leave on and buries the real leak in noise. + * + * Before adding a type, check that it can actually hold the loop open. Only the + * `HandleWrap`-backed types expose `hasRef()`, so anything else is reported + * unconditionally — which is right for `TLSWRAP` and `HTTP2SESSION`, whose whole + * job is to sit on a socket that does hold the loop, and wrong for e.g. + * `FILEHANDLE` or `DNSCHANNEL`, which never hold it and so only add noise. */ -const TYPE_DESCRIPTIONS: Readonly> = { +const TRACKED_TYPES: Readonly> = { TCPWRAP: 'open network connection', TCPSERVERWRAP: 'listening TCP server', - TCPSOCKETWRAP: 'open network connection', - TCPCONNECTWRAP: 'pending outbound TCP connection', + TLSWRAP: 'open TLS connection', PIPEWRAP: 'open pipe', PIPESERVERWRAP: 'listening pipe server', - PIPECONNECTWRAP: 'pending pipe connection', UDPWRAP: 'open UDP socket', - UDPSENDWRAP: 'pending UDP send', - TLSWRAP: 'open TLS connection', TTYWRAP: 'open terminal stream', - TIMERWRAP: 'internal timer holding the loop open', Timeout: 'timer from setTimeout or setInterval', Immediate: 'pending setImmediate callback', - FSREQCALLBACK: 'pending file-system operation', - FSREQPROMISE: 'pending file-system operation', + PROCESSWRAP: 'spawned child process still running', FSEVENTWRAP: 'file-system watcher', STATWATCHER: 'file-system stat watcher', - PROCESSWRAP: 'spawned child process still running', - ChildProcess: 'spawned child process still running', - GETADDRINFOREQWRAP: 'pending DNS lookup', - GETNAMEINFOREQWRAP: 'pending DNS reverse lookup', - QUERYWRAP: 'pending DNS query', - HTTPCLIENTREQUEST: 'in-flight HTTP request', - HTTPINCOMINGMESSAGE: 'incoming HTTP message', - HTTP2SESSION: 'open HTTP/2 connection', - HTTP2STREAM: 'open HTTP/2 request stream', - HTTP2PING: 'pending HTTP/2 ping', - HTTP2SETTINGS: 'pending HTTP/2 settings', - WRITEWRAP: 'pending stream write', - SHUTDOWNWRAP: 'pending stream shutdown', SIGNALWRAP: 'OS signal handler still registered', WORKER: 'worker thread still running', MESSAGEPORT: 'open worker-thread message channel', - ZLIB: 'open (de)compression stream', - DNSCHANNEL: 'DNS resolver holding sockets open', - ELDHISTOGRAM: 'event-loop-delay monitor (perf_hooks)', - FILEHANDLE: 'open file handle', - FILEHANDLECLOSEREQ: 'pending file-handle close', - HEAPSNAPSHOT: 'heap snapshot being written', - JSSTREAM: 'custom JavaScript-backed stream', - JSUDPWRAP: 'custom JavaScript-backed UDP socket', - KEYPAIRGENREQUEST: 'pending key-pair generation', - KEYGENREQUEST: 'pending key generation', - KEYEXPORTREQUEST: 'pending key export', - CIPHERREQUEST: 'pending cipher operation', - DERIVEBITSREQUEST: 'pending key-derivation', - HASHREQUEST: 'pending hash operation', - SIGNREQUEST: 'pending sign operation', - VERIFYREQUEST: 'pending verify operation', - HTTPPARSER: 'HTTP parser for an open connection', - INSPECTORJSBINDING: 'debugger/inspector session attached', - SCRYPTREQUEST: 'pending scrypt operation', - PBKDF2REQUEST: 'pending PBKDF2 operation', + HTTP2SESSION: 'open HTTP/2 connection', }; +/** + * How many stack frames to capture per resource. + * + * Node's default (`Error.stackTraceLimit`, 10) is far too shallow here: a socket + * opened by an HTTP agent sits behind ~9 frames of `node:internal/async_hooks`, + * `node:net`, `node:_http_agent` and `node:tls` before any CLI code appears, so + * every frame gets filtered as an internal and the report has nothing to show. + */ +const STACK_CAPTURE_DEPTH = 60; + /** * A single stack frame: the function name (used for the report heading), plus * the file and line, which we read to show the line of code that created the @@ -122,14 +101,23 @@ export class LeakedHandleTracker { private readonly hook = createHook({ init: (asyncId, type, _triggerAsyncId, resource) => { - if (SKIP_TYPES.has(type)) { + if (!(type in TRACKED_TYPES)) { return; } - this.watched.set(asyncId, { - type, - handleRef: new WeakRefImpl(resource as { hasRef?(): boolean }), - creationStack: captureCreationStack(), - }); + // An exception thrown from an async_hooks callback is not catchable by the + // application: Node prints "Error in AsyncHook callback" and aborts the + // process. A diagnostic must never be able to kill the process it is + // observing, so anything that goes wrong here costs us one handle's + // provenance and nothing more. + try { + this.watched.set(asyncId, { + type, + handleRef: new WeakRefImpl(resource as { hasRef?(): boolean }), + creationStack: captureCreationStack(), + }); + } catch { + this.watched.delete(asyncId); + } }, destroy: (asyncId) => { this.watched.delete(asyncId); @@ -169,6 +157,10 @@ export class LeakedHandleTracker { * Report every resource still holding the event loop open, each with the * source location where it was created. Call at the very end of execution, by * which point only genuinely leaked handles should remain. + * + * Emitted at DEBUG, not INFO: this is debugging detail, and nothing reaches + * here unless the user passed `--debug-cli`, which raises the CLI log level to + * DEBUG for exactly this reason. */ public async report(ioHelper: IoHelper): Promise { this.hook.disable(); @@ -179,26 +171,41 @@ export class LeakedHandleTracker { if (handle === undefined) { return false; } + // Only HandleWrap-backed types can tell us whether they are holding the + // loop. The rest (TLSWRAP, HTTP2SESSION) are reported unverified — they sit + // on a socket that does hold it, and TLSWRAP is the leak behind #1217, so + // dropping the unverifiable ones would hide the case this flag exists for. return handle.hasRef?.() ?? true; }); this.watched.clear(); + if (leaks.length === 0) { + // This report only runs because the process was still alive after the + // grace period, so something *is* holding the loop open. Finding nothing + // means the leak is outside what we track, not that there is no leak. + await ioHelper.defaults.debug('The CLI process is still alive, but no tracked handle explains it.'); + await ioHelper.defaults.debug('The cause may be a handle opened before tracking started, or a type this build does not track.'); + return; + } + await ioHelper.defaults.debug(`${leaks.length} ${leaks.length === 1 ? 'handle' : 'handles'} still keeping the CLI process alive:`); + + // One report pass can revisit the same file for every frame of every handle. + // In a bundled CLI that file is tens of megabytes, so read each one once. + const sources = new SourceCache(); for (const leak of leaks) { - await this.describe(leak, ioHelper); + await this.describe(leak, ioHelper, sources); } } - private async describe(leak: WatchedResource, ioHelper: IoHelper): Promise { + private async describe(leak: WatchedResource, ioHelper: IoHelper, sources: SourceCache): Promise { const frames = actionableFrames(leak.creationStack); await ioHelper.defaults.debug(''); - const description = TYPE_DESCRIPTIONS[leak.type]; - const heading = description ? `# ${leak.type} (${description})` : `# ${leak.type}`; - await ioHelper.defaults.debug(chalk.bold(heading)); + await ioHelper.defaults.debug(chalk.bold(`# ${leak.type} (${TRACKED_TYPES[leak.type]})`)); if (frames.length === 0) { - await ioHelper.defaults.debug(' (no application stack frames)'); + await ioHelper.defaults.debug(' (opened entirely inside Node internals, no CLI frames to show)'); return; } @@ -211,9 +218,12 @@ export class LeakedHandleTracker { await ioHelper.defaults.debug(' call stack:'); for (const frame of frames) { - const source = sourceAt(frame); + // Always print the location. It is the part that identifies the frame, so + // a frame whose file we cannot read must still appear. + await ioHelper.defaults.debug(` ${frame.func} (${frame.file}:${frame.line})`); + const source = sources.lineAt(frame); if (source) { - await ioHelper.defaults.debug(` ${chalk.dim(source)}`); + await ioHelper.defaults.debug(` ${chalk.dim(source)}`); } } } @@ -238,6 +248,8 @@ function captureCreationStack(): SourceFrame[] { // method we invoke, so the unbound-method concern does not apply here. // eslint-disable-next-line @typescript-eslint/unbound-method const previous = Error.prepareStackTrace; + const previousLimit = Error.stackTraceLimit; + Error.stackTraceLimit = STACK_CAPTURE_DEPTH; Error.prepareStackTrace = (_error, callSites) => callSites.map((site) => { const file = site.getFileName() ?? ''; return { @@ -253,6 +265,7 @@ function captureCreationStack(): SourceFrame[] { return carrier.stack?.slice(1) ?? []; } finally { Error.prepareStackTrace = previous; + Error.stackTraceLimit = previousLimit; } } @@ -264,15 +277,39 @@ function actionableFrames(frames: SourceFrame[]): SourceFrame[] { return frames.filter((frame) => frame.file && !frame.file.startsWith('node:')); } -function sourceAt(frame: SourceFrame): string | undefined { - try { - const line = readFileSync(frame.file, 'utf-8').split(/\r?\n/)[frame.line - 1]?.trim() || undefined; +/** + * Reads the line of code behind a stack frame, holding each file's lines so a + * report pass reads any given file at most once. + * + * This matters more than it looks: the published CLI is a single bundle of over + * half a million lines, and a report can hold dozens of frames pointing into it. + * Re-reading and re-splitting per frame turns the report into a multi-second + * stall, at the exact moment the user is already waiting on a hung CLI. + */ +class SourceCache { + private readonly files = new Map(); + + public lineAt(frame: SourceFrame): string | undefined { + const line = this.linesOf(frame.file)?.[frame.line - 1]?.trim() || undefined; // Truncate so an unexpectedly long line (e.g. a generated or packed file) // doesn't flood the report. return line && line.length > 200 ? `${line.slice(0, 200)}…` : line; + } + + private linesOf(file: string): string[] | undefined { + if (!this.files.has(file)) { + this.files.set(file, readLines(file)); + } + return this.files.get(file); + } +} + +function readLines(file: string): string[] | undefined { + try { + return readFileSync(file, 'utf-8').split(/\r?\n/); } catch { - // The source file may not be readable (e.g. a bundled or eval'd frame). - // The location is still useful on its own, so reporting continues without it. + // The source file may not be readable (e.g. a bundled or eval'd frame). The + // location is still reported on its own, so reporting continues without it. return undefined; } } diff --git a/packages/aws-cdk/test/cli/debug-handles.test.ts b/packages/aws-cdk/test/cli/debug-handles.test.ts index 2b45c28e3..adde15c4f 100644 --- a/packages/aws-cdk/test/cli/debug-handles.test.ts +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -6,12 +6,20 @@ import type { LeakedHandleTracker } from '../../lib/cli/debug-handles'; import { trackLeakedHandles } from '../../lib/cli/debug-handles'; import { TestIoHost, expectIoMsg } from '../_helpers/io-host'; +// What the report prints when it finds nothing. It still says something: the +// report only runs because the process was alive, so "no leaks" means the cause +// is outside what we track. +const NOTHING_FOUND = [ + 'The CLI process is still alive, but no tracked handle explains it.', + 'The cause may be a handle opened before tracking started, or a type this build does not track.', +]; + let ioHost: TestIoHost; let tracker: LeakedHandleTracker; beforeEach(() => { - // The report is emitted at debug level, which the host filters out at its - // default of 'info'. + // The report is debug detail, which the host filters out at its default of + // 'info'. In the real CLI `--debug-cli` raises the level to match. ioHost = new TestIoHost('debug'); }); @@ -28,9 +36,9 @@ function reportedLines(): string[] { /** * Put a resource into the tracker's watch list directly. * - * Some report branches cannot be reached by creating real handles: the resource - * types are Node internals we can't conjure, or the state (a garbage collected - * handle, an unreadable source file) can't be forced from a test. + * Some report branches cannot be reached by creating real handles: the state (a + * garbage collected handle, an unreadable source file) can't be forced from a + * test. */ function injectWatched(into: LeakedHandleTracker, resource: { type: string; @@ -93,6 +101,35 @@ test('reports a leaked TCP connection as an open network connection', async () = } }); +test('captures deep enough to reach application code behind Node internals', async () => { + const server = net.createServer(); + await once(server.listen(0), 'listening'); + const { port } = server.address() as net.AddressInfo; + + tracker = trackLeakedHandles(); + + // A socket is created ~9 frames deep inside node:net, node:_http_agent and + // node:tls before any application frame appears. At Node's default + // stackTraceLimit of 10 every captured frame is an internal one, so the report + // has nothing actionable to show. Nesting the call proves we capture past that. + const openDeep = (depth: number): net.Socket => + depth === 0 ? net.connect(port, '127.0.0.1') : openDeep(depth - 1); + const client = openDeep(12); + + try { + await once(client, 'connect'); + await tracker.report(ioHost.asHelper()); + + // All 13 nesting frames, so the capture reached well past the default of 10. + const ourFrames = reportedLines().filter((l) => l.includes('openDeep')); + expect(ourFrames.length).toBeGreaterThan(10); + } finally { + client.destroy(); + server.close(); + await once(server, 'close'); + } +}); + test('excludes handles that have been unref()ed', async () => { tracker = trackLeakedHandles(); @@ -103,38 +140,43 @@ test('excludes handles that have been unref()ed', async () => { await tracker.report(ioHost.asHelper()); clearInterval(unrefed); - expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); + expect(reportedLines()).toEqual(NOTHING_FOUND); }); -test('reports zero handles on a clean exit with nothing left open', async () => { +test('says so explicitly when no tracked handle explains the hang', async () => { tracker = trackLeakedHandles(); // Nothing is created after tracking starts, so nothing should be holding the - // loop open: the report is just the header with a count of zero. + // loop open. Printing nothing at all would read as a broken flag, so the report + // has to say that it looked and came up empty. await tracker.report(ioHost.asHelper()); - expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); + expect(reportedLines()).toEqual(NOTHING_FOUND); }); -test('does not report promises, which are filtered as noise', async () => { +test('does not report promises or tick objects, which are pure noise', async () => { tracker = trackLeakedHandles(); - // Every await creates promises; none of them should show up in the report. + // Every await creates promises and tick objects, tens of thousands of them in a + // real synth. Capturing a stack for each would dominate the flag's cost and + // bury the actual leak. for (let i = 0; i < 50; i++) { await delay(1); } await tracker.report(ioHost.asHelper()); - expect(reportedLines().some((l) => l.includes('PROMISE'))).toBe(false); + const lines = reportedLines(); + expect(lines.some((l) => l.includes('PROMISE'))).toBe(false); + expect(lines.some((l) => l.includes('TickObject'))).toBe(false); }); test('emits the report at debug level, not info', async () => { tracker = trackLeakedHandles(); + // The whole report is debug output. At info it would print during ordinary runs + // of any command that happens to leave a handle open. await tracker.report(ioHost.asHelper()); - // The whole report is debug output. Emitting at info would print it during - // ordinary runs of any command that happens to leave a handle open. expect(ioHost.notifySpy).toHaveBeenCalledWith(expectIoMsg(expect.any(String), 'debug')); expect(ioHost.notifySpy).not.toHaveBeenCalledWith(expectIoMsg(expect.any(String), 'info')); }); @@ -148,38 +190,40 @@ test('reports nothing until tracking is started', async () => { await tracker.report(ioHost.asHelper()); clearInterval(before); - expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); + expect(reportedLines()).toEqual(NOTHING_FOUND); }); -test('describes an unknown resource type without a description', async () => { +test('excludes handles that have already been garbage collected', async () => { tracker = trackLeakedHandles(); - // Node's set of async resource types grows over time. An unrecognised type - // must still be reported, just without the plain-language explanation. - injectWatched(tracker, { type: 'SOMETHINGNEW' }); + // We hold handles weakly so tracking doesn't keep them alive. A collected + // handle is by definition no longer keeping the loop open. + injectWatched(tracker, { type: 'TCPWRAP', deref: () => undefined }); await tracker.report(ioHost.asHelper()); - const lines = reportedLines(); - expect(lines).toContainEqual(chalk.bold('# SOMETHINGNEW')); - expect(lines).toContain(' (no application stack frames)'); + expect(reportedLines()).toEqual(NOTHING_FOUND); }); -test('excludes handles that have already been garbage collected', async () => { +test('says so when a handle was opened entirely inside Node internals', async () => { tracker = trackLeakedHandles(); - // We hold handles weakly so tracking doesn't keep them alive. A collected - // handle is by definition no longer keeping the loop open. - injectWatched(tracker, { type: 'TCPWRAP', deref: () => undefined }); + // With no application frames there is no location to print, so the report has + // to explain the absence rather than leave an empty stack behind a heading. + injectWatched(tracker, { type: 'TCPWRAP' }); await tracker.report(ioHost.asHelper()); - expect(reportedLines()).toEqual(['0 handles still keeping the CLI process alive:']); + const lines = reportedLines(); + expect(lines).toContainEqual(chalk.bold('# TCPWRAP (open network connection)')); + expect(lines).toContain(' (opened entirely inside Node internals, no CLI frames to show)'); + expect(lines).not.toContain(' call stack:'); }); -test('still reports a handle whose source file cannot be read', async () => { +test('still prints the location of a frame whose source file cannot be read', async () => { tracker = trackLeakedHandles(); // Bundled and eval'd frames have file names that don't exist on disk. The - // location is worth reporting even when we can't show the line of code. + // location identifies the frame, so it must appear even with no line of code + // to show beneath it. injectWatched(tracker, { type: 'TCPWRAP', creationStack: [{ func: 'openSocket', file: '/does/not/exist.ts', line: 1 }], @@ -189,6 +233,7 @@ test('still reports a handle whose source file cannot be read', async () => { const lines = reportedLines(); expect(lines).toContain(' created in openSocket()'); expect(lines).toContain(' call stack:'); + expect(lines).toContain(' openSocket (/does/not/exist.ts:1)'); }); test('scheduleReport stays silent until the grace period has passed', async () => { @@ -204,7 +249,7 @@ test('scheduleReport stays silent until the grace period has passed', async () = jest.advanceTimersByTime(1000); await drainMicrotasks(); - expect(reportedLines()[0]).toMatch(/still keeping the CLI process alive:$/); + expect(reportedLines().length).toBeGreaterThan(0); } finally { jest.useRealTimers(); }