feat(cli): logging can be corked (#25644)

🍾

This PR extends #25536 by fixing issues with logging.

- Asset building and publishing are now completely separate tasks, so there is never a need for the "Building and Publishing" message in cdk-assets. I've removed a good chunk of unnecessary private props in `AssetPublisher` and now we simply print `Building` when building an asset and `Publishing` when publishing an asset. No combos anymore.
- Asset build/publish can now happen concurrently with stack deployments when there are no dependencies between the two, but if `--require-approval` is set (which it is by default), sensitive stack deployments prompt the user for a `y/n` response before deployment. Additional asset related messages may come in at this time, cluttering the log. The solution here is to implement a cork that is turned on when prompting the user and turned off after user input. When using the helper function `withCorkedLogging(callback)`, logs will instead be stored in memory and released when the cork is popped.

Testing:

There's not a great way to test these changes in code since they should only affect logging. Instead, I hope the following photos suffice:

Before the lock change, logging looked like this:
<img width="698" alt="Screen Shot 2023-05-18 at 4 59 35 PM" src="https://github.com/aws/aws-cdk/assets/36202692/c554c1f2-1034-422c-95e6-ebf15f09b35b">

Now it looks like this in the same scenario: 
 
<img width="697" alt="Screen Shot 2023-05-18 at 4 49 39 PM" src="https://github.com/aws/aws-cdk/assets/36202692/1257c20e-73c4-4fc2-b8cd-ae510f32c756">

The screenshots also show the logs that say `Building` and `Publishing` separately rather than `Building and Publishing` as it did before.

----

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

Author: kaizencc

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

@@ -17,7 +17,7 @@ import { CloudWatchLogEventMonitor } from './api/logs/logs-monitor';
 import { StackActivityProgress } from './api/util/cloudformation/stack-activity-monitor';
 import { printSecurityDiff, printStackDiff, RequireApproval } from './diff';
 import { ResourceImporter } from './import';
-import { data, debug, error, highlight, print, success, warning } from './logging';
+import { data, debug, error, highlight, print, success, warning, withCorkedLogging } from './logging';
 import { deserializeStructure, serializeStructure } from './serialize';
 import { Configuration, PROJECT_CONFIG } from './settings';
 import { numberFromBool, partition } from './util';
@@ -238,23 +238,24 @@ export class CdkToolkit {
       if (requireApproval !== RequireApproval.Never) {
         const currentTemplate = await this.props.deployments.readCurrentTemplate(stack);
         if (printSecurityDiff(currentTemplate, stack, requireApproval)) {
-
-          // only talk to user if STDIN is a terminal (otherwise, fail)
-          if (!process.stdin.isTTY) {
-            throw new Error(
-              '"--require-approval" is enabled and stack includes security-sensitive updates, ' +
-              'but terminal (TTY) is not attached so we are unable to get a confirmation from the user');
-          }
-
-          // only talk to user if concurrency is 1 (otherwise, fail)
-          if (concurrency > 1) {
-            throw new Error(
-              '"--require-approval" is enabled and stack includes security-sensitive updates, ' +
-              'but concurrency is greater than 1 so we are unable to get a confirmation from the user');
-          }
-
-          const confirmed = await promptly.confirm('Do you wish to deploy these changes (y/n)?');
-          if (!confirmed) { throw new Error('Aborted by user'); }
+          await withCorkedLogging(async () => {
+            // only talk to user if STDIN is a terminal (otherwise, fail)
+            if (!process.stdin.isTTY) {
+              throw new Error(
+                '"--require-approval" is enabled and stack includes security-sensitive updates, ' +
+                'but terminal (TTY) is not attached so we are unable to get a confirmation from the user');
+            }
+
+            // only talk to user if concurrency is 1 (otherwise, fail)
+            if (concurrency > 1) {
+              throw new Error(
+                '"--require-approval" is enabled and stack includes security-sensitive updates, ' +
+                'but concurrency is greater than 1 so we are unable to get a confirmation from the user');
+            }
+
+            const confirmed = await promptly.confirm('Do you wish to deploy these changes (y/n)?');
+            if (!confirmed) { throw new Error('Aborted by user'); }
+          });
         }
       }
 

packages/aws-cdk/lib/logging.ts

@@ -7,6 +7,34 @@ const { stdout, stderr } = process;
 
 type WritableFactory = () => Writable;
 
+export async function withCorkedLogging<A>(block: () => Promise<A>): Promise<A> {
+  corkLogging();
+  try {
+    return await block();
+  } finally {
+    uncorkLogging();
+  }
+}
+
+let CORK_COUNTER = 0;
+const logBuffer: [Writable, string][] = [];
+
+function corked() {
+  return CORK_COUNTER !== 0;
+}
+
+function corkLogging() {
+  CORK_COUNTER += 1;
+}
+
+function uncorkLogging() {
+  CORK_COUNTER -= 1;
+  if (!corked()) {
+    logBuffer.forEach(([stream, str]) => stream.write(str + '\n'));
+    logBuffer.splice(0);
+  }
+}
+
 const logger = (stream: Writable | WritableFactory, styles?: StyleFn[], timestamp?: boolean) => (fmt: string, ...args: unknown[]) => {
   const ts = timestamp ? `[${formatTime(new Date())}] ` : '';
 
@@ -15,11 +43,19 @@ const logger = (stream: Writable | WritableFactory, styles?: StyleFn[], timestam
     str = styles.reduce((a, style) => style(a), str);
   }
 
-
   const realStream = typeof stream === 'function' ? stream() : stream;
+
+  // Logger is currently corked, so we store the message to be printed
+  // later when we are uncorked.
+  if (corked()) {
+    logBuffer.push([realStream, str]);
+    return;
+  }
+
   realStream.write(str + '\n');
 };
 
+
 function formatTime(d: Date) {
   return `${lpad(d.getHours(), 2)}:${lpad(d.getMinutes(), 2)}:${lpad(d.getSeconds(), 2)}`;
 

packages/cdk-assets/lib/publishing.ts

@@ -82,9 +82,6 @@ export class AssetPublishing implements IPublishProgress {
   private readonly publishInParallel: boolean;
   private readonly buildAssets: boolean;
   private readonly publishAssets: boolean;
-  private readonly startMessagePrefix: string;
-  private readonly successMessagePrefix: string;
-  private readonly errorMessagePrefix: string;
   private readonly handlerCache = new Map<IManifestEntry, IAssetHandler>();
 
   constructor(private readonly manifest: AssetManifest, private readonly options: AssetPublishingOptions) {
@@ -94,34 +91,6 @@ export class AssetPublishing implements IPublishProgress {
     this.buildAssets = options.buildAssets ?? true;
     this.publishAssets = options.publishAssets ?? true;
 
-    const getMessages = () => {
-      if (this.buildAssets && this.publishAssets) {
-        return {
-          startMessagePrefix: 'Building and publishing',
-          successMessagePrefix: 'Built and published',
-          errorMessagePrefix: 'Error building and publishing',
-        };
-      } else if (this.buildAssets) {
-        return {
-          startMessagePrefix: 'Building',
-          successMessagePrefix: 'Built',
-          errorMessagePrefix: 'Error building',
-        };
-      } else {
-        return {
-          startMessagePrefix: 'Publishing',
-          successMessagePrefix: 'Published',
-          errorMessagePrefix: 'Error publishing',
-        };
-      }
-    };
-
-    const messages = getMessages();
-
-    this.startMessagePrefix = messages.startMessagePrefix;
-    this.successMessagePrefix = messages.successMessagePrefix;
-    this.errorMessagePrefix = messages.errorMessagePrefix;
-
     const self = this;
     this.handlerHost = {
       aws: this.options.aws,
@@ -146,7 +115,7 @@ export class AssetPublishing implements IPublishProgress {
     }
 
     if ((this.options.throwOnError ?? true) && this.failures.length > 0) {
-      throw new Error(`${this.errorMessagePrefix}: ${this.failures.map(e => e.error.message)}`);
+      throw new Error(`Error publishing: ${this.failures.map(e => e.error.message)}`);
     }
   }
 
@@ -155,14 +124,17 @@ export class AssetPublishing implements IPublishProgress {
    */
   public async buildEntry(asset: IManifestEntry) {
     try {
-      if (this.progressEvent(EventType.START, `${this.startMessagePrefix} ${asset.id}`)) { return false; }
+      if (this.progressEvent(EventType.START, `Building ${asset.id}`)) { return false; }
 
       const handler = this.assetHandler(asset);
       await handler.build();
 
       if (this.aborted) {
         throw new Error('Aborted');
       }
+
+      this.completedOperations++;
+      if (this.progressEvent(EventType.SUCCESS, `Built ${asset.id}`)) { return false; }
     } catch (e: any) {
       this.failures.push({ asset, error: e });
       this.completedOperations++;
@@ -177,7 +149,7 @@ export class AssetPublishing implements IPublishProgress {
    */
   public async publishEntry(asset: IManifestEntry) {
     try {
-      if (this.progressEvent(EventType.UPLOAD, `${this.startMessagePrefix} ${asset.id}`)) { return false; }
+      if (this.progressEvent(EventType.START, `Publishing ${asset.id}`)) { return false; }
 
       const handler = this.assetHandler(asset);
       await handler.publish();
@@ -187,7 +159,7 @@ export class AssetPublishing implements IPublishProgress {
       }
 
       this.completedOperations++;
-      if (this.progressEvent(EventType.SUCCESS, `${this.successMessagePrefix} ${asset.id}`)) { return false; }
+      if (this.progressEvent(EventType.SUCCESS, `Published ${asset.id}`)) { return false; }
     } catch (e: any) {
       this.failures.push({ asset, error: e });
       this.completedOperations++;
@@ -212,7 +184,7 @@ export class AssetPublishing implements IPublishProgress {
    */
   private async publishAsset(asset: IManifestEntry) {
     try {
-      if (this.progressEvent(EventType.START, `${this.startMessagePrefix} ${asset.id}`)) { return false; }
+      if (this.progressEvent(EventType.START, `Publishing ${asset.id}`)) { return false; }
 
       const handler = this.assetHandler(asset);
 
@@ -229,7 +201,7 @@ export class AssetPublishing implements IPublishProgress {
       }
 
       this.completedOperations++;
-      if (this.progressEvent(EventType.SUCCESS, `${this.successMessagePrefix} ${asset.id}`)) { return false; }
+      if (this.progressEvent(EventType.SUCCESS, `Published ${asset.id}`)) { return false; }
     } catch (e: any) {
       this.failures.push({ asset, error: e });
       this.completedOperations++;

packages/cdk-assets/test/docker-images.test.ts

@@ -247,7 +247,7 @@ describe('with a complete manifest', () => {
   test('Displays an error if the ECR repository cannot be found', async () => {
     aws.mockEcr.describeImages = mockedApiFailure('RepositoryNotFoundException', 'Repository not Found');
 
-    await expect(pub.publish()).rejects.toThrow('Error building and publishing: Repository not Found');
+    await expect(pub.publish()).rejects.toThrow('Error publishing: Repository not Found');
   });
 
   test('successful run does not need to query account ID', async () => {