feat(toolkit-lib): structured messages for hotswap (#260)

Adds structured data to hotswap messages. Includes a new trace method
that contains information about the hotswap after details have been
computed, but before execution.

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

---------

Co-authored-by: Eli Polonsky <Eli.polonsky@gmail.com>

Author: mrgrain

packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/payloads/hotswap.ts

@@ -1,5 +1,6 @@
 import type { PropertyDifference, Resource } from '@aws-cdk/cloudformation-diff';
 import type * as cxapi from '@aws-cdk/cx-api';
+import type { Duration } from './types';
 import type { ResourceMetadata } from '../../resource-metadata/resource-metadata';
 
 /**
@@ -176,10 +177,7 @@ export interface NonHotswappableChange {
   readonly description: string;
 }
 
-/**
- * Information about a hotswap deployment
- */
-export interface HotswapDeployment {
+export interface HotswapDeploymentAttempt {
   /**
    * The stack that's currently being deployed
    */
@@ -192,23 +190,18 @@ export interface HotswapDeployment {
 }
 
 /**
- * The result of an attempted hotswap deployment
+ * Information about a hotswap deployment
  */
-export interface HotswapResult {
+export interface HotswapDeploymentDetails {
   /**
-   * The stack that was hotswapped
+   * The stack that's currently being deployed
    */
   readonly stack: cxapi.CloudFormationStackArtifact;
+
   /**
    * The mode the hotswap deployment was initiated with.
    */
   readonly mode: 'hotswap-only' | 'fall-back';
-  /**
-   * Whether hotswapping happened or not.
-   *
-   * `false` indicates that the deployment could not be hotswapped and full deployment may be attempted as fallback.
-   */
-  readonly hotswapped: boolean;
   /**
    * The changes that were deemed hotswappable
    */
@@ -218,3 +211,15 @@ export interface HotswapResult {
    */
   readonly nonHotswappableChanges: NonHotswappableChange[];
 }
+
+/**
+ * The result of an attempted hotswap deployment
+ */
+export interface HotswapResult extends Duration, HotswapDeploymentDetails {
+  /**
+   * Whether hotswapping happened or not.
+   *
+   * `false` indicates that the deployment could not be hotswapped and full deployment may be attempted as fallback.
+   */
+  readonly hotswapped: boolean;
+}

packages/@aws-cdk/tmp-toolkit-helpers/src/api/io/private/messages.ts

@@ -5,7 +5,7 @@ import type { BootstrapEnvironmentProgress } from '../payloads/bootstrap-environ
 import type { MissingContext, UpdatedContext } from '../payloads/context';
 import type { BuildAsset, DeployConfirmationRequest, PublishAsset, StackDeployProgress, SuccessfulDeployStackResult } from '../payloads/deploy';
 import type { StackDestroy, StackDestroyProgress } from '../payloads/destroy';
-import type { HotswapDeployment } from '../payloads/hotswap';
+import type { HotswapDeploymentDetails, HotswapDeploymentAttempt, HotswappableChange, HotswapResult } from '../payloads/hotswap';
 import type { StackDetailsPayload } from '../payloads/list';
 import type { CloudWatchLogEvent, CloudWatchLogMonitorControlEvent } from '../payloads/logs-monitor';
 import type { StackRollbackProgress } from '../payloads/rollback';
@@ -197,15 +197,30 @@ export const IO = {
   }),
 
   // Hotswap (54xx)
-  CDK_TOOLKIT_I5400: make.trace<HotswapDeployment>({
+  CDK_TOOLKIT_I5400: make.trace<HotswapDeploymentAttempt>({
     code: 'CDK_TOOLKIT_I5400',
-    description: 'Starting a hotswap deployment',
-    interface: 'HotswapDeployment',
+    description: 'Attempting a hotswap deployment',
+    interface: 'HotswapDeploymentAttempt',
   }),
-  CDK_TOOLKIT_I5410: make.info<Duration>({
+  CDK_TOOLKIT_I5401: make.trace<HotswapDeploymentDetails>({
+    code: 'CDK_TOOLKIT_I5401',
+    description: 'Computed details for the hotswap deployment',
+    interface: 'HotswapDeploymentDetails',
+  }),
+  CDK_TOOLKIT_I5402: make.info<HotswappableChange>({
+    code: 'CDK_TOOLKIT_I5402',
+    description: 'A hotswappable change is processed as part of a hotswap deployment',
+    interface: 'HotswappableChange',
+  }),
+  CDK_TOOLKIT_I5403: make.info<HotswappableChange>({
+    code: 'CDK_TOOLKIT_I5403',
+    description: 'The hotswappable change has completed processing',
+    interface: 'HotswappableChange',
+  }),
+  CDK_TOOLKIT_I5410: make.info<HotswapResult>({
     code: 'CDK_TOOLKIT_I5410',
     description: 'Hotswap deployment has ended, a full deployment might still follow if needed',
-    interface: 'Duration',
+    interface: 'HotswapResult',
   }),
 
   // Stack Monitor (55xx)

packages/@aws-cdk/toolkit-lib/docs/message-registry.md

@@ -40,8 +40,11 @@ group: Documents
 | `CDK_TOOLKIT_I5313` | File event detected during active deployment, changes are queued | `info` | {@link FileWatchEvent} |
 | `CDK_TOOLKIT_I5314` | Initial watch deployment started | `info` | n/a |
 | `CDK_TOOLKIT_I5315` | Queued watch deployment started | `info` | n/a |
-| `CDK_TOOLKIT_I5400` | Starting a hotswap deployment | `trace` | {@link HotswapDeployment} |
-| `CDK_TOOLKIT_I5410` | Hotswap deployment has ended, a full deployment might still follow if needed | `info` | {@link Duration} |
+| `CDK_TOOLKIT_I5400` | Attempting a hotswap deployment | `trace` | {@link HotswapDeploymentAttempt} |
+| `CDK_TOOLKIT_I5401` | Computed details for the hotswap deployment | `trace` | {@link HotswapDeploymentDetails} |
+| `CDK_TOOLKIT_I5402` | A hotswappable change is processed as part of a hotswap deployment | `info` | {@link HotswappableChange} |
+| `CDK_TOOLKIT_I5403` | The hotswappable change has completed processing | `info` | {@link HotswappableChange} |
+| `CDK_TOOLKIT_I5410` | Hotswap deployment has ended, a full deployment might still follow if needed | `info` | {@link HotswapResult} |
 | `CDK_TOOLKIT_I5501` | Stack Monitoring: Start monitoring of a single stack | `info` | {@link StackMonitoringControlEvent} |
 | `CDK_TOOLKIT_I5502` | Stack Monitoring: Activity event for a single stack | `info` | {@link StackActivity} |
 | `CDK_TOOLKIT_I5503` | Stack Monitoring: Finished monitoring of a single stack | `info` | {@link StackMonitoringControlEvent} |

packages/aws-cdk/lib/api/deployments/hotswap-deployments.ts

@@ -110,7 +110,7 @@ export async function tryHotswapDeployment(
     hotswapPropertyOverrides,
   );
 
-  await hotswapSpan.end();
+  await hotswapSpan.end(result);
 
   if (result?.hotswapped === true) {
     return {
@@ -135,7 +135,7 @@ async function hotswapDeployment(
   stack: cxapi.CloudFormationStackArtifact,
   hotswapMode: HotswapMode,
   hotswapPropertyOverrides: HotswapPropertyOverrides,
-): Promise<HotswapResult> {
+): Promise<Omit<HotswapResult, 'duration'>> {
   // resolve the environment, so we can substitute things like AWS::Region in CFN expressions
   const resolvedEnv = await sdkProvider.resolveEnvironment(stack.environment);
   // create a new SDK using the CLI credentials, because the default one will not work for new-style synthesis -
@@ -162,11 +162,18 @@ async function hotswapDeployment(
     currentTemplate.nestedStacks, hotswapPropertyOverrides,
   );
 
-  await logNonHotswappableChanges(ioSpan, nonHotswappable, hotswapMode);
+  await logRejectedChanges(ioSpan, nonHotswappable, hotswapMode);
 
   const hotswappableChanges = hotswappable.map(o => o.change);
   const nonHotswappableChanges = nonHotswappable.map(n => n.change);
 
+  await ioSpan.notify(IO.CDK_TOOLKIT_I5401.msg('Hotswap plan created', {
+    stack,
+    mode: hotswapMode,
+    hotswappableChanges,
+    nonHotswappableChanges,
+  }));
+
   // preserve classic hotswap behavior
   if (hotswapMode === 'fall-back') {
     if (nonHotswappableChanges.length > 0) {
@@ -181,7 +188,7 @@ async function hotswapDeployment(
   }
 
   // apply the short-circuitable changes
-  await applyAllHotswappableChanges(sdk, ioSpan, hotswappable);
+  await applyAllHotswapOperations(sdk, ioSpan, hotswappable);
 
   return {
     stack,
@@ -489,27 +496,29 @@ function isCandidateForHotswapping(
   };
 }
 
-async function applyAllHotswappableChanges(sdk: SDK, ioSpan: IMessageSpan<any>, hotswappableChanges: HotswapOperation[]): Promise<void[]> {
-  if (hotswappableChanges.length > 0) {
-    await ioSpan.notify(IO.DEFAULT_TOOLKIT_INFO.msg(`\n${ICON} hotswapping resources:`));
+async function applyAllHotswapOperations(sdk: SDK, ioSpan: IMessageSpan<any>, hotswappableChanges: HotswapOperation[]): Promise<void[]> {
+  if (hotswappableChanges.length === 0) {
+    return Promise.resolve([]);
   }
+
+  await ioSpan.notify(IO.DEFAULT_TOOLKIT_INFO.msg(`\n${ICON} hotswapping resources:`));
   const limit = pLimit(10);
   // eslint-disable-next-line @cdklabs/promiseall-no-unbounded-parallelism
   return Promise.all(hotswappableChanges.map(hotswapOperation => limit(() => {
-    return applyHotswappableChange(sdk, ioSpan, hotswapOperation);
+    return applyHotswapOperation(sdk, ioSpan, hotswapOperation);
   })));
 }
 
-async function applyHotswappableChange(sdk: SDK, ioSpan: IMessageSpan<any>, hotswapOperation: HotswapOperation): Promise<void> {
+async function applyHotswapOperation(sdk: SDK, ioSpan: IMessageSpan<any>, hotswapOperation: HotswapOperation): Promise<void> {
   // note the type of service that was successfully hotswapped in the User-Agent
   const customUserAgent = `cdk-hotswap/success-${hotswapOperation.service}`;
   sdk.appendCustomUserAgent(customUserAgent);
-
   const resourceText = (r: AffectedResource) => r.description ?? `${r.resourceType} '${r.physicalName ?? r.logicalId}'`;
 
-  for (const resource of hotswapOperation.change.resources) {
-    await ioSpan.notify(IO.DEFAULT_TOOLKIT_INFO.msg(format(`   ${ICON} %s`, chalk.bold(resourceText(resource)))));
-  }
+  await ioSpan.notify(IO.CDK_TOOLKIT_I5402.msg(
+    hotswapOperation.change.resources.map(r => format(`   ${ICON} %s`, chalk.bold(resourceText(r)))).join('\n'),
+    hotswapOperation.change,
+  ));
 
   // if the SDK call fails, an error will be thrown by the SDK
   // and will prevent the green 'hotswapped!' text from being displayed
@@ -525,9 +534,10 @@ async function applyHotswappableChange(sdk: SDK, ioSpan: IMessageSpan<any>, hots
     throw e;
   }
 
-  for (const resource of hotswapOperation.change.resources) {
-    await ioSpan.notify(IO.DEFAULT_TOOLKIT_INFO.msg(format(`${ICON} %s %s`, chalk.bold(resourceText(resource)), chalk.green('hotswapped!'))));
-  }
+  await ioSpan.notify(IO.CDK_TOOLKIT_I5403.msg(
+    hotswapOperation.change.resources.map(r => format(`   ${ICON} %s %s`, chalk.bold(resourceText(r)), chalk.green('hotswapped!'))).join('\n'),
+    hotswapOperation.change,
+  ));
 
   sdk.removeCustomUserAgent(customUserAgent);
 }
@@ -550,12 +560,12 @@ function formatWaiterErrorResult(result: WaiterResult) {
   return main;
 }
 
-async function logNonHotswappableChanges(
+async function logRejectedChanges(
   ioSpan: IMessageSpan<any>,
-  nonHotswappableChanges: RejectedChange[],
+  rejectedChanges: RejectedChange[],
   hotswapMode: HotswapMode,
 ): Promise<void> {
-  if (nonHotswappableChanges.length === 0) {
+  if (rejectedChanges.length === 0) {
     return;
   }
   /**
@@ -566,9 +576,9 @@ async function logNonHotswappableChanges(
    * This logic prevents us from logging that change as non-hotswappable when we hotswap it.
    */
   if (hotswapMode === 'hotswap-only') {
-    nonHotswappableChanges = nonHotswappableChanges.filter((change) => change.hotswapOnlyVisible === true);
+    rejectedChanges = rejectedChanges.filter((change) => change.hotswapOnlyVisible === true);
 
-    if (nonHotswappableChanges.length === 0) {
+    if (rejectedChanges.length === 0) {
       return;
     }
   }
@@ -581,8 +591,8 @@ async function logNonHotswappableChanges(
     messages.push(format('%s %s', chalk.red('⚠️'), chalk.red('The following non-hotswappable changes were found:')));
   }
 
-  for (const rejection of nonHotswappableChanges) {
-    messages.push('    ' + nonHotswappableChangeMessage(rejection.change));
+  for (const { change } of rejectedChanges) {
+    messages.push('    ' + nonHotswappableChangeMessage(change));
   }
   messages.push(''); // newline