diff --git a/packages/@aws-cdk/toolkit-lib/lib/api/cloud-assembly/private/exec.ts b/packages/@aws-cdk/toolkit-lib/lib/api/cloud-assembly/private/exec.ts index 8c349253b..ec9902238 100644 --- a/packages/@aws-cdk/toolkit-lib/lib/api/cloud-assembly/private/exec.ts +++ b/packages/@aws-cdk/toolkit-lib/lib/api/cloud-assembly/private/exec.ts @@ -4,6 +4,12 @@ import { readFileSync } from 'fs'; import split = require('split2'); import { AssemblyError } from '../../../toolkit/toolkit-error'; +// [#1217-trace] Temporary instrumentation for issue #1217. Remove before merge. +function trace1217(msg: string): void { + // eslint-disable-next-line no-console + console.error(`[#1217-trace] ${new Date().toISOString()} ${msg}`); +} + type EventPublisher = (event: 'open' | 'data_stdout' | 'data_stderr' | 'close', line: string) => void; interface ExecOptions { @@ -27,6 +33,7 @@ interface ExecOptions { */ export async function execInChildProcess(commandAndArgs: string, options: ExecOptions = {}) { const captureOutput = options.captureOutput ?? true; + trace1217(`execInChildProcess: spawning "${commandAndArgs}" (captureOutput=${captureOutput})`); return new Promise((ok, fail) => { // We use a slightly lower-level interface to: @@ -81,11 +88,14 @@ export async function execInChildProcess(commandAndArgs: string, options: ExecOp } proc.on('error', (e) => { + trace1217(`execInChildProcess: proc.on('error') — ${e?.message ?? e}`); fail(AssemblyError.withCause(`Failed to execute CDK app: ${commandAndArgs}`, e)); }); proc.on('exit', code => { + trace1217(`execInChildProcess: proc.on('exit') code=${code}`); if (code === 0) { + trace1217('execInChildProcess: resolving ok()'); return ok(); } else { const stdErrString = stderr.join('\n'); @@ -112,6 +122,7 @@ export async function execInChildProcess(commandAndArgs: string, options: ExecOp } } + trace1217(`execInChildProcess: rejecting fail() with code ${code}`); return fail(error); } }); diff --git a/packages/aws-cdk/lib/cli/cdk-toolkit.ts b/packages/aws-cdk/lib/cli/cdk-toolkit.ts index 8b7b1f4d6..abf44dfe6 100644 --- a/packages/aws-cdk/lib/cli/cdk-toolkit.ts +++ b/packages/aws-cdk/lib/cli/cdk-toolkit.ts @@ -13,6 +13,12 @@ import { CliIoHost } from './io-host'; import type { Configuration } from './user-configuration'; import { PROJECT_CONFIG } from './user-configuration'; import type { ActionLessRequest, IoHelper } from '../../lib/api-private'; + +// [#1217-trace] Temporary instrumentation for issue #1217. Remove before merge. +function trace1217(msg: string): void { + // eslint-disable-next-line no-console + console.error(`[#1217-trace] ${new Date().toISOString()} ${msg}`); +} import { asIoHelper, cfnApi, createIgnoreMatcher, IO, tagsForStack } from '../../lib/api-private'; import type { AssetBuildNode, AssetPublishNode, Concurrency, StackNode, WorkGraph } from '../api'; import { @@ -1288,7 +1294,9 @@ export class CdkToolkit { `Supply a stack id (${stacks.stackArtifacts.map((s) => chalk.green(s.hierarchicalId)).join(', ')}) to display its template.`, ); + trace1217('synth: before displayFlagsMessage'); await displayFlagsMessage(this.ioHost.asIoHelper(), this.toolkit, this.props.cloudExecutable); + trace1217('synth: after displayFlagsMessage'); return undefined; } @@ -2347,11 +2355,14 @@ async function askUserConfirmation( * - The default value for the flag (unconfiguredBehavesLike) is different from the recommended value */ export async function displayFlagsMessage(ioHost: IoHelper, toolkit: InternalToolkit, cloudExecutable: CloudExecutable): Promise { + trace1217('displayFlagsMessage: before toolkit.flags'); const flags = await toolkit.flags(cloudExecutable); + trace1217(`displayFlagsMessage: after toolkit.flags (count=${flags.length})`); // The "unconfiguredBehavesLike" information got added later. If none of the flags have this information, // we don't have enough information to reliably display this information without scaring users, so don't do anything. if (flags.every(flag => flag.unconfiguredBehavesLike === undefined)) { + trace1217('displayFlagsMessage: returning early (no unconfiguredBehavesLike data)'); return; } @@ -2359,8 +2370,11 @@ export async function displayFlagsMessage(ioHost: IoHelper, toolkit: InternalToo const numUnconfigured = unconfiguredFlags.length; if (numUnconfigured > 0) { + trace1217('displayFlagsMessage: before warn'); await ioHost.defaults.warn(`${numUnconfigured} feature flags are not configured. Run 'cdk flags --unstable=flags' to learn more.`); + trace1217('displayFlagsMessage: after warn'); } + trace1217('displayFlagsMessage: returning normally'); } /** diff --git a/packages/aws-cdk/lib/cli/cli.ts b/packages/aws-cdk/lib/cli/cli.ts index fb050b97a..31cc7e8b4 100644 --- a/packages/aws-cdk/lib/cli/cli.ts +++ b/packages/aws-cdk/lib/cli/cli.ts @@ -42,6 +42,14 @@ import { findUnknownOptions } from './util/check-unknown-options'; import { isCI } from './util/ci'; import { guessAgent } from './util/guess-agent'; +// [#1217-trace] Temporary instrumentation for issue #1217 (CDK CLI hangs in CI). +// Writes timestamped breadcrumbs directly to stderr so the last printed line +// pinpoints exactly which await never returned. Remove before merge. +function trace1217(msg: string): void { + // eslint-disable-next-line no-console + console.error(`[#1217-trace] ${new Date().toISOString()} ${msg}`); +} + export async function exec(args: string[], synthesizer?: Synthesizer): Promise { const argv = await parseCommandLineArguments(args); argv.language = getLanguageFromAlias(argv.language) ?? argv.language; @@ -237,13 +245,21 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise notices.display()); + trace1217('exec.finally: after notices.display'); } + trace1217('exec.finally: leave'); } async function main(command: string, args: any): Promise { @@ -875,14 +894,30 @@ function determineHotswapMode(hotswap?: boolean, hotswapFallback?: boolean, watc /* c8 ignore start */ // we never call this in unit tests export function cli(args: string[] = process.argv.slice(2)) { + // [#1217-trace] Heartbeat: every 5s, dump active resource types so the customer's + // log shows what handles are alive at the moment of the hang. .unref() so this + // timer itself doesn't keep the loop alive. + const heartbeat = setInterval(() => { + // eslint-disable-next-line no-console + console.error( + `[#1217-trace] ${new Date().toISOString()} heartbeat: active=${JSON.stringify(process.getActiveResourcesInfo())}`, + ); + }, 5000); + heartbeat.unref(); + + trace1217(`cli: enter (isTTY=${!!process.stdout.isTTY}, argv=${JSON.stringify(args)})`); + let error: ErrorDetails | undefined; exec(args) .then(async (value) => { + trace1217(`cli.then: enter (value=${typeof value === 'number' ? value : 'void'})`); if (typeof value === 'number') { process.exitCode = value; } + trace1217('cli.then: leave'); }) .catch(async (err) => { + trace1217(`cli.catch: enter (err.name=${err?.name}, err.message=${err?.message})`); // Log the stack trace if we're on a developer workstation. Otherwise this will be into a minified // file and the printed code line and stack trace are huge and useless. prettyPrintError(err, isDeveloperBuildVersion()); @@ -890,13 +925,23 @@ export function cli(args: string[] = process.argv.slice(2)) { name: cdkCliErrorName(err), }; process.exitCode = 1; + trace1217('cli.catch: leave'); }) .finally(async () => { + trace1217('cli.finally: enter'); try { + trace1217('cli.finally: before telemetry.end'); await CliIoHost.get()?.telemetry?.end(error); + trace1217('cli.finally: after telemetry.end'); } catch (e: any) { + trace1217(`cli.finally: telemetry.end threw: ${e?.message}`); await CliIoHost.get()?.asIoHelper().defaults.trace(`Ending Telemetry failed: ${e.message}`); } + // Final dump: if .finally() runs at all, we see what's alive at the very end. + // eslint-disable-next-line no-console + console.error( + `[#1217-trace] ${new Date().toISOString()} cli.finally: leave; active=${JSON.stringify(process.getActiveResourcesInfo())}`, + ); }); } /* c8 ignore stop */