chore(cli): [DO NOT MERGE] [#1217] trace instrumentation

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<void>((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);
       }
     });

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,20 +2355,26 @@ 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<void> {
+  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;
   }
 
   const unconfiguredFlags = FlagOperations.filterNeedsAttention(flags);
   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');
 }
 
 /**

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<number | void> {
   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<n
   try {
     return await main(cmd, argv);
   } finally {
+    trace1217('exec.finally: enter');
+
     // If we locked the 'cdk.out' directory, release it here.
+    trace1217('exec.finally: before outDirLock.release');
     await outDirLock?.release();
+    trace1217('exec.finally: after outDirLock.release');
 
     // Do PSAs here
+    trace1217('exec.finally: before displayVersionMessage');
     await displayVersionMessage(ioHelper);
+    trace1217('exec.finally: after displayVersionMessage');
 
+    trace1217('exec.finally: before await refreshNotices');
     await refreshNotices;
+    trace1217('exec.finally: after await refreshNotices');
     if (cmd === 'notices') {
       // do not trap errors here
       // this is the notices command itself, any error should be loud
@@ -253,8 +269,11 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise<n
         showTotal: argv.unacknowledged,
       });
     } else if (shouldDisplayNotices && cmd !== 'version') {
+      trace1217('exec.finally: before notices.display');
       await trapErrors(ioHelper, 'Could not display notices', () => notices.display());
+      trace1217('exec.finally: after notices.display');
     }
+    trace1217('exec.finally: leave');
   }
 
   async function main(command: string, args: any): Promise<number | void> {
@@ -875,28 +894,54 @@ 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());
       error = {
         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 */