chore(toolkit): consistent durations and error codes (#33287)

### Issue #33255 

Closes #33255 

### Reason for this change

Introducing consistent duration messages.

### Description of changes

- A new helper to end a timer with a message
- Attempted to bring a system into message codes, this deliberately breaks some existing codes (better now than later)
- changed payload prop `time` to `duration` on timings/duration messages.

### Describe any new or updated permissions being added

n/a

### Description of how you validated changes

existing tests

### Checklist
- [x] My code adheres to the [CONTRIBUTING GUIDE](https://github.com/aws/aws-cdk/blob/main/CONTRIBUTING.md) and [DESIGN GUIDELINES](https://github.com/aws/aws-cdk/blob/main/docs/DESIGN_GUIDELINES.md)

----

*By submitting this pull request, I confirm that my contribution is made under the terms of the Apache-2.0 license*

Author: mrgrain

packages/@aws-cdk/toolkit/lib/api/io/private/codes.ts

@@ -1,20 +1,27 @@
 import { IoMessageCode } from '../io-message';
 
 export const CODES = {
-  // Toolkit Info codes
-  CDK_TOOLKIT_I0001: 'Display stack data',
-  CDK_TOOLKIT_I0002: 'Successfully deployed stacks',
-  CDK_TOOLKIT_I3001: 'Informs about any log groups that are traced as part of the deployment',
-  CDK_TOOLKIT_I5001: 'Display synthesis times',
-  CDK_TOOLKIT_I5050: 'Confirm rollback',
+  // Synth
+  CDK_TOOLKIT_I1000: 'Provides synthesis times',
+  CDK_TOOLKIT_I1901: 'Provides stack data',
+  CDK_TOOLKIT_I1902: 'Successfully deployed stacks',
+
+  // Deploy
+  CDK_TOOLKIT_I5000: 'Provides deployment times',
+  CDK_TOOLKIT_I5001: 'Provides total time in deploy action, including synth and rollback',
+  CDK_TOOLKIT_I5031: 'Informs about any log groups that are traced as part of the deployment',
+  CDK_TOOLKIT_I5050: 'Confirm rollback during deployment',
   CDK_TOOLKIT_I5060: 'Confirm deploy security sensitive changes',
-  CDK_TOOLKIT_I7010: 'Confirm destroy stacks',
+  CDK_TOOLKIT_I5900: 'Deployment results on success',
 
-  // Toolkit Warning codes
+  // Rollback
+  CDK_TOOLKIT_I6000: 'Provides rollback times',
 
-  // Toolkit Error codes
+  // Destroy
+  CDK_TOOLKIT_I7000: 'Provides destroy times',
+  CDK_TOOLKIT_I7010: 'Confirm destroy stacks',
 
-  // Assembly Info codes
+  // Assembly codes
   CDK_ASSEMBLY_I0042: 'Writing updated context',
   CDK_ASSEMBLY_I0241: 'Fetching missing context',
   CDK_ASSEMBLY_I1000: 'Cloud assembly output starts',

packages/@aws-cdk/toolkit/lib/api/io/private/timer.ts

@@ -1,3 +1,6 @@
+import { VALID_CODE } from './codes';
+import { info } from './messages';
+import { ActionAwareIoHost } from './types';
 import { formatTime } from '../../aws-cdk';
 
 /**
@@ -29,4 +32,31 @@ export class Timer {
       asSec: formatTime(elapsedTime),
     };
   }
+
+  /**
+   * Ends the current timer as a specified timing and notifies the IoHost.
+   * @returns the elapsed time
+   */
+  public async endAs(ioHost: ActionAwareIoHost, type: 'synth' | 'deploy' | 'rollback' | 'destroy') {
+    const duration = this.end();
+    const { code, text } = timerMessageProps(type);
+
+    await ioHost.notify(info(`\n✨  ${text} time: ${duration.asSec}s\n`, code, {
+      duration: duration.asMs,
+    }));
+
+    return duration;
+  }
+}
+
+function timerMessageProps(type: 'synth' | 'deploy' | 'rollback'| 'destroy'): {
+  code: VALID_CODE;
+  text: string;
+} {
+  switch (type) {
+    case 'synth': return { code: 'CDK_TOOLKIT_I1000', text: 'Synthesis' };
+    case 'deploy': return { code: 'CDK_TOOLKIT_I5000', text: 'Deployment' };
+    case 'rollback': return { code: 'CDK_TOOLKIT_I6000', text: 'Rollback' };
+    case 'destroy': return { code: 'CDK_TOOLKIT_I7000', text: 'Destroy' };
+  }
 }

packages/@aws-cdk/toolkit/lib/toolkit/toolkit.ts

@@ -14,7 +14,7 @@ import { type RollbackOptions } from '../actions/rollback';
 import { type SynthOptions } from '../actions/synth';
 import { patternsArrayForWatch, WatchOptions } from '../actions/watch';
 import { type SdkOptions } from '../api/aws-auth';
-import { DEFAULT_TOOLKIT_STACK_NAME, SdkProvider, SuccessfulDeployStackResult, StackCollection, Deployments, HotswapMode, StackActivityProgress, ResourceMigrator, obscureTemplate, serializeStructure, tagsForStack, CliIoHost, validateSnsTopicArn, Concurrency, WorkGraphBuilder, AssetBuildNode, AssetPublishNode, StackNode, formatErrorMessage, CloudWatchLogEventMonitor, findCloudWatchLogGroups } from '../api/aws-cdk';
+import { DEFAULT_TOOLKIT_STACK_NAME, SdkProvider, SuccessfulDeployStackResult, StackCollection, Deployments, HotswapMode, StackActivityProgress, ResourceMigrator, obscureTemplate, serializeStructure, tagsForStack, CliIoHost, validateSnsTopicArn, Concurrency, WorkGraphBuilder, AssetBuildNode, AssetPublishNode, StackNode, formatErrorMessage, CloudWatchLogEventMonitor, findCloudWatchLogGroups, formatTime } from '../api/aws-cdk';
 import { CachedCloudAssemblySource, IdentityCloudAssemblySource, StackAssembly, ICloudAssemblySource, StackSelectionStrategy } from '../api/cloud-assembly';
 import { ALL_STACKS, CloudAssemblySourceBuilder } from '../api/cloud-assembly/private';
 import { ToolkitError } from '../api/errors';
@@ -158,10 +158,12 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
    */
   public async synth(cx: ICloudAssemblySource, options: SynthOptions = {}): Promise<ICloudAssemblySource> {
     const ioHost = withAction(this.ioHost, 'synth');
+    const synthTimer = Timer.start();
     const assembly = await this.assemblyFromSource(cx);
     const stacks = assembly.selectStacksV2(options.stacks ?? ALL_STACKS);
     const autoValidateStacks = options.validateStacks ? [assembly.selectStacksForValidation()] : [];
     await this.validateStacksMetadata(stacks.concat(...autoValidateStacks), ioHost);
+    await synthTimer.endAs(ioHost, 'synth');
 
     // if we have a single stack, print it to STDOUT
     const message = `Successfully synthesized to ${chalk.blue(path.resolve(stacks.assembly.directory))}`;
@@ -175,7 +177,7 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
       const firstStack = stacks.firstStack!;
       const template = firstStack.template;
       const obscuredTemplate = obscureTemplate(template);
-      await ioHost.notify(result(message, 'CDK_TOOLKIT_I0001', {
+      await ioHost.notify(result(message, 'CDK_TOOLKIT_I1901', {
         ...assemblyData,
         stack: {
           stackName: firstStack.stackName,
@@ -187,7 +189,7 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
       }));
     } else {
       // not outputting template to stdout, let's explain things to the user a little bit...
-      await ioHost.notify(result(chalk.green(message), 'CDK_TOOLKIT_I0002', assemblyData));
+      await ioHost.notify(result(chalk.green(message), 'CDK_TOOLKIT_I1902', assemblyData));
       await ioHost.notify(info(`Supply a stack id (${stacks.stackArtifacts.map((s) => chalk.green(s.hierarchicalId)).join(', ')}) to display its template.`));
     }
 
@@ -235,14 +237,10 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
    */
   private async _deploy(assembly: StackAssembly, action: 'deploy' | 'watch', options: ExtendedDeployOptions = {}) {
     const ioHost = withAction(this.ioHost, action);
-    const timer = Timer.start();
+    const synthTimer = Timer.start();
     const stackCollection = assembly.selectStacksV2(options.stacks ?? ALL_STACKS);
     await this.validateStacksMetadata(stackCollection, ioHost);
-
-    const synthTime = timer.end();
-    await ioHost.notify(info(`\n✨  Synthesis time: ${synthTime.asSec}s\n`, 'CDK_TOOLKIT_I5001', {
-      time: synthTime.asMs,
-    }));
+    const synthDuration = await synthTimer.endAs(ioHost, 'synth');
 
     if (stackCollection.stackCount === 0) {
       await ioHost.notify(error('This app contains no stacks'));
@@ -352,14 +350,14 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
       await ioHost.notify(
         info(`${chalk.bold(stack.displayName)}: deploying... [${stackIndex}/${stackCollection.stackCount}]`),
       );
-      const startDeployTime = Timer.start();
+      const deployTimer = Timer.start();
 
       let tags = options.tags;
       if (!tags || tags.length === 0) {
         tags = tagsForStack(stack);
       }
 
-      let elapsedDeployTime;
+      let deployDuration;
       try {
         let deployResult: SuccessfulDeployStackResult | undefined;
 
@@ -405,7 +403,6 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
               if (options.force) {
                 await ioHost.notify(warn(`${motivation}. Rolling back first (--force).`));
               } else {
-                // @todo reintroduce concurrency and corked logging in CliHost
                 const confirmed = await ioHost.requestResponse(confirm('CDK_TOOLKIT_I5050', question, motivation, true, concurrency));
                 if (!confirmed) { throw new ToolkitError('Aborted by user'); }
               }
@@ -429,7 +426,6 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
               if (options.force) {
                 await ioHost.notify(warn(`${motivation}. Proceeding with regular deployment (--force).`));
               } else {
-                // @todo reintroduce concurrency and corked logging in CliHost
                 const confirmed = await ioHost.requestResponse(confirm('CDK_TOOLKIT_I5050', question, motivation, true, concurrency));
                 if (!confirmed) { throw new ToolkitError('Aborted by user'); }
               }
@@ -448,24 +444,20 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
           ? ` ✅  ${stack.displayName} (no changes)`
           : ` ✅  ${stack.displayName}`;
 
-        await ioHost.notify(success('\n' + message));
-        elapsedDeployTime = startDeployTime.end();
-        await ioHost.notify(info(`\n✨  Deployment time: ${elapsedDeployTime.asSec}s\n`));
+        await ioHost.notify(result(chalk.green('\n' + message), 'CDK_TOOLKIT_I5900', deployResult));
+        deployDuration = await deployTimer.endAs(ioHost, 'deploy');
 
         if (Object.keys(deployResult.outputs).length > 0) {
-          await ioHost.notify(info('Outputs:'));
-
+          const buffer = ['Outputs:'];
           stackOutputs[stack.stackName] = deployResult.outputs;
-        }
 
-        for (const name of Object.keys(deployResult.outputs).sort()) {
-          const value = deployResult.outputs[name];
-          await ioHost.notify(info(`${chalk.cyan(stack.id)}.${chalk.cyan(name)} = ${chalk.underline(chalk.cyan(value))}`));
+          for (const name of Object.keys(deployResult.outputs).sort()) {
+            const value = deployResult.outputs[name];
+            buffer.push(`${chalk.cyan(stack.id)}.${chalk.cyan(name)} = ${chalk.underline(chalk.cyan(value))}`);
+          }
+          await ioHost.notify(info(buffer.join('\n')));
         }
-
-        await ioHost.notify(info('Stack ARN:'));
-
-        await ioHost.notify(info(deployResult.stackArn));
+        await ioHost.notify(info(`Stack ARN:\n${deployResult.stackArn}`));
       } catch (e: any) {
         // It has to be exactly this string because an integration test tests for
         // "bold(stackname) failed: ResourceNotReady: <error>"
@@ -482,7 +474,7 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
             foundLogGroupsResult.sdk,
             foundLogGroupsResult.logGroupNames,
           );
-          await ioHost.notify(info(`The following log groups are added: ${foundLogGroupsResult.logGroupNames}`, 'CDK_TOOLKIT_I3001'));
+          await ioHost.notify(info(`The following log groups are added: ${foundLogGroupsResult.logGroupNames}`, 'CDK_TOOLKIT_I5031'));
         }
 
         // If an outputs file has been specified, create the file path and write stack outputs to it once.
@@ -496,7 +488,8 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
           });
         }
       }
-      await ioHost.notify(info(`\n✨  Total time: ${synthTime.asSec + elapsedDeployTime.asSec}s\n`));
+      const duration = synthDuration.asMs + (deployDuration?.asMs ?? 0);
+      await ioHost.notify(info(`\n✨  Total time: ${formatTime(duration)}s\n`, 'CDK_TOOLKIT_I5001', { duration }));
     };
 
     const assetBuildTime = options.assetBuildTime ?? AssetBuildTime.ALL_BEFORE_DEPLOY;
@@ -649,13 +642,10 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
    */
   private async _rollback(assembly: StackAssembly, action: 'rollback' | 'deploy' | 'watch', options: RollbackOptions): Promise<void> {
     const ioHost = withAction(this.ioHost, action);
-    const timer = Timer.start();
+    const synthTimer = Timer.start();
     const stacks = assembly.selectStacksV2(options.stacks);
     await this.validateStacksMetadata(stacks, ioHost);
-    const synthTime = timer.end();
-    await ioHost.notify(info(`\n✨  Synthesis time: ${synthTime.asSec}s\n`, 'CDK_TOOLKIT_I5001', {
-      time: synthTime.asMs,
-    }));
+    await synthTimer.endAs(ioHost, 'synth');
 
     if (stacks.stackCount === 0) {
       await ioHost.notify(error('No stacks selected'));
@@ -666,7 +656,7 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
 
     for (const stack of stacks.stackArtifacts) {
       await ioHost.notify(info(`Rolling back ${chalk.bold(stack.displayName)}`));
-      const startRollbackTime = Timer.start();
+      const rollbackTimer = Timer.start();
       const deployments = await this.deploymentsForAction('rollback');
       try {
         const stackResult = await deployments.rollbackStack({
@@ -680,8 +670,7 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
         if (!stackResult.notInRollbackableState) {
           anyRollbackable = true;
         }
-        const elapsedRollbackTime = startRollbackTime.end();
-        await ioHost.notify(info(`\n✨  Rollback time: ${elapsedRollbackTime.asSec}s\n`));
+        await rollbackTimer.endAs(ioHost, 'rollback');
       } catch (e: any) {
         await ioHost.notify(error(`\n ❌  ${chalk.bold(stack.displayName)} failed: ${formatErrorMessage(e)}`));
         throw new ToolkitError('Rollback failed (use --force to orphan failing resources)');
@@ -707,8 +696,10 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
    */
   private async _destroy(assembly: StackAssembly, action: 'deploy' | 'destroy', options: DestroyOptions): Promise<void> {
     const ioHost = withAction(this.ioHost, action);
+    const synthTimer = Timer.start();
     // The stacks will have been ordered for deployment, so reverse them for deletion.
     const stacks = await assembly.selectStacksV2(options.stacks).reversed();
+    await synthTimer.endAs(ioHost, 'synth');
 
     const motivation = 'Destroying stacks is an irreversible action';
     const question = `Are you sure you want to delete: ${chalk.red(stacks.hierarchicalIds.join(', '))}`;
@@ -717,21 +708,26 @@ export class Toolkit extends CloudAssemblySourceBuilder implements AsyncDisposab
       return ioHost.notify(error('Aborted by user'));
     }
 
-    for (const [index, stack] of stacks.stackArtifacts.entries()) {
-      await ioHost.notify(success(`${chalk.blue(stack.displayName)}: destroying... [${index + 1}/${stacks.stackCount}]`));
-      try {
-        const deployments = await this.deploymentsForAction(action);
-        await deployments.destroyStack({
-          stack,
-          deployName: stack.stackName,
-          roleArn: options.roleArn,
-          ci: options.ci,
-        });
-        await ioHost.notify(success(`\n ✅  ${chalk.blue(stack.displayName)}: ${action}ed`));
-      } catch (e) {
-        await ioHost.notify(error(`\n ❌  ${chalk.blue(stack.displayName)}: ${action} failed ${e}`));
-        throw e;
+    const destroyTimer = Timer.start();
+    try {
+      for (const [index, stack] of stacks.stackArtifacts.entries()) {
+        await ioHost.notify(success(`${chalk.blue(stack.displayName)}: destroying... [${index + 1}/${stacks.stackCount}]`));
+        try {
+          const deployments = await this.deploymentsForAction(action);
+          await deployments.destroyStack({
+            stack,
+            deployName: stack.stackName,
+            roleArn: options.roleArn,
+            ci: options.ci,
+          });
+          await ioHost.notify(success(`\n ✅  ${chalk.blue(stack.displayName)}: ${action}ed`));
+        } catch (e) {
+          await ioHost.notify(error(`\n ❌  ${chalk.blue(stack.displayName)}: ${action} failed ${e}`));
+          throw e;
+        }
       }
+    } finally {
+      await destroyTimer.endAs(ioHost, 'destroy');
     }
   }
 

packages/@aws-cdk/toolkit/test/actions/deploy.test.ts

@@ -148,7 +148,7 @@ describe('deploy', () => {
       expect(ioHost.notifySpy).toHaveBeenCalledWith(expect.objectContaining({
         action: 'deploy',
         level: 'info',
-        code: 'CDK_TOOLKIT_I3001',
+        code: 'CDK_TOOLKIT_I5031',
         message: expect.stringContaining('The following log groups are added: /aws/lambda/lambda-function-name'),
       }));
     });

packages/@aws-cdk/toolkit/test/actions/synth.test.ts

@@ -45,7 +45,7 @@ describe('synth', () => {
     expect(ioHost.notifySpy).toHaveBeenCalledWith(expect.objectContaining({
       action: 'synth',
       level: 'result',
-      code: 'CDK_TOOLKIT_I0001',
+      code: 'CDK_TOOLKIT_I1901',
       message: expect.stringContaining('Successfully synthesized'),
       data: expect.objectContaining({
         stacksCount: 1,
@@ -66,7 +66,7 @@ describe('synth', () => {
     expect(ioHost.notifySpy).toHaveBeenCalledWith(expect.objectContaining({
       action: 'synth',
       level: 'result',
-      code: 'CDK_TOOLKIT_I0002',
+      code: 'CDK_TOOLKIT_I1902',
       message: expect.stringContaining('Successfully synthesized'),
       data: expect.objectContaining({
         stacksCount: 2,