feat: emit all shell logging to publishProgressListener (#295)

Closes #196 

Removes quiet flag and also ensures all events are routed to the
progressListener.

removeD the existing `logger` callback and replaces it with
`shellEventPublisher` which will route the message back to the
configured progressListener if configured. The default behavior is
`stdio` for the new `subprocessOutputDestination` option, which
essentially is the old behavior. Where shells write directly to
stdout/stderr

---------

Co-authored-by: Rico Hermans <rix0rrr@gmail.com>

bin/logging.ts

@@ -18,9 +18,12 @@ export function setLogThreshold(threshold: LogLevel) {
   logThreshold = threshold;
 }
 
-export function log(level: LogLevel, message: string) {
+export function log(level: LogLevel, message: string, stream?: 'stdout' | 'stderr') {
   if (LOG_LEVELS[level] >= LOG_LEVELS[logThreshold]) {
-    // eslint-disable-next-line no-console
-    console.error(`${level.padEnd(7, ' ')}: ${message}`);
+    if (stream === 'stdout') {
+      console.log(`${level.padEnd(7, ' ')}: ${message}`);
+    } else {
+      console.error(`${level.padEnd(7, ' ')}: ${message}`);
+    }
   }
 }

bin/publish.ts

@@ -47,10 +47,15 @@ const EVENT_TO_LEVEL: Record<EventType, LogLevel> = {
   start: 'info',
   success: 'info',
   upload: 'verbose',
+  shell_open: 'verbose',
+  shell_stdout: 'verbose',
+  shell_stderr: 'verbose',
+  shell_close: 'verbose',
 };
 
 class ConsoleProgress implements IPublishProgressListener {
   public onPublishEvent(type: EventType, event: IPublishProgress): void {
-    log(EVENT_TO_LEVEL[type], `[${event.percentComplete}%] ${type}: ${event.message}`);
+    const stream = ['open', 'data_stdout', 'close'].includes(type) ? 'stdout' : 'stderr';
+    log(EVENT_TO_LEVEL[type], `[${event.percentComplete}%] ${type}: ${event.message}`, stream);
   }
 }

lib/private/archive.ts

@@ -6,18 +6,18 @@ import * as glob from 'glob';
 // eslint-disable-next-line @typescript-eslint/no-require-imports
 const archiver = require('archiver');
 
-type Logger = (x: string) => void;
+type EventEmitter = (x: string) => void;
 
 export async function zipDirectory(
   directory: string,
   outputFile: string,
-  logger: Logger
+  eventEmitter: EventEmitter
 ): Promise<void> {
   // We write to a temporary file and rename at the last moment. This is so that if we are
   // interrupted during this process, we don't leave a half-finished file in the target location.
   const temporaryOutputFile = `${outputFile}.${randomString()}._tmp`;
   await writeZipFile(directory, temporaryOutputFile);
-  await moveIntoPlace(temporaryOutputFile, outputFile, logger);
+  await moveIntoPlace(temporaryOutputFile, outputFile, eventEmitter);
 }
 
 function writeZipFile(directory: string, outputFile: string): Promise<void> {
@@ -70,7 +70,7 @@ function writeZipFile(directory: string, outputFile: string): Promise<void> {
  *   file open, so retry a couple of times.
  * - This same function may be called in parallel and be interrupted at any point.
  */
-async function moveIntoPlace(source: string, target: string, logger: Logger) {
+async function moveIntoPlace(source: string, target: string, eventEmitter: EventEmitter) {
   let delay = 100;
   let attempts = 5;
   while (true) {
@@ -82,7 +82,7 @@ async function moveIntoPlace(source: string, target: string, logger: Logger) {
       if (e.code !== 'EPERM' || attempts-- <= 0) {
         throw e;
       }
-      logger(e.message);
+      eventEmitter(e.message);
       await sleep(Math.floor(Math.random() * delay));
       delay *= 2;
     }

lib/private/asset-handler.ts

@@ -1,6 +1,6 @@
 import { DockerFactory } from './docker';
 import { IAws } from '../aws';
-import { EventType } from '../progress';
+import { EventEmitter } from '../progress';
 
 /**
  * Options for publishing an asset.
@@ -40,12 +40,23 @@ export interface IHandlerHost {
   readonly aborted: boolean;
   readonly dockerFactory: DockerFactory;
 
-  emitMessage(type: EventType, m: string): void;
+  emitMessage: EventEmitter;
 }
 
 export interface IHandlerOptions {
   /**
-   * Suppress all output
+   * Where to send output of a subprocesses
+   *
+   * @default 'stdio'
    */
-  readonly quiet?: boolean;
+  readonly subprocessOutputDestination: SubprocessOutputDestination;
 }
+
+/**
+ * The potential destinations for subprocess output.
+ *
+ * 'stdio' will send output directly to stdout/stderr,
+ * 'publish' will publish the output to the {@link IPublishProgressListener},
+ * 'ignore' will ignore the output, and emit it nowhere.
+ */
+export type SubprocessOutputDestination = 'stdio' | 'ignore' | 'publish';

lib/private/docker-credentials.ts

@@ -1,8 +1,8 @@
 import * as fs from 'fs';
 import * as os from 'os';
 import * as path from 'path';
-import { Logger } from './shell';
 import { IAws, IECRClient } from '../aws';
+import { EventEmitter, EventType } from '../progress';
 
 export interface DockerCredentials {
   readonly Username: string;
@@ -106,9 +106,9 @@ export async function fetchDockerLoginCredentials(
   }
 }
 
-export async function obtainEcrCredentials(ecr: IECRClient, logger?: Logger) {
-  if (logger) {
-    logger('Fetching ECR authorization token');
+export async function obtainEcrCredentials(ecr: IECRClient, eventEmitter?: EventEmitter) {
+  if (eventEmitter) {
+    eventEmitter(EventType.DEBUG, 'Fetching ECR authorization token');
   }
 
   const authData = (await ecr.getAuthorizationToken()).authorizationData || [];

lib/private/docker.ts

@@ -2,9 +2,11 @@ import * as fs from 'fs';
 import * as os from 'os';
 import * as path from 'path';
 import { cdkCredentialsConfig, obtainEcrCredentials } from './docker-credentials';
-import { Logger, shell, ShellOptions, ProcessFailedError } from './shell';
+import { shell, ShellOptions, ProcessFailedError } from './shell';
 import { createCriticalSection } from './util';
 import { IECRClient } from '../aws';
+import { SubprocessOutputDestination } from './asset-handler';
+import { EventEmitter, shellEventPublisherFromEventEmitter } from '../progress';
 
 interface BuildOptions {
   readonly directory: string;
@@ -24,12 +26,10 @@ interface BuildOptions {
   readonly cacheFrom?: DockerCacheOption[];
   readonly cacheTo?: DockerCacheOption;
   readonly cacheDisabled?: boolean;
-  readonly quiet?: boolean;
 }
 
 interface PushOptions {
   readonly tag: string;
-  readonly quiet?: boolean;
 }
 
 export interface DockerCredentialsConfig {
@@ -55,14 +55,19 @@ export interface DockerCacheOption {
 export class Docker {
   private configDir: string | undefined = undefined;
 
-  constructor(private readonly logger?: Logger) {}
+  constructor(
+    private readonly eventEmitter: EventEmitter,
+    private readonly subprocessOutputDestination: SubprocessOutputDestination
+  ) {}
 
   /**
    * Whether an image with the given tag exists
    */
   public async exists(tag: string) {
     try {
-      await this.execute(['inspect', tag], { quiet: true });
+      await this.execute(['inspect', tag], {
+        subprocessOutputDestination: 'ignore',
+      });
       return true;
     } catch (e: any) {
       const error: ProcessFailedError = e;
@@ -123,26 +128,26 @@ export class Docker {
     ];
     await this.execute(buildCommand, {
       cwd: options.directory,
-      quiet: options.quiet,
+      subprocessOutputDestination: this.subprocessOutputDestination,
     });
   }
 
   /**
    * Get credentials from ECR and run docker login
    */
   public async login(ecr: IECRClient) {
-    const credentials = await obtainEcrCredentials(ecr);
+    const credentials = await obtainEcrCredentials(ecr, this.eventEmitter);
 
     // Use --password-stdin otherwise docker will complain. Loudly.
     await this.execute(
       ['login', '--username', credentials.username, '--password-stdin', credentials.endpoint],
       {
         input: credentials.password,
 
-        // Need to quiet otherwise Docker will complain
+        // Need to ignore otherwise Docker will complain
         // 'WARNING! Your password will be stored unencrypted'
         // doesn't really matter since it's a token.
-        quiet: true,
+        subprocessOutputDestination: 'ignore',
       }
     );
   }
@@ -152,7 +157,9 @@ export class Docker {
   }
 
   public async push(options: PushOptions) {
-    await this.execute(['push', options.tag], { quiet: options.quiet });
+    await this.execute(['push', options.tag], {
+      subprocessOutputDestination: this.subprocessOutputDestination,
+    });
   }
 
   /**
@@ -194,14 +201,16 @@ export class Docker {
     this.configDir = undefined;
   }
 
-  private async execute(args: string[], options: ShellOptions = {}) {
+  private async execute(args: string[], options: Omit<ShellOptions, 'shellEventPublisher'> = {}) {
     const configArgs = this.configDir ? ['--config', this.configDir] : [];
 
     const pathToCdkAssets = path.resolve(__dirname, '..', '..', 'bin');
+
+    const shellEventPublisher = shellEventPublisherFromEventEmitter(this.eventEmitter);
     try {
       await shell([getDockerCmd(), ...configArgs, ...args], {
-        logger: this.logger,
         ...options,
+        shellEventPublisher: shellEventPublisher,
         env: {
           ...process.env,
           ...options.env,
@@ -234,7 +243,8 @@ export class Docker {
 export interface DockerFactoryOptions {
   readonly repoUri: string;
   readonly ecr: IECRClient;
-  readonly logger: (m: string) => void;
+  readonly eventEmitter: EventEmitter;
+  readonly subprocessOutputDestination: SubprocessOutputDestination;
 }
 
 /**
@@ -249,7 +259,7 @@ export class DockerFactory {
    * Gets a Docker instance for building images.
    */
   public async forBuild(options: DockerFactoryOptions): Promise<Docker> {
-    const docker = new Docker(options.logger);
+    const docker = new Docker(options.eventEmitter, options.subprocessOutputDestination);
 
     // Default behavior is to login before build so that the Dockerfile can reference images in the ECR repo
     // However, if we're in a pipelines environment (for example),
@@ -268,7 +278,7 @@ export class DockerFactory {
    * Gets a Docker instance for pushing images to ECR.
    */
   public async forEcrPush(options: DockerFactoryOptions) {
-    const docker = new Docker(options.logger);
+    const docker = new Docker(options.eventEmitter, options.subprocessOutputDestination);
     await this.loginOncePerDestination(docker, options);
     return docker;
   }

lib/private/handlers/container-images.ts

@@ -3,7 +3,7 @@ import { DockerImageDestination } from '@aws-cdk/cloud-assembly-schema';
 import { destinationToClientOptions } from './client-options';
 import { DockerImageManifestEntry } from '../../asset-manifest';
 import type { IECRClient } from '../../aws';
-import { EventType } from '../../progress';
+import { EventType, shellEventPublisherFromEventEmitter } from '../../progress';
 import { IAssetHandler, IHandlerHost, IHandlerOptions } from '../asset-handler';
 import { Docker } from '../docker';
 import { replaceAwsPlaceholders } from '../placeholders';
@@ -38,18 +38,16 @@ export class ContainerImageAssetHandler implements IAssetHandler {
 
     const dockerForBuilding = await this.host.dockerFactory.forBuild({
       repoUri: initOnce.repoUri,
-      logger: (m: string) => this.host.emitMessage(EventType.DEBUG, m),
+      eventEmitter: (m: string) => this.host.emitMessage(EventType.DEBUG, m),
       ecr: initOnce.ecr,
+      subprocessOutputDestination: this.options.subprocessOutputDestination,
     });
 
     const builder = new ContainerImageBuilder(
       dockerForBuilding,
       this.workDir,
       this.asset,
-      this.host,
-      {
-        quiet: this.options.quiet,
-      }
+      this.host
     );
     const localTagName = await builder.build();
 
@@ -85,16 +83,19 @@ export class ContainerImageAssetHandler implements IAssetHandler {
 
     const dockerForPushing = await this.host.dockerFactory.forEcrPush({
       repoUri: initOnce.repoUri,
-      logger: (m: string) => this.host.emitMessage(EventType.DEBUG, m),
+      eventEmitter: this.host.emitMessage,
       ecr: initOnce.ecr,
+      subprocessOutputDestination: this.options.subprocessOutputDestination,
     });
 
     if (this.host.aborted) {
       return;
     }
 
     this.host.emitMessage(EventType.UPLOAD, `Push ${initOnce.imageUri}`);
-    await dockerForPushing.push({ tag: initOnce.imageUri, quiet: this.options.quiet });
+    await dockerForPushing.push({
+      tag: initOnce.imageUri,
+    });
   }
 
   private async initOnce(
@@ -152,17 +153,12 @@ export class ContainerImageAssetHandler implements IAssetHandler {
   }
 }
 
-interface ContainerImageBuilderOptions {
-  readonly quiet?: boolean;
-}
-
 class ContainerImageBuilder {
   constructor(
     private readonly docker: Docker,
     private readonly workDir: string,
     private readonly asset: DockerImageManifestEntry,
-    private readonly host: IHandlerHost,
-    private readonly options: ContainerImageBuilderOptions
+    private readonly host: IHandlerHost
   ) {}
 
   async build(): Promise<string | undefined> {
@@ -208,7 +204,15 @@ class ContainerImageBuilder {
       return undefined;
     }
 
-    return (await shell(executable, { cwd: assetPath, quiet: true })).trim();
+    const shellEventPublisher = shellEventPublisherFromEventEmitter(this.host.emitMessage);
+
+    return (
+      await shell(executable, {
+        cwd: assetPath,
+        shellEventPublisher,
+        subprocessOutputDestination: 'ignore',
+      })
+    ).trim();
   }
 
   private async buildImage(localTagName: string): Promise<void> {
@@ -236,7 +240,6 @@ class ContainerImageBuilder {
       cacheFrom: source.cacheFrom,
       cacheTo: source.cacheTo,
       cacheDisabled: source.cacheDisabled,
-      quiet: this.options.quiet,
     });
   }
 

lib/private/handlers/files.ts

@@ -6,7 +6,7 @@ import { destinationToClientOptions } from './client-options';
 import { FileManifestEntry } from '../../asset-manifest';
 import { IS3Client } from '../../aws';
 import { PutObjectCommandInput } from '../../aws-types';
-import { EventType } from '../../progress';
+import { EventType, shellEventPublisherFromEventEmitter } from '../../progress';
 import { zipDirectory } from '../archive';
 import { IAssetHandler, IHandlerHost, type PublishOptions } from '../asset-handler';
 import { pathExists } from '../fs-extra';
@@ -203,8 +203,12 @@ export class FileAssetHandler implements IAssetHandler {
   private async externalPackageFile(executable: string[]): Promise<PackagedFileAsset> {
     this.host.emitMessage(EventType.BUILD, `Building asset source using command: '${executable}'`);
 
+    const shellEventPublisher = shellEventPublisherFromEventEmitter(this.host.emitMessage);
+
     return {
-      packagedPath: (await shell(executable, { quiet: true })).trim(),
+      packagedPath: (
+        await shell(executable, { subprocessOutputDestination: 'ignore', shellEventPublisher })
+      ).trim(),
       contentType: 'application/zip',
     };
   }