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/cli.ts b/packages/aws-cdk/lib/cli/cli.ts index 58867c496..61cf307e5 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..4b54ed9dc --- /dev/null +++ b/packages/aws-cdk/lib/cli/debug-handles.ts @@ -0,0 +1,280 @@ +import { createHook } from 'node:async_hooks'; +import { readFileSync } from 'node:fs'; +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: '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: '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', +}; + +/** + * 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; + 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} ${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(''); + 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; + } + + // 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}()`); + } + + await ioHelper.defaults.info(' call stack:'); + for (const frame of frames) { + const source = sourceAt(frame); + if (source) { + await ioHelper.defaults.info(` ${chalk.dim(source)}`); + } + } + } +} + +/** + * 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. + * + * `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[] } = {}; + + // `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 { + func: site.getFunctionName() ?? '', + file: file.startsWith('file://') ? fileURLToPath(file) : file, + line: site.getLineNumber() ?? 0, + }; + }); + try { + Error.captureStackTrace(carrier, captureCreationStack); + // 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 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) => 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; + // 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). + // 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..265606663 --- /dev/null +++ b/packages/aws-cdk/test/cli/debug-handles.test.ts @@ -0,0 +1,97 @@ +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'; + +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+ 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)')); + // 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 () => { + 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 handles 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 handles 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); +});