From 68770395ab4e4cbcfd45c91e803f68dbadcb2c10 Mon Sep 17 00:00:00 2001 From: Hogan Bobertz Date: Tue, 21 Jan 2025 10:59:02 -0500 Subject: [PATCH] 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 --- bin/logging.ts | 9 +- bin/publish.ts | 7 +- lib/private/archive.ts | 10 +- lib/private/asset-handler.ts | 19 ++- lib/private/docker-credentials.ts | 8 +- lib/private/docker.ts | 40 +++--- lib/private/handlers/container-images.ts | 35 +++--- lib/private/handlers/files.ts | 8 +- lib/private/shell.ts | 54 +++++--- lib/progress.ts | 65 ++++++++++ lib/publishing.ts | 27 +++- test/archive.test.ts | 10 +- test/assetpublishing.test.ts | 122 ++++++++++++++++++ test/mock-progress-listener.ts | 44 +++++++ test/shell-logging.test.ts | 152 ++++++++++++----------- 15 files changed, 462 insertions(+), 148 deletions(-) create mode 100644 test/assetpublishing.test.ts create mode 100644 test/mock-progress-listener.ts diff --git a/bin/logging.ts b/bin/logging.ts index 5326feb..d58f3d9 100644 --- a/bin/logging.ts +++ b/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}`); + } } } diff --git a/bin/publish.ts b/bin/publish.ts index 7e451a2..c914058 100644 --- a/bin/publish.ts +++ b/bin/publish.ts @@ -47,10 +47,15 @@ const EVENT_TO_LEVEL: Record = { 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); } } diff --git a/lib/private/archive.ts b/lib/private/archive.ts index baa8589..176786a 100644 --- a/lib/private/archive.ts +++ b/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 { // 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 { @@ -70,7 +70,7 @@ function writeZipFile(directory: string, outputFile: string): Promise { * 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; } diff --git a/lib/private/asset-handler.ts b/lib/private/asset-handler.ts index 36566cc..5d6d847 100644 --- a/lib/private/asset-handler.ts +++ b/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'; diff --git a/lib/private/docker-credentials.ts b/lib/private/docker-credentials.ts index 41b3341..91b7e15 100644 --- a/lib/private/docker-credentials.ts +++ b/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 || []; diff --git a/lib/private/docker.ts b/lib/private/docker.ts index ab519db..5eab65d 100644 --- a/lib/private/docker.ts +++ b/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,7 +128,7 @@ export class Docker { ]; await this.execute(buildCommand, { cwd: options.directory, - quiet: options.quiet, + subprocessOutputDestination: this.subprocessOutputDestination, }); } @@ -131,7 +136,7 @@ export class Docker { * 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( @@ -139,10 +144,10 @@ export class Docker { { 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 = {}) { 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 { - 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; } diff --git a/lib/private/handlers/container-images.ts b/lib/private/handlers/container-images.ts index 7cbf89a..7d3169e 100644 --- a/lib/private/handlers/container-images.ts +++ b/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,8 +83,9 @@ 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) { @@ -94,7 +93,9 @@ export class ContainerImageAssetHandler implements IAssetHandler { } 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 { @@ -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 { @@ -236,7 +240,6 @@ class ContainerImageBuilder { cacheFrom: source.cacheFrom, cacheTo: source.cacheTo, cacheDisabled: source.cacheDisabled, - quiet: this.options.quiet, }); } diff --git a/lib/private/handlers/files.ts b/lib/private/handlers/files.ts index 0758f9f..80d5fb4 100644 --- a/lib/private/handlers/files.ts +++ b/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 { 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', }; } diff --git a/lib/private/shell.ts b/lib/private/shell.ts index 567d695..e9052c3 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -1,11 +1,14 @@ import * as child_process from 'child_process'; +import { SubprocessOutputDestination } from './asset-handler'; -export type Logger = (x: string) => void; +export type ShellEventType = 'open' | 'data_stdout' | 'data_stderr' | 'close'; + +export type ShellEventPublisher = (event: ShellEventType, message: string) => void; export interface ShellOptions extends child_process.SpawnOptions { - readonly quiet?: boolean; - readonly logger?: Logger; + readonly shellEventPublisher: ShellEventPublisher; readonly input?: string; + readonly subprocessOutputDestination?: SubprocessOutputDestination; } /** @@ -14,10 +17,8 @@ export interface ShellOptions extends child_process.SpawnOptions { * Shell function which both prints to stdout and collects the output into a * string. */ -export async function shell(command: string[], options: ShellOptions = {}): Promise { - if (options.logger) { - options.logger(renderCommandLine(command)); - } +export async function shell(command: string[], options: ShellOptions): Promise { + handleShellOutput(renderCommandLine(command), options, 'open'); const child = child_process.spawn(command[0], command.slice(1), { ...options, stdio: [options.input ? 'pipe' : 'ignore', 'pipe', 'pipe'], @@ -32,25 +33,21 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom const stdout = new Array(); const stderr = new Array(); - // Both write to stdout and collect + // Both emit event and collect output child.stdout!.on('data', (chunk) => { - if (!options.quiet) { - process.stdout.write(chunk); - } + handleShellOutput(chunk, options, 'data_stdout'); stdout.push(chunk); }); child.stderr!.on('data', (chunk) => { - if (!options.quiet) { - process.stderr.write(chunk); - } - + handleShellOutput(chunk, options, 'data_stderr'); stderr.push(chunk); }); child.once('error', reject); child.once('close', (code, signal) => { + handleShellOutput(renderCommandLine(command), options, 'close'); if (code === 0) { resolve(Buffer.concat(stdout).toString('utf-8')); } else { @@ -67,6 +64,33 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom }); } +function handleShellOutput( + chunk: Buffer | string, + options: ShellOptions, + shellEventType: ShellEventType +): void { + switch (options.subprocessOutputDestination) { + case 'ignore': + return; + case 'publish': + options.shellEventPublisher(shellEventType, chunk.toString('utf-8')); + break; + case 'stdio': + default: + switch (shellEventType) { + case 'data_stdout': + process.stdout.write(chunk); + break; + case 'data_stderr': + process.stderr.write(chunk); + break; + case 'open': + options.shellEventPublisher(shellEventType, chunk.toString('utf-8')); + break; + } + break; + } +} export type ProcessFailedError = ProcessFailed; class ProcessFailed extends Error { diff --git a/lib/progress.ts b/lib/progress.ts index b2c8e77..603c778 100644 --- a/lib/progress.ts +++ b/lib/progress.ts @@ -1,4 +1,5 @@ import { IManifestEntry } from './asset-manifest'; +import { ShellEventType } from './private/shell'; /** * A listener for progress events from the publisher @@ -58,8 +59,72 @@ export enum EventType { * Another type of detail message */ DEBUG = 'debug', + + /** + * When a shell command is executed. Emits the the command line arguments given to + * the subprocess as a string upon shell execution. + * + * Only emitted when subprocessOutputDestination is set to 'publish' + */ + SHELL_OPEN = 'shell_open', + + /** + * stdout from a shell command + * + * Only emitted when subprocessOutputDestination is set to 'publish' + */ + SHELL_STDOUT = 'shell_stdout', + + /** + * stdout from a shell command + * + * Only emitted when subprocessOutputDestination is set to 'publish' + */ + SHELL_STDERR = 'shell_stderr', + + /** + * When a shell command closes. Emits the the command line arguments given to + * the subprocess as a string upon shell closure. + * + * Only emitted when subprocessOutputDestination is set to 'publish' + */ + SHELL_CLOSE = 'shell_close', +} + +/** + * A helper function to convert shell events to asset progress events + * @param event a shell event + * @returns an {@link EventType} + */ +export function shellEventToEventType(event: ShellEventType): EventType { + switch (event) { + case 'open': + return EventType.SHELL_OPEN; + case 'close': + return EventType.SHELL_CLOSE; + case 'data_stdout': + return EventType.SHELL_STDOUT; + case 'data_stderr': + return EventType.SHELL_STDERR; + } } +/** + * Create a ShellEventPublisher for an {@link EventEmitter} + * + * Returns a ShellEventPublisher that translates ShellEvents into messages + * emitted via the EventEmitter. Uses `shellEventToEventType` to translate + * shell event types to event types + */ +export function shellEventPublisherFromEventEmitter(eventEmitter: EventEmitter) { + return (event: ShellEventType, message: string) => { + const eventType = shellEventToEventType(event); + eventEmitter(eventType, message); + }; +} + +export type EventEmitter = (type: EventType, m: string) => void; + /** * Context object for publishing progress */ diff --git a/lib/publishing.ts b/lib/publishing.ts index cf0293c..f48b4e1 100644 --- a/lib/publishing.ts +++ b/lib/publishing.ts @@ -1,6 +1,11 @@ import { AssetManifest, IManifestEntry } from './asset-manifest'; import { IAws } from './aws'; -import { IAssetHandler, IHandlerHost, type PublishOptions } from './private/asset-handler'; +import { + IAssetHandler, + IHandlerHost, + type PublishOptions, + SubprocessOutputDestination, +} from './private/asset-handler'; import { DockerFactory } from './private/docker'; import { makeAssetHandler } from './private/handlers'; import { pLimit } from './private/p-limit'; @@ -48,11 +53,16 @@ export interface AssetPublishingOptions { readonly publishAssets?: boolean; /** - * Whether to print publishing logs - * - * @default true + * @deprecated use {@link #subprocessOutputDestination} instead */ readonly quiet?: boolean; + + /** + * Where to send output of a subprocesses + * + * @default 'stdio' + */ + subprocessOutputDestination?: SubprocessOutputDestination; } /** @@ -281,8 +291,15 @@ export class AssetPublishing implements IPublishProgress { if (existing) { return existing; } + if (this.options.quiet !== undefined && this.options.subprocessOutputDestination) { + throw new Error( + 'Cannot set both quiet and subprocessOutputDestination. Please use only subprocessOutputDestination' + ); + } + const subprocessOutputDestination = + this.options.subprocessOutputDestination ?? (this.options.quiet ? 'ignore' : 'stdio'); const ret = makeAssetHandler(this.manifest, asset, this.handlerHost, { - quiet: this.options.quiet, + subprocessOutputDestination, }); this.handlerCache.set(asset, ret); return ret; diff --git a/test/archive.test.ts b/test/archive.test.ts index 40bdf8a..c422cc9 100644 --- a/test/archive.test.ts +++ b/test/archive.test.ts @@ -10,7 +10,7 @@ import { rmRfSync } from '../lib/private/fs-extra'; const exec = promisify(_exec); const pathExists = promisify(exists); -function logger(x: string) { +function eventEmitter(x: string) { // eslint-disable-next-line no-console console.log(x); } @@ -21,7 +21,7 @@ test('zipDirectory can take a directory and produce a zip from it', async () => try { const zipFile = path.join(stagingDir, 'output.zip'); const originalDir = path.join(__dirname, 'test-archive'); - await zipDirectory(originalDir, zipFile, logger); + await zipDirectory(originalDir, zipFile, eventEmitter); // unzip and verify that the resulting tree is the same await exec(`unzip ${zipFile}`, { cwd: extractDir }); @@ -56,9 +56,9 @@ test('md5 hash of a zip stays consistent across invocations', async () => { const zipFile1 = path.join(stagingDir, 'output.zip'); const zipFile2 = path.join(stagingDir, 'output.zip'); const originalDir = path.join(__dirname, 'test-archive'); - await zipDirectory(originalDir, zipFile1, logger); + await zipDirectory(originalDir, zipFile1, eventEmitter); await new Promise((ok) => setTimeout(ok, 2000)); // wait 2s - await zipDirectory(originalDir, zipFile2, logger); + await zipDirectory(originalDir, zipFile2, eventEmitter); const hash1 = contentHash(await fs.readFile(zipFile1)); const hash2 = contentHash(await fs.readFile(zipFile2)); @@ -85,7 +85,7 @@ test('zipDirectory follows symlinks', async () => { const originalDir = path.join(__dirname, 'test-archive-follow', 'data'); const zipFile = path.join(stagingDir, 'output.zip'); - await expect(zipDirectory(originalDir, zipFile, logger)).resolves.toBeUndefined(); + await expect(zipDirectory(originalDir, zipFile, eventEmitter)).resolves.toBeUndefined(); await expect(exec(`unzip ${zipFile}`, { cwd: extractDir })).resolves.toBeDefined(); await expect(exec(`diff -bur ${originalDir} ${extractDir}`)).resolves.toBeDefined(); } finally { diff --git a/test/assetpublishing.test.ts b/test/assetpublishing.test.ts new file mode 100644 index 0000000..0b4ca35 --- /dev/null +++ b/test/assetpublishing.test.ts @@ -0,0 +1,122 @@ +import { Manifest } from '@aws-cdk/cloud-assembly-schema'; +import { GetBucketLocationCommand, ListObjectsV2Command } from '@aws-sdk/client-s3'; +import { MockAws, mockS3 } from './mock-aws'; +import mockfs from './mock-fs'; +import { AssetManifest, AssetPublishing, IAws } from '../lib'; +import { MockProgressListener } from './mock-progress-listener'; +import { EventType } from '../lib/progress'; + +describe('Asset Publishing Logging', () => { + let aws: IAws; + let progressListener: MockProgressListener; + + beforeEach(() => { + // Setup mock filesystem with a simple file asset + mockfs({ + '/logging-test/cdk.out/assets.json': JSON.stringify({ + version: Manifest.version(), + files: { + simpleAsset: { + source: { + path: 'simple_file.txt', + }, + destinations: { + testDestination: { + region: 'us-test-1', + assumeRoleArn: 'arn:aws:role:test', + bucketName: 'test-bucket', + objectKey: 'test-key', + }, + }, + }, + }, + }), + '/logging-test/cdk.out/simple_file.txt': 'Test file contents', + }); + + // Reset and configure mocks + aws = new MockAws(); + progressListener = new MockProgressListener(); + + mockS3.on(GetBucketLocationCommand).resolves({}); + mockS3.on(ListObjectsV2Command).resolves({ Contents: undefined }); + }); + + afterEach(() => { + mockfs.restore(); + }); + + test('receiving normal progress events during publishing', async () => { + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/logging-test/cdk.out')), { + aws, + progressListener, + }); + + await pub.publish(); + + const messages: string[] = progressListener.messages.map((msg) => msg.message); + + // Verify progress events + + expect(progressListener.messages.length).toBeGreaterThan(0); + + // Check that progress events contain percentage and asset details + expect(messages).toContainEqual('Publishing simpleAsset:testDestination'); + expect(messages).toContainEqual('Check s3://test-bucket/test-key'); + expect(messages).toContainEqual('Upload s3://test-bucket/test-key'); + expect(messages).toContainEqual('Published simpleAsset:testDestination'); + }); + + test('handles multiple asset destinations with logging', async () => { + // Setup mock filesystem with multiple destinations + mockfs({ + '/multi-dest/cdk.out/assets.json': JSON.stringify({ + version: Manifest.version(), + files: { + multiAsset: { + source: { + path: 'multi_file.txt', + }, + destinations: { + destination1: { + region: 'us-test-1', + assumeRoleArn: 'arn:aws:role:test1', + bucketName: 'test-bucket-1', + objectKey: 'test-key-1', + }, + destination2: { + region: 'us-test-2', + assumeRoleArn: 'arn:aws:role:test2', + bucketName: 'test-bucket-2', + objectKey: 'test-key-2', + }, + }, + }, + }, + }), + '/multi-dest/cdk.out/multi_file.txt': 'Multifile contents', + }); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/multi-dest/cdk.out')), { + aws, + progressListener, + }); + + await pub.publish(); + + // Verify events for both destinations + const startEvents = progressListener.messages.filter((msg) => msg.type === EventType.START); + const completeEvents = progressListener.messages.filter( + (msg) => msg.type === EventType.SUCCESS + ); + + expect(startEvents.length).toBe(2); + expect(completeEvents.length).toBe(2); + + // Check that both destinations are mentioned in events + expect(startEvents[0].message).toContain('multiAsset:destination1'); + expect(startEvents[1].message).toContain('multiAsset:destination2'); + expect(completeEvents[0].message).toContain('multiAsset:destination1'); + expect(completeEvents[1].message).toContain('multiAsset:destination2'); + }); +}); diff --git a/test/mock-progress-listener.ts b/test/mock-progress-listener.ts new file mode 100644 index 0000000..2dd5cd3 --- /dev/null +++ b/test/mock-progress-listener.ts @@ -0,0 +1,44 @@ +import { EventType } from '../lib'; +import { IPublishProgress, IPublishProgressListener } from '../lib/progress'; + +/** + * Represents a logged message with additional metadata purely for testing purposes. + */ +export interface LoggedMessage { + /** + * The {@link EventType} of the logged message + */ + readonly type: EventType; + + /** + * The message text + */ + readonly message: string; + + /** + * The stream this message would have been logged to, if cdk-assets was run from the CLI + */ + readonly stream: 'stdout' | 'stderr'; +} + +/** + * Mock implementation of IPublishProgressListener that captures events for testing purposes. + */ +export class MockProgressListener implements IPublishProgressListener { + public messages: LoggedMessage[] = []; + + onPublishEvent(type: EventType, event: IPublishProgress): void { + this.messages.push({ + type, + message: event.message, + stream: ['open', 'data_stdout', 'close'].includes(type) ? 'stdout' : 'stderr', + }); + } + + /** + * Clear captured messages + */ + clear(): void { + this.messages = []; + } +} diff --git a/test/shell-logging.test.ts b/test/shell-logging.test.ts index 8d41734..4c62769 100644 --- a/test/shell-logging.test.ts +++ b/test/shell-logging.test.ts @@ -1,32 +1,38 @@ import { mockSpawn } from './mock-child_process'; import mockfs from './mock-fs'; +import { MockProgressListener } from './mock-progress-listener'; import { setLogThreshold } from '../bin/logging'; -import { shell } from '../lib/private/shell'; +import { EventType, shellEventToEventType } from '../lib'; +import { shell, ShellEventPublisher } from '../lib/private/shell'; + jest.mock('child_process'); -describe('logging', () => { - let consoleSpy: jest.SpyInstance; +describe('shell', () => { + let progressListener: MockProgressListener; + let shellEventPublisher: ShellEventPublisher; beforeEach(() => { - consoleSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); + progressListener = new MockProgressListener(); + shellEventPublisher = (event, message) => { + const eventType = shellEventToEventType(event); + progressListener.onPublishEvent(eventType, { + message, + percentComplete: 0, + abort: () => {}, + }); + }; mockfs({ '/path/package.json': JSON.stringify({ version: '1.2.3' }), }); }); afterEach(() => { - consoleSpy.mockRestore(); mockfs.restore(); }); test('docker stdout is captured during builds', async () => { // GIVEN setLogThreshold('verbose'); - const processOut = new Array(); - const mockStdout = jest.spyOn(process.stdout, 'write').mockImplementation((chunk) => { - processOut.push(Buffer.isBuffer(chunk) ? chunk.toString() : (chunk as string)); - return true; - }); const expectAllSpawns = mockSpawn({ commandLine: ['docker', 'build', '.'], @@ -34,104 +40,72 @@ describe('logging', () => { }); // WHEN - await shell(['docker', 'build', '.']); + await shell(['docker', 'build', '.'], { + shellEventPublisher, + subprocessOutputDestination: 'publish', + }); // THEN expectAllSpawns(); - await new Promise((resolve) => setImmediate(resolve)); - const hasDockerOutput = processOut.some( - (chunk) => - chunk.includes('Step 1/3') && chunk.includes('Step 2/3') && chunk.includes('Step 3/3') + const dockerOutputMessages = progressListener.messages.filter( + (msg) => + msg.type === EventType.SHELL_STDOUT && + (msg.message.includes('Step 1/3') || + msg.message.includes('Step 2/3') || + msg.message.includes('Step 3/3')) ); - expect(hasDockerOutput).toBe(true); - mockStdout.mockRestore(); + expect(dockerOutputMessages.length).toBeGreaterThan(0); }); - test('stderr is captured and written to process.stderr', async () => { + test('stderr is captured', async () => { // GIVEN - const processErr = new Array(); - const mockStderr = jest.spyOn(process.stderr, 'write').mockImplementation((chunk) => { - processErr.push(Buffer.isBuffer(chunk) ? chunk.toString() : (chunk as string)); - return true; - }); - const expectAllSpawns = mockSpawn({ commandLine: ['docker', 'build', '.'], stderr: 'Warning: Something went wrong', }); // WHEN - await shell(['docker', 'build', '.']); - - // THEN - expectAllSpawns(); - await new Promise((resolve) => setImmediate(resolve)); - - expect(processErr.some((chunk) => chunk.includes('Warning: Something went wrong'))).toBe(true); - mockStderr.mockRestore(); - }); - - test('quiet mode suppresses stdout and stderr', async () => { - // GIVEN - const processOut = new Array(); - const processErr = new Array(); - - const mockStdout = jest.spyOn(process.stdout, 'write').mockImplementation((chunk) => { - processOut.push(Buffer.isBuffer(chunk) ? chunk.toString() : (chunk as string)); - return true; - }); - - const mockStderr = jest.spyOn(process.stderr, 'write').mockImplementation((chunk) => { - processErr.push(Buffer.isBuffer(chunk) ? chunk.toString() : (chunk as string)); - return true; - }); - - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '.'], - stdout: 'Normal output', - stderr: 'Warning output', + await shell(['docker', 'build', '.'], { + shellEventPublisher, + subprocessOutputDestination: 'publish', }); - // WHEN - await shell(['docker', 'build', '.'], { quiet: true }); - // THEN expectAllSpawns(); - await new Promise((resolve) => setImmediate(resolve)); - expect(processOut.length).toBe(0); - expect(processErr.length).toBe(0); + const errorMessages = progressListener.messages.filter((msg) => + msg.message.includes('Warning: Something went wrong') + ); - mockStdout.mockRestore(); - mockStderr.mockRestore(); + expect(errorMessages.length).toBeGreaterThan(0); }); test('handles input option correctly', async () => { // GIVEN const expectedInput = 'some input'; - const processOut = new Array(); - - const mockStdout = jest.spyOn(process.stdout, 'write').mockImplementation((chunk) => { - processOut.push(Buffer.isBuffer(chunk) ? chunk.toString() : (chunk as string)); - return true; - }); const expectAllSpawns = mockSpawn({ commandLine: ['cat'], - stdout: expectedInput, // Echo back the input + stdout: expectedInput, }); // WHEN - await shell(['cat'], { input: expectedInput }); + await shell(['cat'], { + input: expectedInput, + shellEventPublisher, + subprocessOutputDestination: 'publish', + }); // THEN expectAllSpawns(); - await new Promise((resolve) => setImmediate(resolve)); - expect(processOut.some((chunk) => chunk.includes(expectedInput))).toBe(true); - mockStdout.mockRestore(); + const inputMessages = progressListener.messages.filter((msg) => + msg.message.includes(expectedInput) + ); + + expect(inputMessages.length).toBeGreaterThan(0); }); test('throws error on non-zero exit code', async () => { @@ -143,8 +117,40 @@ describe('logging', () => { }); // WHEN/THEN - await expect(shell(['docker', 'build', '.'])).rejects.toThrow('Command failed'); + await expect( + shell(['docker', 'build', '.'], { + shellEventPublisher, + subprocessOutputDestination: 'publish', + }) + ).rejects.toThrow('Command failed'); expectAllSpawns(); + + const errorMessages = progressListener.messages.filter((msg) => + msg.message.includes('Command failed') + ); + + expect(errorMessages.length).toBeGreaterThan(0); + }); + + test('emits proper shell event sequence', async () => { + // GIVEN + const expectAllSpawns = mockSpawn({ + commandLine: ['echo', 'hello'], + stdout: 'hello', + }); + + // WHEN + await shell(['echo', 'hello'], { + shellEventPublisher, + subprocessOutputDestination: 'publish', + }); + + // THEN + expectAllSpawns(); + + // Verify event sequence + const events = progressListener.messages.map((msg) => msg.type); + expect(events).toEqual([EventType.SHELL_OPEN, EventType.SHELL_STDOUT, EventType.SHELL_CLOSE]); }); });