From 98ebc390e98cc12ce1124fdd9aa4366c7da30bee Mon Sep 17 00:00:00 2001 From: HBobertz Date: Tue, 3 Dec 2024 02:15:40 -0500 Subject: [PATCH 01/16] initial docker log capturing --- lib/private/docker.ts | 70 ++++++++++++++++++++++++++++++++----- lib/private/shell.ts | 14 ++++++-- test/docker-logging.test.ts | 38 ++++++++++++++++++++ test/mock-child_process.ts | 4 +++ 4 files changed, 115 insertions(+), 11 deletions(-) create mode 100644 test/docker-logging.test.ts diff --git a/lib/private/docker.ts b/lib/private/docker.ts index ab519db..665fd84 100644 --- a/lib/private/docker.ts +++ b/lib/private/docker.ts @@ -5,6 +5,7 @@ import { cdkCredentialsConfig, obtainEcrCredentials } from './docker-credentials import { Logger, shell, ShellOptions, ProcessFailedError } from './shell'; import { createCriticalSection } from './util'; import { IECRClient } from '../aws'; +import { IPublishProgressListener, EventType } from '../progress'; interface BuildOptions { readonly directory: string; @@ -52,10 +53,43 @@ export interface DockerCacheOption { readonly params?: { [key: string]: string }; } +export interface DockerOptions { + readonly logger?: Logger; + readonly progressListener?: IPublishProgressListener; +} + +interface LineStreamHandler { + processLine(line: string, isError: boolean): void; +} + +class LineStreamWrapper implements LineStreamHandler { + private buffer = ''; + + constructor(private readonly callback: (line: string, isError: boolean) => void) {} + + processLine(chunk: string, isError: boolean) { + // Add new chunk to existing buffer + this.buffer += chunk; + + // Process complete lines + let newlineIndex; + while ((newlineIndex = this.buffer.indexOf('\n')) !== -1) { + // Extract the complete line + const line = this.buffer.slice(0, newlineIndex); + // Keep the rest in the buffer + this.buffer = this.buffer.slice(newlineIndex + 1); + // Send the line to the callback if it's not empty + if (line.trim()) { + this.callback(line, isError); + } + } + } +} + export class Docker { private configDir: string | undefined = undefined; - constructor(private readonly logger?: Logger) {} + constructor(private readonly options?: DockerOptions) {} /** * Whether an image with the given tag exists @@ -194,18 +228,31 @@ export class Docker { this.configDir = undefined; } - private async execute(args: string[], options: ShellOptions = {}) { + private async execute(args: string[], shellOptions: ShellOptions = {}) { const configArgs = this.configDir ? ['--config', this.configDir] : []; const pathToCdkAssets = path.resolve(__dirname, '..', '..', 'bin'); try { await shell([getDockerCmd(), ...configArgs, ...args], { - logger: this.logger, - ...options, + logger: this.options?.logger, + ...shellOptions, env: { ...process.env, - ...options.env, - PATH: `${pathToCdkAssets}${path.delimiter}${options.env?.PATH ?? process.env.PATH}`, + ...shellOptions.env, + PATH: `${pathToCdkAssets}${path.delimiter}${shellOptions.env?.PATH ?? process.env.PATH}`, + }, + outputListener: (data: string, isError: boolean) => { + if (this.options?.progressListener && !shellOptions.quiet) { + this.options.progressListener.onPublishEvent( + isError ? EventType.FAIL : EventType.DEBUG, + { + message: `[docker ${isError ? 'stderr' : 'stdout'}] ${data}`, + currentAsset: undefined, + percentComplete: -1, + abort: () => {}, + } + ); + } }, }); } catch (e: any) { @@ -235,6 +282,7 @@ export interface DockerFactoryOptions { readonly repoUri: string; readonly ecr: IECRClient; readonly logger: (m: string) => void; + readonly progressListener?: IPublishProgressListener; } /** @@ -249,7 +297,10 @@ 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({ + logger: options.logger, + progressListener: options.progressListener, + }); // 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 +319,10 @@ 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({ + logger: options.logger, + progressListener: options.progressListener, + }); await this.loginOncePerDestination(docker, options); return docker; } diff --git a/lib/private/shell.ts b/lib/private/shell.ts index 567d695..7a55b6f 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -6,6 +6,7 @@ export interface ShellOptions extends child_process.SpawnOptions { readonly quiet?: boolean; readonly logger?: Logger; readonly input?: string; + readonly outputListener?: (data: string, isError: boolean) => void; } /** @@ -35,16 +36,23 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom // Both write to stdout and collect child.stdout!.on('data', (chunk) => { if (!options.quiet) { - process.stdout.write(chunk); + if (options.outputListener) { + options.outputListener(chunk.toString(), false); + } else { + process.stdout.write(chunk); + } } stdout.push(chunk); }); child.stderr!.on('data', (chunk) => { if (!options.quiet) { - process.stderr.write(chunk); + if (options.outputListener) { + options.outputListener(chunk.toString(), true); + } else { + process.stderr.write(chunk); + } } - stderr.push(chunk); }); diff --git a/test/docker-logging.test.ts b/test/docker-logging.test.ts new file mode 100644 index 0000000..a3f1965 --- /dev/null +++ b/test/docker-logging.test.ts @@ -0,0 +1,38 @@ +// test/docker-logging.test.ts +jest.mock('child_process'); + +import { FakeListener } from './fake-listener'; +import { mockSpawn } from './mock-child_process'; +import { Docker } from '../lib/private/docker'; + +describe('Docker logging', () => { + test('captures stdout and stderr in progress listener', async () => { + const progressListener = new FakeListener(); + const docker = new Docker({ + progressListener: progressListener, + }); + + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + stderr: 'stderr test string\n', + }); + + // Use the internal execute method directly for testing + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + + // Verify both stdout and stderr were captured + expect(progressListener.messages).toEqual([ + '[docker stdout] stdout test string\n', + '[docker stderr] stderr test string\n', + ]); + + expectAllSpawns(progressListener.messages[0]); + + expectAllSpawns(); + }); +}); + +function fakeLog(message: string): void { + // do nothing +} diff --git a/test/mock-child_process.ts b/test/mock-child_process.ts index 4588650..c0efc6f 100644 --- a/test/mock-child_process.ts +++ b/test/mock-child_process.ts @@ -10,6 +10,7 @@ export interface Invocation { cwd?: string; exitCode?: number; stdout?: string; + stderr?: string; /** * Only match a prefix of the command (don't care about the details of the arguments) @@ -48,6 +49,9 @@ export function mockSpawn(...invocations: Invocation[]): () => void { if (invocation.stdout) { mockEmit(child.stdout, 'data', Buffer.from(invocation.stdout)); } + if (invocation.stderr) { + mockEmit(child.stderr, 'data', Buffer.from(invocation.stderr)); + } mockEmit(child, 'close', invocation.exitCode ?? 0); return child; From 081ce2da420095fc1055d717d5bf3c4124994241 Mon Sep 17 00:00:00 2001 From: HBobertz Date: Tue, 3 Dec 2024 02:32:10 -0500 Subject: [PATCH 02/16] add better testing and error emission --- lib/private/docker.ts | 65 +++++++++---------- test/docker-logging.test.ts | 120 ++++++++++++++++++++++++++++++++---- test/fake-listener.ts | 3 +- test/mock-child_process.ts | 20 +++--- 4 files changed, 149 insertions(+), 59 deletions(-) diff --git a/lib/private/docker.ts b/lib/private/docker.ts index 665fd84..7b02248 100644 --- a/lib/private/docker.ts +++ b/lib/private/docker.ts @@ -58,33 +58,28 @@ export interface DockerOptions { readonly progressListener?: IPublishProgressListener; } -interface LineStreamHandler { - processLine(line: string, isError: boolean): void; -} +// interface LineStreamHandler { +// processLine(line: string, isError: boolean): void; +// } -class LineStreamWrapper implements LineStreamHandler { - private buffer = ''; - - constructor(private readonly callback: (line: string, isError: boolean) => void) {} - - processLine(chunk: string, isError: boolean) { - // Add new chunk to existing buffer - this.buffer += chunk; - - // Process complete lines - let newlineIndex; - while ((newlineIndex = this.buffer.indexOf('\n')) !== -1) { - // Extract the complete line - const line = this.buffer.slice(0, newlineIndex); - // Keep the rest in the buffer - this.buffer = this.buffer.slice(newlineIndex + 1); - // Send the line to the callback if it's not empty - if (line.trim()) { - this.callback(line, isError); - } - } - } -} +// class LineStreamWrapper implements LineStreamHandler { +// private buffer = ''; + +// constructor(private readonly callback: (line: string, isError: boolean) => void) {} + +// processLine(chunk: string, isError: boolean) { +// this.buffer += chunk; + +// let newlineIndex; +// while ((newlineIndex = this.buffer.indexOf('\n')) !== -1) { +// const line = this.buffer.slice(0, newlineIndex); +// this.buffer = this.buffer.slice(newlineIndex + 1); +// if (line.trim()) { +// this.callback(line, isError); +// } +// } +// } +// } export class Docker { private configDir: string | undefined = undefined; @@ -242,16 +237,14 @@ export class Docker { PATH: `${pathToCdkAssets}${path.delimiter}${shellOptions.env?.PATH ?? process.env.PATH}`, }, outputListener: (data: string, isError: boolean) => { - if (this.options?.progressListener && !shellOptions.quiet) { - this.options.progressListener.onPublishEvent( - isError ? EventType.FAIL : EventType.DEBUG, - { - message: `[docker ${isError ? 'stderr' : 'stdout'}] ${data}`, - currentAsset: undefined, - percentComplete: -1, - abort: () => {}, - } - ); + if (this.options?.progressListener && !shellOptions.quiet && data.trim().length > 0) { + const eventType = isError ? EventType.FAIL : EventType.DEBUG; + this.options.progressListener.onPublishEvent(eventType, { + message: `[docker ${isError ? 'stderr' : 'stdout'}] ${data}`, + currentAsset: undefined, + percentComplete: -1, + abort: () => {}, + }); } }, }); diff --git a/test/docker-logging.test.ts b/test/docker-logging.test.ts index a3f1965..655554b 100644 --- a/test/docker-logging.test.ts +++ b/test/docker-logging.test.ts @@ -4,35 +4,131 @@ jest.mock('child_process'); import { FakeListener } from './fake-listener'; import { mockSpawn } from './mock-child_process'; import { Docker } from '../lib/private/docker'; +import { EventType } from '../lib/progress'; describe('Docker logging', () => { - test('captures stdout and stderr in progress listener', async () => { - const progressListener = new FakeListener(); - const docker = new Docker({ + let progressListener: FakeListener; + let docker: Docker; + + beforeEach(() => { + progressListener = new FakeListener(); + docker = new Docker({ progressListener: progressListener, }); + }); + test('captures stdout as DEBUG events', async () => { const expectAllSpawns = mockSpawn({ commandLine: ['docker', 'build', '--tag', 'test-image', '.'], stdout: 'stdout test string\n', - stderr: 'stderr test string\n', }); - // Use the internal execute method directly for testing await (docker as any).execute(['build', '--tag', 'test-image', '.']); - // Verify both stdout and stderr were captured + expect(progressListener.types).toEqual([EventType.DEBUG]); + expect(progressListener.messages).toEqual(['[docker stdout] stdout test string\n']); + + expectAllSpawns(); + }); + + test('captures stderr as FAIL events', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stderr: 'error test string\n', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + // Give time for events to process + await new Promise((resolve) => setTimeout(resolve, 50)); + + expect(progressListener.types).toEqual([EventType.FAIL]); + expect(progressListener.messages).toEqual(['[docker stderr] error test string\n']); + + expectAllSpawns(); + }); + + test('captures both stdout and stderr with correct event types', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + stderr: 'error test string\n', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + // Give time for events to process + await new Promise((resolve) => setTimeout(resolve, 50)); + + expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); expect(progressListener.messages).toEqual([ '[docker stdout] stdout test string\n', - '[docker stderr] stderr test string\n', + '[docker stderr] error test string\n', ]); - expectAllSpawns(progressListener.messages[0]); + expectAllSpawns(); + }); + + test('does not emit events when quiet option is true', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + stderr: 'error test string\n', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.'], { quiet: true }); + + expect(progressListener.types).toHaveLength(0); + expect(progressListener.messages).toHaveLength(0); expectAllSpawns(); }); -}); -function fakeLog(message: string): void { - // do nothing -} + test('handles empty stdout/stderr without emitting events', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: '', + stderr: '', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + + expect(progressListener.types).toHaveLength(0); + expect(progressListener.messages).toHaveLength(0); + + expectAllSpawns(); + }); + + test('preserves multiline output formatting', async () => { + const multilineStdout = 'Line 1\nLine 2\nLine 3\n'; + const multilineStderr = 'Error 1\nError 2\n'; + + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: multilineStdout, + stderr: multilineStderr, + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + + expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); + expect(progressListener.messages).toEqual([ + '[docker stdout] Line 1\nLine 2\nLine 3\n', + '[docker stderr] Error 1\nError 2\n', + ]); + + expectAllSpawns(); + }); + + test('works without a progress listener', async () => { + const dockerNoListener = new Docker({}); + + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + stderr: 'error test string\n', + }); + + await (dockerNoListener as any).execute(['build', '--tag', 'test-image', '.']); + + expectAllSpawns(); + }); +}); diff --git a/test/fake-listener.ts b/test/fake-listener.ts index 1b02685..6bd73cc 100644 --- a/test/fake-listener.ts +++ b/test/fake-listener.ts @@ -6,7 +6,8 @@ export class FakeListener implements IPublishProgressListener { constructor(private readonly doAbort = false) {} - public onPublishEvent(_type: EventType, event: IPublishProgress): void { + public onPublishEvent(type: EventType, event: IPublishProgress): void { + this.types.push(type); this.messages.push(event.message); if (this.doAbort) { diff --git a/test/mock-child_process.ts b/test/mock-child_process.ts index c0efc6f..e1994a1 100644 --- a/test/mock-child_process.ts +++ b/test/mock-child_process.ts @@ -11,30 +11,23 @@ export interface Invocation { exitCode?: number; stdout?: string; stderr?: string; - - /** - * Only match a prefix of the command (don't care about the details of the arguments) - */ prefix?: boolean; } export function mockSpawn(...invocations: Invocation[]): () => void { let mock = child_process.spawn as any; for (const _invocation of invocations) { - const invocation = _invocation; // Mirror into variable for closure + const invocation = _invocation; mock = mock.mockImplementationOnce( (binary: string, args: string[], options: child_process.SpawnOptions) => { if (invocation.prefix) { - // Match command line prefix expect([binary, ...args].slice(0, invocation.commandLine.length)).toEqual( invocation.commandLine ); } else { - // Match full command line expect([binary, ...args]).toEqual(invocation.commandLine); } - // Prune the temp directory off here if (invocation.cwd != null) { expect(invocation.cwd).toEqual((options.cwd as string).slice(-invocation.cwd.length)); } @@ -50,9 +43,16 @@ export function mockSpawn(...invocations: Invocation[]): () => void { mockEmit(child.stdout, 'data', Buffer.from(invocation.stdout)); } if (invocation.stderr) { - mockEmit(child.stderr, 'data', Buffer.from(invocation.stderr)); + // Send stderr data after stdout + setTimeout(() => { + if (invocation.stderr) { + mockEmit(child.stderr, 'data', Buffer.from(invocation.stderr)); + } + }, 10); } - mockEmit(child, 'close', invocation.exitCode ?? 0); + setTimeout(() => { + mockEmit(child, 'close', invocation.exitCode ?? 0); + }, 20); return child; } From 1b5a38bf4da89072dc6fc5c5d72b6cea7cbf4cef Mon Sep 17 00:00:00 2001 From: HBobertz Date: Sat, 7 Dec 2024 14:48:42 -0500 Subject: [PATCH 03/16] remove unnecessary stuff --- lib/private/docker.ts | 23 ----------------------- test/mock-child_process.ts | 12 ++++-------- 2 files changed, 4 insertions(+), 31 deletions(-) diff --git a/lib/private/docker.ts b/lib/private/docker.ts index 7b02248..c90bc35 100644 --- a/lib/private/docker.ts +++ b/lib/private/docker.ts @@ -58,29 +58,6 @@ export interface DockerOptions { readonly progressListener?: IPublishProgressListener; } -// interface LineStreamHandler { -// processLine(line: string, isError: boolean): void; -// } - -// class LineStreamWrapper implements LineStreamHandler { -// private buffer = ''; - -// constructor(private readonly callback: (line: string, isError: boolean) => void) {} - -// processLine(chunk: string, isError: boolean) { -// this.buffer += chunk; - -// let newlineIndex; -// while ((newlineIndex = this.buffer.indexOf('\n')) !== -1) { -// const line = this.buffer.slice(0, newlineIndex); -// this.buffer = this.buffer.slice(newlineIndex + 1); -// if (line.trim()) { -// this.callback(line, isError); -// } -// } -// } -// } - export class Docker { private configDir: string | undefined = undefined; diff --git a/test/mock-child_process.ts b/test/mock-child_process.ts index e1994a1..ee5e86d 100644 --- a/test/mock-child_process.ts +++ b/test/mock-child_process.ts @@ -44,15 +44,11 @@ export function mockSpawn(...invocations: Invocation[]): () => void { } if (invocation.stderr) { // Send stderr data after stdout - setTimeout(() => { - if (invocation.stderr) { - mockEmit(child.stderr, 'data', Buffer.from(invocation.stderr)); - } - }, 10); + if (invocation.stderr) { + mockEmit(child.stderr, 'data', Buffer.from(invocation.stderr)); + } } - setTimeout(() => { - mockEmit(child, 'close', invocation.exitCode ?? 0); - }, 20); + mockEmit(child, 'close', invocation.exitCode ?? 0); return child; } From 057644a05d2735b7d46db5af684dc6708f1e7233 Mon Sep 17 00:00:00 2001 From: HBobertz Date: Sun, 8 Dec 2024 17:01:30 -0500 Subject: [PATCH 04/16] updated log capturing --- bin/cdk-assets.ts | 24 +- bin/logging.ts | 70 ++++- bin/publish.ts | 6 +- lib/private/docker.ts | 14 +- lib/private/shell.ts | 26 +- lib/progress.ts | 2 +- test/docker-logging.test.ts | 134 ---------- test/logging.test.ts | 494 ++++++++++++++++++++++++++++++++++++ 8 files changed, 596 insertions(+), 174 deletions(-) delete mode 100644 test/docker-logging.test.ts create mode 100644 test/logging.test.ts diff --git a/bin/cdk-assets.ts b/bin/cdk-assets.ts index 7135659..ab334eb 100644 --- a/bin/cdk-assets.ts +++ b/bin/cdk-assets.ts @@ -1,10 +1,30 @@ +// Modified bin/cdk-assets.ts import * as yargs from 'yargs'; import { list } from './list'; -import { setLogThreshold, VERSION } from './logging'; +import { log, setGlobalProgressListener, setLogThreshold, VERSION } from './logging'; import { publish } from './publish'; -import { AssetManifest } from '../lib'; +import { AssetManifest, EventType, IPublishProgress, IPublishProgressListener } from '../lib'; + +class DefaultProgressListener implements IPublishProgressListener { + public onPublishEvent(type: EventType, event: IPublishProgress): void { + // Map event types to log levels + switch (type) { + case EventType.FAIL: + log('error', event.message); + break; + case EventType.DEBUG: + log('verbose', event.message); + break; + default: + log('info', event.message); + } + } +} async function main() { + const defaultListener = new DefaultProgressListener(); + setGlobalProgressListener(defaultListener); + const argv = yargs .usage('$0 [args]') .option('verbose', { diff --git a/bin/logging.ts b/bin/logging.ts index 5326feb..385cf67 100644 --- a/bin/logging.ts +++ b/bin/logging.ts @@ -1,14 +1,19 @@ +// Modified bin/logging.ts to integrate with progress interface import * as fs from 'fs'; import * as path from 'path'; - -export type LogLevel = 'verbose' | 'info' | 'error'; -let logThreshold: LogLevel = 'info'; +import { EventType, IPublishProgress, IPublishProgressListener } from '../lib/progress'; export const VERSION = JSON.parse( fs.readFileSync(path.join(__dirname, '..', 'package.json'), { encoding: 'utf-8' }) ).version; -const LOG_LEVELS: Record = { +export type LogLevel = 'verbose' | 'info' | 'error'; +let logThreshold: LogLevel = 'info'; + +// Global progress listener that can be set +let globalProgressListener: IPublishProgressListener | undefined; + +export const LOG_LEVELS: Record = { verbose: 1, info: 2, error: 3, @@ -18,9 +23,62 @@ export function setLogThreshold(threshold: LogLevel) { logThreshold = threshold; } -export function log(level: LogLevel, message: string) { +export function setGlobalProgressListener(listener: IPublishProgressListener) { + globalProgressListener = listener; +} + +// Convert log level to event type +function logLevelToEventType(level: LogLevel): EventType { + switch (level) { + case 'error': + return EventType.FAIL; + case 'verbose': + return EventType.DEBUG; + default: + return EventType.DEBUG; + } +} + +export function log(level: LogLevel, message: string, percentComplete?: number) { if (LOG_LEVELS[level] >= LOG_LEVELS[logThreshold]) { - // eslint-disable-next-line no-console + // Still write to stderr for backward compatibility console.error(`${level.padEnd(7, ' ')}: ${message}`); + + // Also send to progress listener if configured + if (globalProgressListener) { + const progressEvent: IPublishProgress = { + message: `${message}`, + percentComplete: percentComplete, + abort: () => {}, + }; + globalProgressListener.onPublishEvent(logLevelToEventType(level), progressEvent); + } + } +} + +export class ShellOutputHandler { + constructor(private readonly progressListener?: IPublishProgressListener) {} + + public handleOutput(chunk: any, isError: boolean = false) { + const text = chunk.toString(); + + // Write to standard streams for backward compatibility + if (isError) { + process.stderr.write(text); + } else { + process.stdout.write(text); + } + + // Also send to progress listener if configured + if (this.progressListener) { + const progressEvent: IPublishProgress = { + message: text, + abort: () => {}, + }; + this.progressListener.onPublishEvent( + isError ? EventType.FAIL : EventType.DEBUG, + progressEvent + ); + } } } diff --git a/bin/publish.ts b/bin/publish.ts index 7e451a2..c7158d1 100644 --- a/bin/publish.ts +++ b/bin/publish.ts @@ -51,6 +51,10 @@ const EVENT_TO_LEVEL: Record = { class ConsoleProgress implements IPublishProgressListener { public onPublishEvent(type: EventType, event: IPublishProgress): void { - log(EVENT_TO_LEVEL[type], `[${event.percentComplete}%] ${type}: ${event.message}`); + log( + EVENT_TO_LEVEL[type], + `[${event.percentComplete}%] ${type}: ${event.message}`, + event.percentComplete + ); } } diff --git a/lib/private/docker.ts b/lib/private/docker.ts index c90bc35..fbdd25f 100644 --- a/lib/private/docker.ts +++ b/lib/private/docker.ts @@ -5,7 +5,7 @@ import { cdkCredentialsConfig, obtainEcrCredentials } from './docker-credentials import { Logger, shell, ShellOptions, ProcessFailedError } from './shell'; import { createCriticalSection } from './util'; import { IECRClient } from '../aws'; -import { IPublishProgressListener, EventType } from '../progress'; +import { IPublishProgressListener } from '../progress'; interface BuildOptions { readonly directory: string; @@ -213,17 +213,7 @@ export class Docker { ...shellOptions.env, PATH: `${pathToCdkAssets}${path.delimiter}${shellOptions.env?.PATH ?? process.env.PATH}`, }, - outputListener: (data: string, isError: boolean) => { - if (this.options?.progressListener && !shellOptions.quiet && data.trim().length > 0) { - const eventType = isError ? EventType.FAIL : EventType.DEBUG; - this.options.progressListener.onPublishEvent(eventType, { - message: `[docker ${isError ? 'stderr' : 'stdout'}] ${data}`, - currentAsset: undefined, - percentComplete: -1, - abort: () => {}, - }); - } - }, + progressListener: this.options?.progressListener, }); } catch (e: any) { if (e.code === 'ENOENT') { diff --git a/lib/private/shell.ts b/lib/private/shell.ts index 7a55b6f..17dfc69 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -1,4 +1,6 @@ import * as child_process from 'child_process'; +import { ShellOutputHandler } from '../../bin/logging'; +import { IPublishProgressListener } from '../progress'; export type Logger = (x: string) => void; @@ -6,19 +8,16 @@ export interface ShellOptions extends child_process.SpawnOptions { readonly quiet?: boolean; readonly logger?: Logger; readonly input?: string; - readonly outputListener?: (data: string, isError: boolean) => void; + readonly progressListener?: IPublishProgressListener; } -/** - * OS helpers - * - * 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)); } + + const outputHandler = new ShellOutputHandler(options.progressListener); + const child = child_process.spawn(command[0], command.slice(1), { ...options, stdio: [options.input ? 'pipe' : 'ignore', 'pipe', 'pipe'], @@ -33,25 +32,16 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom const stdout = new Array(); const stderr = new Array(); - // Both write to stdout and collect child.stdout!.on('data', (chunk) => { if (!options.quiet) { - if (options.outputListener) { - options.outputListener(chunk.toString(), false); - } else { - process.stdout.write(chunk); - } + outputHandler.handleOutput(chunk, false); } stdout.push(chunk); }); child.stderr!.on('data', (chunk) => { if (!options.quiet) { - if (options.outputListener) { - options.outputListener(chunk.toString(), true); - } else { - process.stderr.write(chunk); - } + outputHandler.handleOutput(chunk, true); } stderr.push(chunk); }); diff --git a/lib/progress.ts b/lib/progress.ts index b2c8e77..d9f24b8 100644 --- a/lib/progress.ts +++ b/lib/progress.ts @@ -77,7 +77,7 @@ export interface IPublishProgress { /** * How far along are we? */ - readonly percentComplete: number; + readonly percentComplete?: number; /** * Abort the current publishing operation diff --git a/test/docker-logging.test.ts b/test/docker-logging.test.ts deleted file mode 100644 index 655554b..0000000 --- a/test/docker-logging.test.ts +++ /dev/null @@ -1,134 +0,0 @@ -// test/docker-logging.test.ts -jest.mock('child_process'); - -import { FakeListener } from './fake-listener'; -import { mockSpawn } from './mock-child_process'; -import { Docker } from '../lib/private/docker'; -import { EventType } from '../lib/progress'; - -describe('Docker logging', () => { - let progressListener: FakeListener; - let docker: Docker; - - beforeEach(() => { - progressListener = new FakeListener(); - docker = new Docker({ - progressListener: progressListener, - }); - }); - - test('captures stdout as DEBUG events', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - - expect(progressListener.types).toEqual([EventType.DEBUG]); - expect(progressListener.messages).toEqual(['[docker stdout] stdout test string\n']); - - expectAllSpawns(); - }); - - test('captures stderr as FAIL events', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stderr: 'error test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - // Give time for events to process - await new Promise((resolve) => setTimeout(resolve, 50)); - - expect(progressListener.types).toEqual([EventType.FAIL]); - expect(progressListener.messages).toEqual(['[docker stderr] error test string\n']); - - expectAllSpawns(); - }); - - test('captures both stdout and stderr with correct event types', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - stderr: 'error test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - // Give time for events to process - await new Promise((resolve) => setTimeout(resolve, 50)); - - expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); - expect(progressListener.messages).toEqual([ - '[docker stdout] stdout test string\n', - '[docker stderr] error test string\n', - ]); - - expectAllSpawns(); - }); - - test('does not emit events when quiet option is true', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - stderr: 'error test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.'], { quiet: true }); - - expect(progressListener.types).toHaveLength(0); - expect(progressListener.messages).toHaveLength(0); - - expectAllSpawns(); - }); - - test('handles empty stdout/stderr without emitting events', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: '', - stderr: '', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - - expect(progressListener.types).toHaveLength(0); - expect(progressListener.messages).toHaveLength(0); - - expectAllSpawns(); - }); - - test('preserves multiline output formatting', async () => { - const multilineStdout = 'Line 1\nLine 2\nLine 3\n'; - const multilineStderr = 'Error 1\nError 2\n'; - - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: multilineStdout, - stderr: multilineStderr, - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - - expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); - expect(progressListener.messages).toEqual([ - '[docker stdout] Line 1\nLine 2\nLine 3\n', - '[docker stderr] Error 1\nError 2\n', - ]); - - expectAllSpawns(); - }); - - test('works without a progress listener', async () => { - const dockerNoListener = new Docker({}); - - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - stderr: 'error test string\n', - }); - - await (dockerNoListener as any).execute(['build', '--tag', 'test-image', '.']); - - expectAllSpawns(); - }); -}); diff --git a/test/logging.test.ts b/test/logging.test.ts new file mode 100644 index 0000000..dd31107 --- /dev/null +++ b/test/logging.test.ts @@ -0,0 +1,494 @@ +jest.mock('child_process'); + +import { GetBucketLocationCommand, ListObjectsV2Command } from '@aws-sdk/client-s3'; +import { FakeListener } from './fake-listener'; +import { mockSpawn } from './mock-child_process'; +import { + log, + LOG_LEVELS, + setLogThreshold, + ShellOutputHandler, + setGlobalProgressListener, + VERSION, +} from '../bin/logging'; +import { AssetManifest, AssetPublishing } from '../lib'; +import { MockAws, mockS3 } from './mock-aws'; +import mockfs from './mock-fs'; +import { Docker } from '../lib/private/docker'; +import { EventType } from '../lib/progress'; + +describe('Docker logging', () => { + let progressListener: FakeListener; + let docker: Docker; + + beforeEach(() => { + progressListener = new FakeListener(); + docker = new Docker({ + progressListener: progressListener, + }); + }); + + test('captures stdout as DEBUG events', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + + expect(progressListener.types).toEqual([EventType.DEBUG]); + expect(progressListener.messages).toEqual(['stdout test string\n']); + + expectAllSpawns(); + }); + + test('captures stderr as FAIL events', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stderr: 'error test string\n', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + // Give time for events to process + await new Promise((resolve) => setTimeout(resolve, 50)); + + expect(progressListener.types).toEqual([EventType.FAIL]); + expect(progressListener.messages).toEqual(['error test string\n']); + + expectAllSpawns(); + }); + + test('captures both stdout and stderr with correct event types', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + stderr: 'error test string\n', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + // Give time for events to process + await new Promise((resolve) => setTimeout(resolve, 50)); + + expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); + expect(progressListener.messages).toEqual(['stdout test string\n', 'error test string\n']); + + expectAllSpawns(); + }); + + test('does not emit events when quiet option is true', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + stderr: 'error test string\n', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.'], { quiet: true }); + + expect(progressListener.types).toHaveLength(0); + expect(progressListener.messages).toHaveLength(0); + + expectAllSpawns(); + }); + + test('handles empty stdout/stderr without emitting events', async () => { + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: '', + stderr: '', + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + + expect(progressListener.types).toHaveLength(0); + expect(progressListener.messages).toHaveLength(0); + + expectAllSpawns(); + }); + + test('preserves multiline output formatting', async () => { + const multilineStdout = 'Line 1\nLine 2\nLine 3\n'; + const multilineStderr = 'Error 1\nError 2\n'; + + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: multilineStdout, + stderr: multilineStderr, + }); + + await (docker as any).execute(['build', '--tag', 'test-image', '.']); + + expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); + expect(progressListener.messages).toEqual(['Line 1\nLine 2\nLine 3\n', 'Error 1\nError 2\n']); + + expectAllSpawns(); + }); + + test('works without a progress listener', async () => { + const dockerNoListener = new Docker({}); + + const expectAllSpawns = mockSpawn({ + commandLine: ['docker', 'build', '--tag', 'test-image', '.'], + stdout: 'stdout test string\n', + stderr: 'error test string\n', + }); + + await (dockerNoListener as any).execute(['build', '--tag', 'test-image', '.']); + + expectAllSpawns(); + }); +}); + +describe('logging functionality', () => { + let originalConsoleError: typeof console.error; + let mockConsoleError: jest.Mock; + + beforeEach(() => { + // Store original console.error and replace with mock + originalConsoleError = console.error; + mockConsoleError = jest.fn(); + console.error = mockConsoleError; + }); + + afterEach(() => { + // Restore original console.error + console.error = originalConsoleError; + }); + + describe('log levels', () => { + test('logs respect threshold level - verbose', () => { + setLogThreshold('verbose'); + log('verbose', 'verbose message'); + log('info', 'info message'); + log('error', 'error message'); + + expect(mockConsoleError).toHaveBeenCalledTimes(3); + expect(mockConsoleError).toHaveBeenCalledWith('verbose: verbose message'); + expect(mockConsoleError).toHaveBeenCalledWith('info : info message'); + expect(mockConsoleError).toHaveBeenCalledWith('error : error message'); + }); + + test('logs respect threshold level - info', () => { + setLogThreshold('info'); + log('verbose', 'verbose message'); + log('info', 'info message'); + log('error', 'error message'); + + expect(mockConsoleError).toHaveBeenCalledTimes(2); + expect(mockConsoleError).not.toHaveBeenCalledWith('verbose: verbose message'); + expect(mockConsoleError).toHaveBeenCalledWith('info : info message'); + expect(mockConsoleError).toHaveBeenCalledWith('error : error message'); + }); + + test('logs respect threshold level - error', () => { + setLogThreshold('error'); + log('verbose', 'verbose message'); + log('info', 'info message'); + log('error', 'error message'); + + expect(mockConsoleError).toHaveBeenCalledTimes(1); + expect(mockConsoleError).not.toHaveBeenCalledWith('verbose: verbose message'); + expect(mockConsoleError).not.toHaveBeenCalledWith('info : info message'); + expect(mockConsoleError).toHaveBeenCalledWith('error : error message'); + }); + + test('log levels are properly ordered', () => { + expect(LOG_LEVELS.verbose).toBeLessThan(LOG_LEVELS.info); + expect(LOG_LEVELS.info).toBeLessThan(LOG_LEVELS.error); + }); + }); + + describe('ShellOutputHandler', () => { + test('handles empty chunks appropriately', () => { + const mockProgressListener = { + onPublishEvent: jest.fn(), + }; + const handler = new ShellOutputHandler(mockProgressListener); + + handler.handleOutput(''); + handler.handleOutput('', true); + + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(2); + expect(mockProgressListener.onPublishEvent).toHaveBeenNthCalledWith( + 1, + EventType.DEBUG, + expect.objectContaining({ message: '' }) + ); + expect(mockProgressListener.onPublishEvent).toHaveBeenNthCalledWith( + 2, + EventType.FAIL, + expect.objectContaining({ message: '' }) + ); + }); + + test('emits correct event types for stdout and stderr', () => { + const mockProgressListener = { + onPublishEvent: jest.fn(), + }; + const handler = new ShellOutputHandler(mockProgressListener); + + handler.handleOutput('stdout message'); + handler.handleOutput('stderr message', true); + + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(2); + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.DEBUG, + expect.objectContaining({ message: 'stdout message' }) + ); + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.FAIL, + expect.objectContaining({ message: 'stderr message' }) + ); + }); + + test('preserves original output when no progress listener is provided', () => { + const handler = new ShellOutputHandler(); + const originalStdout = process.stdout.write; + const originalStderr = process.stderr.write; + const mockStdout = jest.fn(); + const mockStderr = jest.fn(); + process.stdout.write = mockStdout; + process.stderr.write = mockStderr; + + try { + handler.handleOutput('stdout message'); + handler.handleOutput('stderr message', true); + + expect(mockStdout).toHaveBeenCalledWith('stdout message'); + expect(mockStderr).toHaveBeenCalledWith('stderr message'); + } finally { + process.stdout.write = originalStdout; + process.stderr.write = originalStderr; + } + }); + + test('handles different chunk types properly', () => { + const mockProgressListener = { + onPublishEvent: jest.fn(), + }; + const handler = new ShellOutputHandler(mockProgressListener); + + // Test Buffer input + handler.handleOutput(Buffer.from('buffer message')); + // Test object with toString + handler.handleOutput({ toString: () => 'object message' }); + + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.DEBUG, + expect.objectContaining({ message: 'buffer message' }) + ); + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.DEBUG, + expect.objectContaining({ message: 'object message' }) + ); + }); + }); + + describe('log message formatting', () => { + test('correctly pads log level strings', () => { + setLogThreshold('verbose'); + + const testMessage = 'test message'; + log('verbose', testMessage); + log('info', testMessage); + log('error', testMessage); + + expect(mockConsoleError).toHaveBeenCalledWith('verbose: test message'); + expect(mockConsoleError).toHaveBeenCalledWith('info : test message'); + expect(mockConsoleError).toHaveBeenCalledWith('error : test message'); + }); + + test('handles messages with percentage complete', () => { + setLogThreshold('info'); + + log('info', 'Progress message', 50); + + expect(mockConsoleError).toHaveBeenCalledWith('info : Progress message'); + }); + }); + + describe('version logging', () => { + test('VERSION is properly defined', () => { + expect(VERSION).toBeDefined(); + expect(typeof VERSION).toBe('string'); + }); + }); +}); + +describe('logging event routing', () => { + let mockProgressListener: { onPublishEvent: jest.Mock }; + let originalConsoleError: typeof console.error; + let originalStdoutWrite: typeof process.stdout.write; + let originalStderrWrite: typeof process.stderr.write; + + beforeEach(() => { + mockProgressListener = { onPublishEvent: jest.fn() }; + setGlobalProgressListener(null as any); + + // Store originals + originalConsoleError = console.error; + originalStdoutWrite = process.stdout.write; + originalStderrWrite = process.stderr.write; + + // Mock console and streams + console.error = jest.fn(); + process.stdout.write = jest.fn(); + process.stderr.write = jest.fn(); + + // Reset log threshold + setLogThreshold('verbose'); + }); + + afterEach(() => { + setGlobalProgressListener(null as any); + mockfs.restore(); + // Restore originals + console.error = originalConsoleError; + process.stdout.write = originalStdoutWrite; + process.stderr.write = originalStderrWrite; + }); + + describe('direct logging via log()', () => { + test('routes all log levels through progress listener', () => { + setGlobalProgressListener(mockProgressListener); + + // Test each log level + log('verbose', 'verbose message'); + log('info', 'info message'); + log('error', 'error message'); + + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(3); + + // Check verbose maps to DEBUG + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.DEBUG, + expect.objectContaining({ message: 'verbose message' }) + ); + + // Check info maps to DEBUG + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.DEBUG, + expect.objectContaining({ message: 'info message' }) + ); + + // Check error maps to FAIL + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.FAIL, + expect.objectContaining({ message: 'error message' }) + ); + }); + + test('respects log threshold when routing to progress listener', () => { + setGlobalProgressListener(mockProgressListener); + setLogThreshold('error'); + + log('verbose', 'verbose message'); + log('info', 'info message'); + log('error', 'error message'); + + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(1); + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.FAIL, + expect.objectContaining({ message: 'error message' }) + ); + }); + }); + + describe('shell output handling', () => { + test('routes all shell output through progress listener', () => { + const handler = new ShellOutputHandler(mockProgressListener); + + handler.handleOutput('stdout message'); + handler.handleOutput('stderr message', true); + + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(2); + + // Check stdout routes to DEBUG + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.DEBUG, + expect.objectContaining({ message: 'stdout message' }) + ); + + // Check stderr routes to FAIL + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.FAIL, + expect.objectContaining({ message: 'stderr message' }) + ); + }); + + test('routes multi-line output through progress listener', () => { + const handler = new ShellOutputHandler(mockProgressListener); + const multilineOutput = 'line1\nline2\nline3'; + + handler.handleOutput(multilineOutput); + + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(1); + expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( + EventType.DEBUG, + expect.objectContaining({ message: multilineOutput }) + ); + }); + }); + + describe('asset publishing progress events', () => { + beforeEach(() => { + mockS3.reset(); + // Mock successful bucket location check + mockS3.on(GetBucketLocationCommand).resolves({}); + // Mock successful list objects check + mockS3.on(ListObjectsV2Command).resolves({ Contents: [] }); + mockfs({ + '/simple/cdk.out/assets.json': JSON.stringify({ + version: '1.0.0', + files: { + asset1: { + source: { + path: 'some_file', + }, + destinations: { + dest1: { + region: 'us-north-50', + assumeRoleArn: 'arn:aws:role', + bucketName: 'some_bucket', + objectKey: 'some_key', + }, + }, + }, + }, + }), + '/simple/cdk.out/some_file': 'FILE_CONTENTS', + }); + }); + + test('routes all publishing events through progress listener', async () => { + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/simple/cdk.out')), { + aws: new MockAws(), + progressListener: mockProgressListener, + }); + + await pub.publish(); + + // Verify we get events for start, check, and either found or upload + const eventTypes = mockProgressListener.onPublishEvent.mock.calls.map((call) => call[0]); + + expect(eventTypes).toContain(EventType.START); + expect(eventTypes).toContain(EventType.CHECK); + expect(eventTypes.some((t) => t === EventType.FOUND || t === EventType.UPLOAD)).toBe(true); + }); + + test('routes failure events through progress listener', async () => { + // Make S3 operations fail + mockS3.reset(); + mockS3.on(GetBucketLocationCommand).rejects(new Error('Simulated failure')); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/simple/cdk.out')), { + aws: new MockAws(), + progressListener: mockProgressListener, + }); + + await pub.publish().catch(() => {}); // Ignore the error + + const eventTypes = mockProgressListener.onPublishEvent.mock.calls.map((call) => call[0]); + expect(eventTypes).toContain(EventType.FAIL); + }); + }); +}); From 5bcdaad80effa17911de1113cfd4ecde79574762 Mon Sep 17 00:00:00 2001 From: HBobertz Date: Sun, 8 Dec 2024 17:12:22 -0500 Subject: [PATCH 05/16] better comments and such --- bin/cdk-assets.ts | 2 -- bin/logging.ts | 9 +++------ lib/private/shell.ts | 6 ++++++ 3 files changed, 9 insertions(+), 8 deletions(-) diff --git a/bin/cdk-assets.ts b/bin/cdk-assets.ts index ab334eb..30be487 100644 --- a/bin/cdk-assets.ts +++ b/bin/cdk-assets.ts @@ -1,4 +1,3 @@ -// Modified bin/cdk-assets.ts import * as yargs from 'yargs'; import { list } from './list'; import { log, setGlobalProgressListener, setLogThreshold, VERSION } from './logging'; @@ -7,7 +6,6 @@ import { AssetManifest, EventType, IPublishProgress, IPublishProgressListener } class DefaultProgressListener implements IPublishProgressListener { public onPublishEvent(type: EventType, event: IPublishProgress): void { - // Map event types to log levels switch (type) { case EventType.FAIL: log('error', event.message); diff --git a/bin/logging.ts b/bin/logging.ts index 385cf67..40a459f 100644 --- a/bin/logging.ts +++ b/bin/logging.ts @@ -1,4 +1,3 @@ -// Modified bin/logging.ts to integrate with progress interface import * as fs from 'fs'; import * as path from 'path'; import { EventType, IPublishProgress, IPublishProgressListener } from '../lib/progress'; @@ -10,7 +9,7 @@ export const VERSION = JSON.parse( export type LogLevel = 'verbose' | 'info' | 'error'; let logThreshold: LogLevel = 'info'; -// Global progress listener that can be set +// Global progress listener that will eventually be set let globalProgressListener: IPublishProgressListener | undefined; export const LOG_LEVELS: Record = { @@ -41,10 +40,9 @@ function logLevelToEventType(level: LogLevel): EventType { export function log(level: LogLevel, message: string, percentComplete?: number) { if (LOG_LEVELS[level] >= LOG_LEVELS[logThreshold]) { - // Still write to stderr for backward compatibility console.error(`${level.padEnd(7, ' ')}: ${message}`); - // Also send to progress listener if configured + // Write to progress listener if configured if (globalProgressListener) { const progressEvent: IPublishProgress = { message: `${message}`, @@ -62,14 +60,13 @@ export class ShellOutputHandler { public handleOutput(chunk: any, isError: boolean = false) { const text = chunk.toString(); - // Write to standard streams for backward compatibility if (isError) { process.stderr.write(text); } else { process.stdout.write(text); } - // Also send to progress listener if configured + // Send to progress listener if configured if (this.progressListener) { const progressEvent: IPublishProgress = { message: text, diff --git a/lib/private/shell.ts b/lib/private/shell.ts index 17dfc69..d1fe28e 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -11,6 +11,12 @@ export interface ShellOptions extends child_process.SpawnOptions { readonly progressListener?: IPublishProgressListener; } +/** + * OS helpers + * + * 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)); From f16aa2faf5afb23c64de32ea47a69a2aaa45bc2b Mon Sep 17 00:00:00 2001 From: HBobertz Date: Sun, 8 Dec 2024 17:16:53 -0500 Subject: [PATCH 06/16] update comment again --- bin/logging.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/bin/logging.ts b/bin/logging.ts index 40a459f..0b58467 100644 --- a/bin/logging.ts +++ b/bin/logging.ts @@ -9,7 +9,8 @@ export const VERSION = JSON.parse( export type LogLevel = 'verbose' | 'info' | 'error'; let logThreshold: LogLevel = 'info'; -// Global progress listener that will eventually be set +// Global default progress listener that will be set if using the cli +// If using the library, you should set your own listener let globalProgressListener: IPublishProgressListener | undefined; export const LOG_LEVELS: Record = { From f5798b866c8d67054c34f612c1d2819fe4eea004 Mon Sep 17 00:00:00 2001 From: HBobertz Date: Wed, 11 Dec 2024 13:44:01 -0500 Subject: [PATCH 07/16] fix mock child --- test/mock-child_process.ts | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/test/mock-child_process.ts b/test/mock-child_process.ts index ee5e86d..a5818f2 100644 --- a/test/mock-child_process.ts +++ b/test/mock-child_process.ts @@ -11,23 +11,29 @@ export interface Invocation { exitCode?: number; stdout?: string; stderr?: string; + /** + * Only match a prefix of the command (don't care about the details of the arguments) + */ prefix?: boolean; } export function mockSpawn(...invocations: Invocation[]): () => void { let mock = child_process.spawn as any; for (const _invocation of invocations) { - const invocation = _invocation; + const invocation = _invocation; // Mirror into variable for closure mock = mock.mockImplementationOnce( (binary: string, args: string[], options: child_process.SpawnOptions) => { if (invocation.prefix) { + // Match command line prefix expect([binary, ...args].slice(0, invocation.commandLine.length)).toEqual( invocation.commandLine ); } else { + // Match full command line expect([binary, ...args]).toEqual(invocation.commandLine); } + // Prune the temp directory off here if (invocation.cwd != null) { expect(invocation.cwd).toEqual((options.cwd as string).slice(-invocation.cwd.length)); } @@ -43,10 +49,7 @@ export function mockSpawn(...invocations: Invocation[]): () => void { mockEmit(child.stdout, 'data', Buffer.from(invocation.stdout)); } if (invocation.stderr) { - // Send stderr data after stdout - if (invocation.stderr) { - mockEmit(child.stderr, 'data', Buffer.from(invocation.stderr)); - } + mockEmit(child.stderr, 'data', Buffer.from(invocation.stderr)); } mockEmit(child, 'close', invocation.exitCode ?? 0); From 7fee2ff9c7b5c8cf8319ed2ae91d1aef750d7026 Mon Sep 17 00:00:00 2001 From: HBobertz Date: Fri, 13 Dec 2024 10:05:03 -0500 Subject: [PATCH 08/16] make logging better --- bin/cdk-assets.ts | 19 ++----------------- bin/logging.ts | 42 ++++++++++++++++++++++++++++-------------- 2 files changed, 30 insertions(+), 31 deletions(-) diff --git a/bin/cdk-assets.ts b/bin/cdk-assets.ts index 30be487..304495f 100644 --- a/bin/cdk-assets.ts +++ b/bin/cdk-assets.ts @@ -1,23 +1,8 @@ import * as yargs from 'yargs'; import { list } from './list'; -import { log, setGlobalProgressListener, setLogThreshold, VERSION } from './logging'; +import { setGlobalProgressListener, setLogThreshold, VERSION, DefaultProgressListener } from './logging'; import { publish } from './publish'; -import { AssetManifest, EventType, IPublishProgress, IPublishProgressListener } from '../lib'; - -class DefaultProgressListener implements IPublishProgressListener { - public onPublishEvent(type: EventType, event: IPublishProgress): void { - switch (type) { - case EventType.FAIL: - log('error', event.message); - break; - case EventType.DEBUG: - log('verbose', event.message); - break; - default: - log('info', event.message); - } - } -} +import { AssetManifest } from '../lib'; async function main() { const defaultListener = new DefaultProgressListener(); diff --git a/bin/logging.ts b/bin/logging.ts index 0b58467..83f34d3 100644 --- a/bin/logging.ts +++ b/bin/logging.ts @@ -6,6 +6,21 @@ export const VERSION = JSON.parse( fs.readFileSync(path.join(__dirname, '..', 'package.json'), { encoding: 'utf-8' }) ).version; +export class DefaultProgressListener implements IPublishProgressListener { + public onPublishEvent(type: EventType, event: IPublishProgress): void { + switch (type) { + case EventType.FAIL: + console.error(`error : ${event.message}`); + break; + case EventType.DEBUG: + console.error(`verbose: ${event.message}`); + break; + default: + console.error(`info : ${event.message}`); + } + } +} + export type LogLevel = 'verbose' | 'info' | 'error'; let logThreshold: LogLevel = 'info'; @@ -32,26 +47,25 @@ function logLevelToEventType(level: LogLevel): EventType { switch (level) { case 'error': return EventType.FAIL; - case 'verbose': - return EventType.DEBUG; default: return EventType.DEBUG; } } export function log(level: LogLevel, message: string, percentComplete?: number) { + // should be entirely irrelevant but just to verify that the globalProgressListener is set + if (!globalProgressListener) { + setGlobalProgressListener(new DefaultProgressListener()); + } + if (LOG_LEVELS[level] >= LOG_LEVELS[logThreshold]) { - console.error(`${level.padEnd(7, ' ')}: ${message}`); + const progressEvent: IPublishProgress = { + message: `${message}`, + percentComplete: percentComplete, + abort: () => {}, + }; - // Write to progress listener if configured - if (globalProgressListener) { - const progressEvent: IPublishProgress = { - message: `${message}`, - percentComplete: percentComplete, - abort: () => {}, - }; - globalProgressListener.onPublishEvent(logLevelToEventType(level), progressEvent); - } + globalProgressListener!.onPublishEvent(logLevelToEventType(level), progressEvent); } } @@ -68,7 +82,7 @@ export class ShellOutputHandler { } // Send to progress listener if configured - if (this.progressListener) { + if (this.progressListener && text.length > 0) { const progressEvent: IPublishProgress = { message: text, abort: () => {}, @@ -79,4 +93,4 @@ export class ShellOutputHandler { ); } } -} +} \ No newline at end of file From 39b52b6191910133662798963c5dfb431b1c61c3 Mon Sep 17 00:00:00 2001 From: HBobertz Date: Thu, 26 Dec 2024 13:24:13 -0500 Subject: [PATCH 09/16] remove unnecessary feature --- bin/cdk-assets.ts | 4 +- bin/logging.ts | 55 +---- lib/progress.ts | 2 +- test/logging.test.ts | 494 ------------------------------------------- 4 files changed, 4 insertions(+), 551 deletions(-) diff --git a/bin/cdk-assets.ts b/bin/cdk-assets.ts index 304495f..8c525f5 100644 --- a/bin/cdk-assets.ts +++ b/bin/cdk-assets.ts @@ -1,12 +1,10 @@ import * as yargs from 'yargs'; import { list } from './list'; -import { setGlobalProgressListener, setLogThreshold, VERSION, DefaultProgressListener } from './logging'; +import { setLogThreshold, VERSION } from './logging'; import { publish } from './publish'; import { AssetManifest } from '../lib'; async function main() { - const defaultListener = new DefaultProgressListener(); - setGlobalProgressListener(defaultListener); const argv = yargs .usage('$0 [args]') diff --git a/bin/logging.ts b/bin/logging.ts index 83f34d3..c1fe507 100644 --- a/bin/logging.ts +++ b/bin/logging.ts @@ -6,28 +6,9 @@ export const VERSION = JSON.parse( fs.readFileSync(path.join(__dirname, '..', 'package.json'), { encoding: 'utf-8' }) ).version; -export class DefaultProgressListener implements IPublishProgressListener { - public onPublishEvent(type: EventType, event: IPublishProgress): void { - switch (type) { - case EventType.FAIL: - console.error(`error : ${event.message}`); - break; - case EventType.DEBUG: - console.error(`verbose: ${event.message}`); - break; - default: - console.error(`info : ${event.message}`); - } - } -} - export type LogLevel = 'verbose' | 'info' | 'error'; let logThreshold: LogLevel = 'info'; -// Global default progress listener that will be set if using the cli -// If using the library, you should set your own listener -let globalProgressListener: IPublishProgressListener | undefined; - export const LOG_LEVELS: Record = { verbose: 1, info: 2, @@ -38,35 +19,9 @@ export function setLogThreshold(threshold: LogLevel) { logThreshold = threshold; } -export function setGlobalProgressListener(listener: IPublishProgressListener) { - globalProgressListener = listener; -} - -// Convert log level to event type -function logLevelToEventType(level: LogLevel): EventType { - switch (level) { - case 'error': - return EventType.FAIL; - default: - return EventType.DEBUG; - } -} - -export function log(level: LogLevel, message: string, percentComplete?: number) { +export function log(level: LogLevel, message: string ) { // should be entirely irrelevant but just to verify that the globalProgressListener is set - if (!globalProgressListener) { - setGlobalProgressListener(new DefaultProgressListener()); - } - - if (LOG_LEVELS[level] >= LOG_LEVELS[logThreshold]) { - const progressEvent: IPublishProgress = { - message: `${message}`, - percentComplete: percentComplete, - abort: () => {}, - }; - - globalProgressListener!.onPublishEvent(logLevelToEventType(level), progressEvent); - } + console.error(`${level.padEnd(7, ' ')}: ${message}`); } export class ShellOutputHandler { @@ -75,12 +30,6 @@ export class ShellOutputHandler { public handleOutput(chunk: any, isError: boolean = false) { const text = chunk.toString(); - if (isError) { - process.stderr.write(text); - } else { - process.stdout.write(text); - } - // Send to progress listener if configured if (this.progressListener && text.length > 0) { const progressEvent: IPublishProgress = { diff --git a/lib/progress.ts b/lib/progress.ts index d9f24b8..b2c8e77 100644 --- a/lib/progress.ts +++ b/lib/progress.ts @@ -77,7 +77,7 @@ export interface IPublishProgress { /** * How far along are we? */ - readonly percentComplete?: number; + readonly percentComplete: number; /** * Abort the current publishing operation diff --git a/test/logging.test.ts b/test/logging.test.ts index dd31107..e69de29 100644 --- a/test/logging.test.ts +++ b/test/logging.test.ts @@ -1,494 +0,0 @@ -jest.mock('child_process'); - -import { GetBucketLocationCommand, ListObjectsV2Command } from '@aws-sdk/client-s3'; -import { FakeListener } from './fake-listener'; -import { mockSpawn } from './mock-child_process'; -import { - log, - LOG_LEVELS, - setLogThreshold, - ShellOutputHandler, - setGlobalProgressListener, - VERSION, -} from '../bin/logging'; -import { AssetManifest, AssetPublishing } from '../lib'; -import { MockAws, mockS3 } from './mock-aws'; -import mockfs from './mock-fs'; -import { Docker } from '../lib/private/docker'; -import { EventType } from '../lib/progress'; - -describe('Docker logging', () => { - let progressListener: FakeListener; - let docker: Docker; - - beforeEach(() => { - progressListener = new FakeListener(); - docker = new Docker({ - progressListener: progressListener, - }); - }); - - test('captures stdout as DEBUG events', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - - expect(progressListener.types).toEqual([EventType.DEBUG]); - expect(progressListener.messages).toEqual(['stdout test string\n']); - - expectAllSpawns(); - }); - - test('captures stderr as FAIL events', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stderr: 'error test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - // Give time for events to process - await new Promise((resolve) => setTimeout(resolve, 50)); - - expect(progressListener.types).toEqual([EventType.FAIL]); - expect(progressListener.messages).toEqual(['error test string\n']); - - expectAllSpawns(); - }); - - test('captures both stdout and stderr with correct event types', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - stderr: 'error test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - // Give time for events to process - await new Promise((resolve) => setTimeout(resolve, 50)); - - expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); - expect(progressListener.messages).toEqual(['stdout test string\n', 'error test string\n']); - - expectAllSpawns(); - }); - - test('does not emit events when quiet option is true', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - stderr: 'error test string\n', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.'], { quiet: true }); - - expect(progressListener.types).toHaveLength(0); - expect(progressListener.messages).toHaveLength(0); - - expectAllSpawns(); - }); - - test('handles empty stdout/stderr without emitting events', async () => { - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: '', - stderr: '', - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - - expect(progressListener.types).toHaveLength(0); - expect(progressListener.messages).toHaveLength(0); - - expectAllSpawns(); - }); - - test('preserves multiline output formatting', async () => { - const multilineStdout = 'Line 1\nLine 2\nLine 3\n'; - const multilineStderr = 'Error 1\nError 2\n'; - - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: multilineStdout, - stderr: multilineStderr, - }); - - await (docker as any).execute(['build', '--tag', 'test-image', '.']); - - expect(progressListener.types).toEqual([EventType.DEBUG, EventType.FAIL]); - expect(progressListener.messages).toEqual(['Line 1\nLine 2\nLine 3\n', 'Error 1\nError 2\n']); - - expectAllSpawns(); - }); - - test('works without a progress listener', async () => { - const dockerNoListener = new Docker({}); - - const expectAllSpawns = mockSpawn({ - commandLine: ['docker', 'build', '--tag', 'test-image', '.'], - stdout: 'stdout test string\n', - stderr: 'error test string\n', - }); - - await (dockerNoListener as any).execute(['build', '--tag', 'test-image', '.']); - - expectAllSpawns(); - }); -}); - -describe('logging functionality', () => { - let originalConsoleError: typeof console.error; - let mockConsoleError: jest.Mock; - - beforeEach(() => { - // Store original console.error and replace with mock - originalConsoleError = console.error; - mockConsoleError = jest.fn(); - console.error = mockConsoleError; - }); - - afterEach(() => { - // Restore original console.error - console.error = originalConsoleError; - }); - - describe('log levels', () => { - test('logs respect threshold level - verbose', () => { - setLogThreshold('verbose'); - log('verbose', 'verbose message'); - log('info', 'info message'); - log('error', 'error message'); - - expect(mockConsoleError).toHaveBeenCalledTimes(3); - expect(mockConsoleError).toHaveBeenCalledWith('verbose: verbose message'); - expect(mockConsoleError).toHaveBeenCalledWith('info : info message'); - expect(mockConsoleError).toHaveBeenCalledWith('error : error message'); - }); - - test('logs respect threshold level - info', () => { - setLogThreshold('info'); - log('verbose', 'verbose message'); - log('info', 'info message'); - log('error', 'error message'); - - expect(mockConsoleError).toHaveBeenCalledTimes(2); - expect(mockConsoleError).not.toHaveBeenCalledWith('verbose: verbose message'); - expect(mockConsoleError).toHaveBeenCalledWith('info : info message'); - expect(mockConsoleError).toHaveBeenCalledWith('error : error message'); - }); - - test('logs respect threshold level - error', () => { - setLogThreshold('error'); - log('verbose', 'verbose message'); - log('info', 'info message'); - log('error', 'error message'); - - expect(mockConsoleError).toHaveBeenCalledTimes(1); - expect(mockConsoleError).not.toHaveBeenCalledWith('verbose: verbose message'); - expect(mockConsoleError).not.toHaveBeenCalledWith('info : info message'); - expect(mockConsoleError).toHaveBeenCalledWith('error : error message'); - }); - - test('log levels are properly ordered', () => { - expect(LOG_LEVELS.verbose).toBeLessThan(LOG_LEVELS.info); - expect(LOG_LEVELS.info).toBeLessThan(LOG_LEVELS.error); - }); - }); - - describe('ShellOutputHandler', () => { - test('handles empty chunks appropriately', () => { - const mockProgressListener = { - onPublishEvent: jest.fn(), - }; - const handler = new ShellOutputHandler(mockProgressListener); - - handler.handleOutput(''); - handler.handleOutput('', true); - - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(2); - expect(mockProgressListener.onPublishEvent).toHaveBeenNthCalledWith( - 1, - EventType.DEBUG, - expect.objectContaining({ message: '' }) - ); - expect(mockProgressListener.onPublishEvent).toHaveBeenNthCalledWith( - 2, - EventType.FAIL, - expect.objectContaining({ message: '' }) - ); - }); - - test('emits correct event types for stdout and stderr', () => { - const mockProgressListener = { - onPublishEvent: jest.fn(), - }; - const handler = new ShellOutputHandler(mockProgressListener); - - handler.handleOutput('stdout message'); - handler.handleOutput('stderr message', true); - - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(2); - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.DEBUG, - expect.objectContaining({ message: 'stdout message' }) - ); - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.FAIL, - expect.objectContaining({ message: 'stderr message' }) - ); - }); - - test('preserves original output when no progress listener is provided', () => { - const handler = new ShellOutputHandler(); - const originalStdout = process.stdout.write; - const originalStderr = process.stderr.write; - const mockStdout = jest.fn(); - const mockStderr = jest.fn(); - process.stdout.write = mockStdout; - process.stderr.write = mockStderr; - - try { - handler.handleOutput('stdout message'); - handler.handleOutput('stderr message', true); - - expect(mockStdout).toHaveBeenCalledWith('stdout message'); - expect(mockStderr).toHaveBeenCalledWith('stderr message'); - } finally { - process.stdout.write = originalStdout; - process.stderr.write = originalStderr; - } - }); - - test('handles different chunk types properly', () => { - const mockProgressListener = { - onPublishEvent: jest.fn(), - }; - const handler = new ShellOutputHandler(mockProgressListener); - - // Test Buffer input - handler.handleOutput(Buffer.from('buffer message')); - // Test object with toString - handler.handleOutput({ toString: () => 'object message' }); - - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.DEBUG, - expect.objectContaining({ message: 'buffer message' }) - ); - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.DEBUG, - expect.objectContaining({ message: 'object message' }) - ); - }); - }); - - describe('log message formatting', () => { - test('correctly pads log level strings', () => { - setLogThreshold('verbose'); - - const testMessage = 'test message'; - log('verbose', testMessage); - log('info', testMessage); - log('error', testMessage); - - expect(mockConsoleError).toHaveBeenCalledWith('verbose: test message'); - expect(mockConsoleError).toHaveBeenCalledWith('info : test message'); - expect(mockConsoleError).toHaveBeenCalledWith('error : test message'); - }); - - test('handles messages with percentage complete', () => { - setLogThreshold('info'); - - log('info', 'Progress message', 50); - - expect(mockConsoleError).toHaveBeenCalledWith('info : Progress message'); - }); - }); - - describe('version logging', () => { - test('VERSION is properly defined', () => { - expect(VERSION).toBeDefined(); - expect(typeof VERSION).toBe('string'); - }); - }); -}); - -describe('logging event routing', () => { - let mockProgressListener: { onPublishEvent: jest.Mock }; - let originalConsoleError: typeof console.error; - let originalStdoutWrite: typeof process.stdout.write; - let originalStderrWrite: typeof process.stderr.write; - - beforeEach(() => { - mockProgressListener = { onPublishEvent: jest.fn() }; - setGlobalProgressListener(null as any); - - // Store originals - originalConsoleError = console.error; - originalStdoutWrite = process.stdout.write; - originalStderrWrite = process.stderr.write; - - // Mock console and streams - console.error = jest.fn(); - process.stdout.write = jest.fn(); - process.stderr.write = jest.fn(); - - // Reset log threshold - setLogThreshold('verbose'); - }); - - afterEach(() => { - setGlobalProgressListener(null as any); - mockfs.restore(); - // Restore originals - console.error = originalConsoleError; - process.stdout.write = originalStdoutWrite; - process.stderr.write = originalStderrWrite; - }); - - describe('direct logging via log()', () => { - test('routes all log levels through progress listener', () => { - setGlobalProgressListener(mockProgressListener); - - // Test each log level - log('verbose', 'verbose message'); - log('info', 'info message'); - log('error', 'error message'); - - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(3); - - // Check verbose maps to DEBUG - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.DEBUG, - expect.objectContaining({ message: 'verbose message' }) - ); - - // Check info maps to DEBUG - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.DEBUG, - expect.objectContaining({ message: 'info message' }) - ); - - // Check error maps to FAIL - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.FAIL, - expect.objectContaining({ message: 'error message' }) - ); - }); - - test('respects log threshold when routing to progress listener', () => { - setGlobalProgressListener(mockProgressListener); - setLogThreshold('error'); - - log('verbose', 'verbose message'); - log('info', 'info message'); - log('error', 'error message'); - - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(1); - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.FAIL, - expect.objectContaining({ message: 'error message' }) - ); - }); - }); - - describe('shell output handling', () => { - test('routes all shell output through progress listener', () => { - const handler = new ShellOutputHandler(mockProgressListener); - - handler.handleOutput('stdout message'); - handler.handleOutput('stderr message', true); - - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(2); - - // Check stdout routes to DEBUG - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.DEBUG, - expect.objectContaining({ message: 'stdout message' }) - ); - - // Check stderr routes to FAIL - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.FAIL, - expect.objectContaining({ message: 'stderr message' }) - ); - }); - - test('routes multi-line output through progress listener', () => { - const handler = new ShellOutputHandler(mockProgressListener); - const multilineOutput = 'line1\nline2\nline3'; - - handler.handleOutput(multilineOutput); - - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledTimes(1); - expect(mockProgressListener.onPublishEvent).toHaveBeenCalledWith( - EventType.DEBUG, - expect.objectContaining({ message: multilineOutput }) - ); - }); - }); - - describe('asset publishing progress events', () => { - beforeEach(() => { - mockS3.reset(); - // Mock successful bucket location check - mockS3.on(GetBucketLocationCommand).resolves({}); - // Mock successful list objects check - mockS3.on(ListObjectsV2Command).resolves({ Contents: [] }); - mockfs({ - '/simple/cdk.out/assets.json': JSON.stringify({ - version: '1.0.0', - files: { - asset1: { - source: { - path: 'some_file', - }, - destinations: { - dest1: { - region: 'us-north-50', - assumeRoleArn: 'arn:aws:role', - bucketName: 'some_bucket', - objectKey: 'some_key', - }, - }, - }, - }, - }), - '/simple/cdk.out/some_file': 'FILE_CONTENTS', - }); - }); - - test('routes all publishing events through progress listener', async () => { - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/simple/cdk.out')), { - aws: new MockAws(), - progressListener: mockProgressListener, - }); - - await pub.publish(); - - // Verify we get events for start, check, and either found or upload - const eventTypes = mockProgressListener.onPublishEvent.mock.calls.map((call) => call[0]); - - expect(eventTypes).toContain(EventType.START); - expect(eventTypes).toContain(EventType.CHECK); - expect(eventTypes.some((t) => t === EventType.FOUND || t === EventType.UPLOAD)).toBe(true); - }); - - test('routes failure events through progress listener', async () => { - // Make S3 operations fail - mockS3.reset(); - mockS3.on(GetBucketLocationCommand).rejects(new Error('Simulated failure')); - - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/simple/cdk.out')), { - aws: new MockAws(), - progressListener: mockProgressListener, - }); - - await pub.publish().catch(() => {}); // Ignore the error - - const eventTypes = mockProgressListener.onPublishEvent.mock.calls.map((call) => call[0]); - expect(eventTypes).toContain(EventType.FAIL); - }); - }); -}); From b1c7851321aa0193163076c62c8cc047387f8fee Mon Sep 17 00:00:00 2001 From: HBobertz Date: Thu, 26 Dec 2024 14:48:27 -0500 Subject: [PATCH 10/16] better capturing of shell logs --- bin/cdk-assets.ts | 1 - bin/logging.ts | 35 +---- bin/publish.ts | 6 +- lib/private/shell.ts | 36 ++++- lib/publishing.ts | 15 +- test/asset-publishing-logs.test.ts | 233 +++++++++++++++++++++++++++++ 6 files changed, 286 insertions(+), 40 deletions(-) create mode 100644 test/asset-publishing-logs.test.ts diff --git a/bin/cdk-assets.ts b/bin/cdk-assets.ts index 8c525f5..7135659 100644 --- a/bin/cdk-assets.ts +++ b/bin/cdk-assets.ts @@ -5,7 +5,6 @@ import { publish } from './publish'; import { AssetManifest } from '../lib'; async function main() { - const argv = yargs .usage('$0 [args]') .option('verbose', { diff --git a/bin/logging.ts b/bin/logging.ts index c1fe507..5326feb 100644 --- a/bin/logging.ts +++ b/bin/logging.ts @@ -1,15 +1,14 @@ import * as fs from 'fs'; import * as path from 'path'; -import { EventType, IPublishProgress, IPublishProgressListener } from '../lib/progress'; + +export type LogLevel = 'verbose' | 'info' | 'error'; +let logThreshold: LogLevel = 'info'; export const VERSION = JSON.parse( fs.readFileSync(path.join(__dirname, '..', 'package.json'), { encoding: 'utf-8' }) ).version; -export type LogLevel = 'verbose' | 'info' | 'error'; -let logThreshold: LogLevel = 'info'; - -export const LOG_LEVELS: Record = { +const LOG_LEVELS: Record = { verbose: 1, info: 2, error: 3, @@ -19,27 +18,9 @@ export function setLogThreshold(threshold: LogLevel) { logThreshold = threshold; } -export function log(level: LogLevel, message: string ) { - // should be entirely irrelevant but just to verify that the globalProgressListener is set +export function log(level: LogLevel, message: string) { + if (LOG_LEVELS[level] >= LOG_LEVELS[logThreshold]) { + // eslint-disable-next-line no-console console.error(`${level.padEnd(7, ' ')}: ${message}`); -} - -export class ShellOutputHandler { - constructor(private readonly progressListener?: IPublishProgressListener) {} - - public handleOutput(chunk: any, isError: boolean = false) { - const text = chunk.toString(); - - // Send to progress listener if configured - if (this.progressListener && text.length > 0) { - const progressEvent: IPublishProgress = { - message: text, - abort: () => {}, - }; - this.progressListener.onPublishEvent( - isError ? EventType.FAIL : EventType.DEBUG, - progressEvent - ); - } } -} \ No newline at end of file +} diff --git a/bin/publish.ts b/bin/publish.ts index c7158d1..7e451a2 100644 --- a/bin/publish.ts +++ b/bin/publish.ts @@ -51,10 +51,6 @@ const EVENT_TO_LEVEL: Record = { class ConsoleProgress implements IPublishProgressListener { public onPublishEvent(type: EventType, event: IPublishProgress): void { - log( - EVENT_TO_LEVEL[type], - `[${event.percentComplete}%] ${type}: ${event.message}`, - event.percentComplete - ); + log(EVENT_TO_LEVEL[type], `[${event.percentComplete}%] ${type}: ${event.message}`); } } diff --git a/lib/private/shell.ts b/lib/private/shell.ts index d1fe28e..572dd4f 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -1,6 +1,5 @@ import * as child_process from 'child_process'; -import { ShellOutputHandler } from '../../bin/logging'; -import { IPublishProgressListener } from '../progress'; +import { EventType, IPublishProgress, IPublishProgressListener } from '../progress'; export type Logger = (x: string) => void; @@ -22,7 +21,7 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom options.logger(renderCommandLine(command)); } - const outputHandler = new ShellOutputHandler(options.progressListener); + const outputHandler = new ShellOutputHandler(); const child = child_process.spawn(command[0], command.slice(1), { ...options, @@ -146,3 +145,34 @@ function windowsEscape(x: string): string { .map((c) => (shellMeta.has(x) ? '^' + c : c)) .join(''); } + +export class ShellOutputHandler { + public handleOutput(chunk: any, isError: boolean = false) { + const text = chunk.toString(); + + // Send to progress listener if configured + if (shellProgressListener && text.length > 0) { + const progressEvent: IPublishProgress = { + message: text, + abort: () => {}, + percentComplete: globalCompletionProgress, + }; + shellProgressListener.onPublishEvent( + isError ? EventType.FAIL : EventType.DEBUG, + progressEvent + ); + } + } +} + +let shellProgressListener: IPublishProgressListener | undefined; + +let globalCompletionProgress: number; + +export function setShellProgressListener(listener: IPublishProgressListener) { + shellProgressListener = listener; +} + +export function setGlobalCompletionProgress(progress: number) { + globalCompletionProgress = progress; +} diff --git a/lib/publishing.ts b/lib/publishing.ts index cf0293c..fb0e4b4 100644 --- a/lib/publishing.ts +++ b/lib/publishing.ts @@ -4,6 +4,7 @@ import { IAssetHandler, IHandlerHost, type PublishOptions } from './private/asse import { DockerFactory } from './private/docker'; import { makeAssetHandler } from './private/handlers'; import { pLimit } from './private/p-limit'; +import { setGlobalCompletionProgress, setShellProgressListener } from './private/shell'; import { EventType, IPublishProgress, IPublishProgressListener } from './progress'; export interface AssetPublishingOptions { @@ -113,6 +114,10 @@ export class AssetPublishing implements IPublishProgress { }, dockerFactory: new DockerFactory(), }; + if (options.progressListener) { + setShellProgressListener(options.progressListener); + } + setGlobalCompletionProgress(this.percentComplete); } /** @@ -249,10 +254,12 @@ export class AssetPublishing implements IPublishProgress { } public get percentComplete() { - if (this.totalOperations === 0) { - return 100; - } - return Math.floor((this.completedOperations / this.totalOperations) * 100); + const completionProgress = + this.totalOperations === 0 + ? 100 + : Math.floor((this.completedOperations / this.totalOperations) * 100); + setGlobalCompletionProgress(completionProgress); + return completionProgress; } public abort(): void { diff --git a/test/asset-publishing-logs.test.ts b/test/asset-publishing-logs.test.ts new file mode 100644 index 0000000..c897c38 --- /dev/null +++ b/test/asset-publishing-logs.test.ts @@ -0,0 +1,233 @@ +import { Manifest } from '@aws-cdk/cloud-assembly-schema'; +import { ListObjectsV2Command } from '@aws-sdk/client-s3'; +import { MockAws, mockS3 } from './mock-aws'; +import mockfs from './mock-fs'; +import { AssetManifest, AssetPublishing } from '../lib'; + +describe('Console Logging', () => { + // Store original console methods + const originalConsoleLog = console.log; + const originalConsoleError = console.error; + const originalConsoleWarn = console.warn; + const originalConsoleInfo = console.info; + const originalConsoleDebug = console.debug; + + // Create spies for console methods + let consoleLogSpy: jest.SpyInstance; + let consoleErrorSpy: jest.SpyInstance; + let consoleWarnSpy: jest.SpyInstance; + let consoleInfoSpy: jest.SpyInstance; + let consoleDebugSpy: jest.SpyInstance; + + beforeEach(() => { + // Mock filesystem with test assets + mockfs({ + '/test/cdk.out/assets.json': JSON.stringify({ + version: Manifest.version(), + files: { + 'asset1': { + source: { + path: 'some_file', + }, + destinations: { + dest1: { + bucketName: 'test-bucket', + objectKey: 'test-key', + region: 'us-east-1', + }, + }, + }, + }, + }), + '/test/cdk.out/some_file': 'test content', + }); + + // Set up spies for all console methods + consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(() => {}); + consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); + consoleWarnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {}); + consoleInfoSpy = jest.spyOn(console, 'info').mockImplementation(() => {}); + consoleDebugSpy = jest.spyOn(console, 'debug').mockImplementation(() => {}); + + // Mock S3 client to prevent actual AWS calls + mockS3.on(ListObjectsV2Command).resolves({ + Contents: [], + }); + }); + + afterEach(() => { + mockfs.restore(); + + // Restore all console methods + console.log = originalConsoleLog; + console.error = originalConsoleError; + console.warn = originalConsoleWarn; + console.info = originalConsoleInfo; + console.debug = originalConsoleDebug; + + // Clear all mocks + jest.clearAllMocks(); + }); + + test('no console output during successful asset publishing while still publishing assets', async () => { + const aws = new MockAws(); + const publishedAssets: string[] = []; + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + progressListener: { + onPublishEvent: (type, event) => { + if (type === 'success') { + publishedAssets.push(event.message); + } + }, + } + }); + + await pub.publish(); + + // Verify no console output occurred + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify asset was actually published + expect(publishedAssets.length).toBeGreaterThan(0); + expect(publishedAssets[0]).toContain('Published asset1:dest1'); + }); + + test('no console output when checking if asset is published while still checking status', async () => { + const aws = new MockAws(); + const checkEvents: string[] = []; + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + progressListener: { + onPublishEvent: (type, event) => { + if (type === 'check') { + checkEvents.push(event.message); + } + }, + } + }); + + const manifest = AssetManifest.fromPath(mockfs.path('/test/cdk.out')); + await pub.isEntryPublished(manifest.entries[0]); + + // Verify no console output occurred + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify check was actually performed + expect(checkEvents.length).toBeGreaterThan(0); + expect(checkEvents[0]).toContain('Check'); + }); + + test('no console output when building asset', async () => { + const aws = new MockAws(); + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { aws }); + + const manifest = AssetManifest.fromPath(mockfs.path('/test/cdk.out')); + await pub.buildEntry(manifest.entries[0]); + + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + }); + + test('no console output during parallel publishing while still publishing assets', async () => { + const aws = new MockAws(); + const publishEvents: string[] = []; + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + publishInParallel: true, + progressListener: { + onPublishEvent: (type, event) => { + if (type === 'start' || type === 'success') { + publishEvents.push(event.message); + } + }, + } + }); + + await pub.publish(); + + // Verify no console output occurred + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify publishing actually occurred + expect(publishEvents.length).toBeGreaterThan(0); + expect(publishEvents).toContainEqual(expect.stringContaining('Publishing asset1:dest1')); + expect(publishEvents).toContainEqual(expect.stringContaining('Published asset1:dest1')); + }); + + test('no console output when publishing fails while still handling errors properly', async () => { + const aws = new MockAws(); + const failureEvents: string[] = []; + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + throwOnError: false, // Prevent the test from failing due to the error + progressListener: { + onPublishEvent: (type, event) => { + if (type === 'fail') { + failureEvents.push(event.message); + } + }, + } + }); + + // Force a failure by making S3 throw an error + const errorMessage = 'Simulated S3 error'; + mockS3.on(ListObjectsV2Command).rejects(new Error(errorMessage)); + + await pub.publish(); + + // Verify no console output occurred + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify error was properly handled + expect(failureEvents.length).toBeGreaterThan(0); + expect(failureEvents[0]).toContain(errorMessage); + expect(pub.hasFailures).toBe(true); + expect(pub.failures.length).toBe(1); + expect(pub.failures[0].error.message).toContain(errorMessage); + }); + + test('progress listener receives messages without console output', async () => { + const aws = new MockAws(); + const messages: string[] = []; + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + progressListener: { + onPublishEvent: (type, event) => { + messages.push(event.message); + }, + }, + }); + + await pub.publish(); + + // Verify that the progress listener received messages + expect(messages.length).toBeGreaterThan(0); + + // But verify no console output occurred + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + }); +}); \ No newline at end of file From 154951f256154d92bb05665b674ac839b8645441 Mon Sep 17 00:00:00 2001 From: github-actions Date: Thu, 26 Dec 2024 19:49:41 +0000 Subject: [PATCH 11/16] chore: self mutation Signed-off-by: github-actions --- test/asset-publishing-logs.test.ts | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/test/asset-publishing-logs.test.ts b/test/asset-publishing-logs.test.ts index c897c38..8122713 100644 --- a/test/asset-publishing-logs.test.ts +++ b/test/asset-publishing-logs.test.ts @@ -25,7 +25,7 @@ describe('Console Logging', () => { '/test/cdk.out/assets.json': JSON.stringify({ version: Manifest.version(), files: { - 'asset1': { + asset1: { source: { path: 'some_file', }, @@ -57,14 +57,14 @@ describe('Console Logging', () => { afterEach(() => { mockfs.restore(); - + // Restore all console methods console.log = originalConsoleLog; console.error = originalConsoleError; console.warn = originalConsoleWarn; console.info = originalConsoleInfo; console.debug = originalConsoleDebug; - + // Clear all mocks jest.clearAllMocks(); }); @@ -72,7 +72,7 @@ describe('Console Logging', () => { test('no console output during successful asset publishing while still publishing assets', async () => { const aws = new MockAws(); const publishedAssets: string[] = []; - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { aws, progressListener: { onPublishEvent: (type, event) => { @@ -80,7 +80,7 @@ describe('Console Logging', () => { publishedAssets.push(event.message); } }, - } + }, }); await pub.publish(); @@ -100,7 +100,7 @@ describe('Console Logging', () => { test('no console output when checking if asset is published while still checking status', async () => { const aws = new MockAws(); const checkEvents: string[] = []; - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { aws, progressListener: { onPublishEvent: (type, event) => { @@ -108,7 +108,7 @@ describe('Console Logging', () => { checkEvents.push(event.message); } }, - } + }, }); const manifest = AssetManifest.fromPath(mockfs.path('/test/cdk.out')); @@ -143,7 +143,7 @@ describe('Console Logging', () => { test('no console output during parallel publishing while still publishing assets', async () => { const aws = new MockAws(); const publishEvents: string[] = []; - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { aws, publishInParallel: true, progressListener: { @@ -152,7 +152,7 @@ describe('Console Logging', () => { publishEvents.push(event.message); } }, - } + }, }); await pub.publish(); @@ -173,7 +173,7 @@ describe('Console Logging', () => { test('no console output when publishing fails while still handling errors properly', async () => { const aws = new MockAws(); const failureEvents: string[] = []; - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { aws, throwOnError: false, // Prevent the test from failing due to the error progressListener: { @@ -182,7 +182,7 @@ describe('Console Logging', () => { failureEvents.push(event.message); } }, - } + }, }); // Force a failure by making S3 throw an error @@ -209,7 +209,7 @@ describe('Console Logging', () => { test('progress listener receives messages without console output', async () => { const aws = new MockAws(); const messages: string[] = []; - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { aws, progressListener: { onPublishEvent: (type, event) => { @@ -230,4 +230,4 @@ describe('Console Logging', () => { expect(consoleInfoSpy).not.toHaveBeenCalled(); expect(consoleDebugSpy).not.toHaveBeenCalled(); }); -}); \ No newline at end of file +}); From d683acfb77f2eedc45ffb1b4af5ee8160c31387c Mon Sep 17 00:00:00 2001 From: HBobertz Date: Thu, 26 Dec 2024 15:30:19 -0500 Subject: [PATCH 12/16] asset-publishing-tests --- test/asset-publishing-logs.test.ts | 350 ++++++++++++++++++++++++++++- 1 file changed, 348 insertions(+), 2 deletions(-) diff --git a/test/asset-publishing-logs.test.ts b/test/asset-publishing-logs.test.ts index 8122713..6bef321 100644 --- a/test/asset-publishing-logs.test.ts +++ b/test/asset-publishing-logs.test.ts @@ -1,8 +1,12 @@ +jest.mock('child_process'); + import { Manifest } from '@aws-cdk/cloud-assembly-schema'; import { ListObjectsV2Command } from '@aws-sdk/client-s3'; -import { MockAws, mockS3 } from './mock-aws'; +import { DescribeImagesCommand, DescribeRepositoriesCommand, GetAuthorizationTokenCommand } from '@aws-sdk/client-ecr'; +import { MockAws, mockS3, mockEcr } from './mock-aws'; +import { mockSpawn } from './mock-child_process'; import mockfs from './mock-fs'; -import { AssetManifest, AssetPublishing } from '../lib'; +import { AssetManifest, AssetPublishing, EventType } from '../lib'; describe('Console Logging', () => { // Store original console methods @@ -231,3 +235,345 @@ describe('Console Logging', () => { expect(consoleDebugSpy).not.toHaveBeenCalled(); }); }); + +describe('Shell Command Logging', () => { + // Store original console methods + const originalConsoleLog = console.log; + const originalConsoleError = console.error; + const originalConsoleWarn = console.warn; + const originalConsoleInfo = console.info; + const originalConsoleDebug = console.debug; + + // Create spies for console methods + let consoleLogSpy: jest.SpyInstance; + let consoleErrorSpy: jest.SpyInstance; + let consoleWarnSpy: jest.SpyInstance; + let consoleInfoSpy: jest.SpyInstance; + let consoleDebugSpy: jest.SpyInstance; + + beforeEach(() => { + // Mock filesystem with a docker asset that will trigger shell commands + mockfs({ + '/test/cdk.out/assets.json': JSON.stringify({ + version: Manifest.version(), + dockerImages: { + 'asset1': { + source: { + directory: 'docker-dir', + }, + destinations: { + dest1: { + repositoryName: 'test-repo', + imageTag: 'test-tag', + region: 'us-east-1', + }, + }, + }, + }, + }), + '/test/cdk.out/docker-dir/Dockerfile': 'FROM node:14', + }); + + // Set up spies for all console methods + consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(() => {}); + consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); + consoleWarnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {}); + consoleInfoSpy = jest.spyOn(console, 'info').mockImplementation(() => {}); + consoleDebugSpy = jest.spyOn(console, 'debug').mockImplementation(() => {}); + + // Reset and setup ECR mocks + mockEcr.reset(); + mockEcr.on(GetAuthorizationTokenCommand).resolves({ + authorizationData: [ + { authorizationToken: Buffer.from('user:pass').toString('base64'), proxyEndpoint: 'https://12345.dkr.ecr.region.amazonaws.com' } + ] + }); + mockEcr.on(DescribeRepositoriesCommand).resolves({ + repositories: [{ repositoryUri: '12345.dkr.ecr.region.amazonaws.com/test-repo' }] + }); + mockEcr.on(DescribeImagesCommand).rejects({ name: 'ImageNotFoundException' }); + + // Reset and setup S3 mocks + mockS3.reset(); + mockS3.on(ListObjectsV2Command).resolves({ + Contents: [], + }); + }); + + afterEach(() => { + mockfs.restore(); + + // Restore all console methods + console.log = originalConsoleLog; + console.error = originalConsoleError; + console.warn = originalConsoleWarn; + console.info = originalConsoleInfo; + console.debug = originalConsoleDebug; + + jest.clearAllMocks(); + }); + + test('captures stdout from shell commands through progress listener', async () => { + const debugMessages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + progressListener: { + onPublishEvent: (type, event) => { + if (type === EventType.DEBUG) { + debugMessages.push(event.message); + } + }, + } + }); + + // Mock successful shell commands with stdout + const expectAllSpawns = mockSpawn( + { + commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], + stdout: 'Login Succeeded\n', + }, + { + commandLine: ['docker', 'inspect', 'cdkasset-asset1'], + exitCode: 1 + }, + { + commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], + stdout: 'Building image...\nBuild completed\n', + }, + { + commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + }, + { + commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + } + ); + + await pub.publish(); + + // Verify no direct console output + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify shell output was captured in progress listener + expect(debugMessages).toEqual(expect.arrayContaining([ + 'Login Succeeded', + 'Building image...', + 'Build completed', + ])); + + expectAllSpawns(); + }); + + test('captures stderr from shell commands through progress listener', async () => { + const debugMessages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + progressListener: { + onPublishEvent: (type, event) => { + if (type === EventType.DEBUG) { + debugMessages.push(event.message); + } + }, + } + }); + + // Mock shell commands with stderr output + const expectAllSpawns = mockSpawn( + { + commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], + stderr: 'Warning: using default credentials\n', + }, + { + commandLine: ['docker', 'inspect', 'cdkasset-asset1'], + exitCode: 1 + }, + { + commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], + stderr: 'Warning: cache not found\n', + }, + { + commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + }, + { + commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + } + ); + + await pub.publish(); + + // Verify no direct console output + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify shell errors were captured in progress listener + expect(debugMessages).toEqual(expect.arrayContaining([ + 'Warning: using default credentials', + 'Warning: cache not found', + ])); + + expectAllSpawns(); + }); + + test('captures both stdout and stderr from shell commands', async () => { + const debugMessages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + progressListener: { + onPublishEvent: (type, event) => { + if (type === EventType.DEBUG) { + debugMessages.push(event.message); + } + }, + } + }); + + // Mock shell commands with both stdout and stderr + const expectAllSpawns = mockSpawn( + { + commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], + stdout: 'Login Succeeded\n', + stderr: 'Warning: using default credentials\n', + }, + { + commandLine: ['docker', 'inspect', 'cdkasset-asset1'], + exitCode: 1 + }, + { + commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], + }, + { + commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + }, + { + commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + } + ); + + await pub.publish(); + + // Verify no direct console output + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify both stdout and stderr were captured + expect(debugMessages).toEqual(expect.arrayContaining([ + 'Login Succeeded', + 'Warning: using default credentials', + ])); + + expectAllSpawns(); + }); + + test('captures shell command output in quiet mode', async () => { + const debugMessages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + quiet: true, + progressListener: { + onPublishEvent: (type, event) => { + if (type === EventType.DEBUG) { + debugMessages.push(event.message); + } + }, + } + }); + + // Mock shell commands with output + const expectAllSpawns = mockSpawn( + { + commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], + stdout: 'Login Succeeded\n', + stderr: 'Warning message\n', + }, + { + commandLine: ['docker', 'inspect', 'cdkasset-asset1'], + exitCode: 1 + }, + { + commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], + }, + { + commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + }, + { + commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + } + ); + + await pub.publish(); + + // Verify no direct console output + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // In quiet mode, output should still be captured but not displayed + expect(debugMessages.length).toBe(0); + + expectAllSpawns(); + }); + + test('shell output is captured when command fails', async () => { + const debugMessages: string[] = []; + const failMessages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + throwOnError: false, + progressListener: { + onPublishEvent: (type, event) => { + if (type === EventType.DEBUG) { + debugMessages.push(event.message); + } else if (type === EventType.FAIL) { + failMessages.push(event.message); + } + }, + } + }); + + // Mock failing shell command for initial docker login + const expectAllSpawns = mockSpawn( + { + commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], + stderr: 'Authentication failed\n', + exitCode: 1, + } + ); + + await pub.publish(); + + // Verify no direct console output + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + expect(consoleWarnSpy).not.toHaveBeenCalled(); + expect(consoleInfoSpy).not.toHaveBeenCalled(); + expect(consoleDebugSpy).not.toHaveBeenCalled(); + + // Verify error output was captured + expect(debugMessages).toContain('Authentication failed'); + expect(failMessages.length).toBeGreaterThan(0); + expect(pub.hasFailures).toBe(true); + + expectAllSpawns(); + }); + }); From 35c928d7b30b377a10c7ca67b7e4ab0963e4e25a Mon Sep 17 00:00:00 2001 From: HBobertz Date: Fri, 27 Dec 2024 14:21:13 -0500 Subject: [PATCH 13/16] global shell logger implementation --- bin/publish.ts | 22 +- lib/private/docker.ts | 33 +- lib/private/handlers/container-images.ts | 2 - lib/private/shell.ts | 69 +-- lib/progress.ts | 47 ++ lib/publishing.ts | 14 +- test/asset-publishing-logs.test.ts | 523 +++++++++-------------- 7 files changed, 292 insertions(+), 418 deletions(-) diff --git a/bin/publish.ts b/bin/publish.ts index 7e451a2..556493d 100644 --- a/bin/publish.ts +++ b/bin/publish.ts @@ -7,30 +7,34 @@ import { EventType, IPublishProgress, IPublishProgressListener, + globalOutputHandler, } from '../lib'; export async function publish(args: { path: string; assets?: string[]; profile?: string }) { let manifest = AssetManifest.fromPath(args.path); - log('verbose', `Loaded manifest from ${args.path}: ${manifest.entries.length} assets found`); - - if (args.assets && args.assets.length > 0) { - const selection = args.assets.map((a) => DestinationPattern.parse(a)); - manifest = manifest.select(selection); - log('verbose', `Applied selection: ${manifest.entries.length} assets selected.`); - } + // AssetPublishing will assign the global output handler const pub = new AssetPublishing(manifest, { aws: new DefaultAwsClient(args.profile), progressListener: new ConsoleProgress(), throwOnError: false, }); + globalOutputHandler.verbose( + `Loaded manifest from ${args.path}: ${manifest.entries.length} assets found` + ); + + if (args.assets && args.assets.length > 0) { + const selection = args.assets.map((a) => DestinationPattern.parse(a)); + manifest = manifest.select(selection); + globalOutputHandler.verbose(`Applied selection: ${manifest.entries.length} assets selected.`); + } + await pub.publish(); if (pub.hasFailures) { for (const failure of pub.failures) { - // eslint-disable-next-line no-console - console.error('Failure:', failure.error.stack); + globalOutputHandler.error(`Failure: ${failure.error.stack}`); } process.exitCode = 1; diff --git a/lib/private/docker.ts b/lib/private/docker.ts index fbdd25f..bfc3f40 100644 --- a/lib/private/docker.ts +++ b/lib/private/docker.ts @@ -2,10 +2,9 @@ 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 { IPublishProgressListener } from '../progress'; interface BuildOptions { readonly directory: string; @@ -53,16 +52,9 @@ export interface DockerCacheOption { readonly params?: { [key: string]: string }; } -export interface DockerOptions { - readonly logger?: Logger; - readonly progressListener?: IPublishProgressListener; -} - export class Docker { private configDir: string | undefined = undefined; - constructor(private readonly options?: DockerOptions) {} - /** * Whether an image with the given tag exists */ @@ -200,20 +192,17 @@ export class Docker { this.configDir = undefined; } - private async execute(args: string[], shellOptions: ShellOptions = {}) { + private async execute(args: string[], options: ShellOptions = {}) { const configArgs = this.configDir ? ['--config', this.configDir] : []; const pathToCdkAssets = path.resolve(__dirname, '..', '..', 'bin'); try { await shell([getDockerCmd(), ...configArgs, ...args], { - logger: this.options?.logger, - ...shellOptions, + ...options, env: { - ...process.env, - ...shellOptions.env, - PATH: `${pathToCdkAssets}${path.delimiter}${shellOptions.env?.PATH ?? process.env.PATH}`, + ...options.env, + PATH: `${pathToCdkAssets}${path.delimiter}${options.env?.PATH ?? process.env.PATH}`, }, - progressListener: this.options?.progressListener, }); } catch (e: any) { if (e.code === 'ENOENT') { @@ -241,8 +230,6 @@ export class Docker { export interface DockerFactoryOptions { readonly repoUri: string; readonly ecr: IECRClient; - readonly logger: (m: string) => void; - readonly progressListener?: IPublishProgressListener; } /** @@ -257,10 +244,7 @@ export class DockerFactory { * Gets a Docker instance for building images. */ public async forBuild(options: DockerFactoryOptions): Promise { - const docker = new Docker({ - logger: options.logger, - progressListener: options.progressListener, - }); + const docker = new Docker(); // 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), @@ -279,10 +263,7 @@ export class DockerFactory { * Gets a Docker instance for pushing images to ECR. */ public async forEcrPush(options: DockerFactoryOptions) { - const docker = new Docker({ - logger: options.logger, - progressListener: options.progressListener, - }); + const docker = new Docker(); 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..ff4912f 100644 --- a/lib/private/handlers/container-images.ts +++ b/lib/private/handlers/container-images.ts @@ -38,7 +38,6 @@ export class ContainerImageAssetHandler implements IAssetHandler { const dockerForBuilding = await this.host.dockerFactory.forBuild({ repoUri: initOnce.repoUri, - logger: (m: string) => this.host.emitMessage(EventType.DEBUG, m), ecr: initOnce.ecr, }); @@ -85,7 +84,6 @@ export class ContainerImageAssetHandler implements IAssetHandler { const dockerForPushing = await this.host.dockerFactory.forEcrPush({ repoUri: initOnce.repoUri, - logger: (m: string) => this.host.emitMessage(EventType.DEBUG, m), ecr: initOnce.ecr, }); diff --git a/lib/private/shell.ts b/lib/private/shell.ts index 572dd4f..844d4a1 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -1,13 +1,11 @@ import * as child_process from 'child_process'; -import { EventType, IPublishProgress, IPublishProgressListener } from '../progress'; +import { EventType, globalOutputHandler } from '../progress'; export type Logger = (x: string) => void; export interface ShellOptions extends child_process.SpawnOptions { readonly quiet?: boolean; - readonly logger?: Logger; readonly input?: string; - readonly progressListener?: IPublishProgressListener; } /** @@ -17,11 +15,8 @@ export interface ShellOptions extends child_process.SpawnOptions { * string. */ export async function shell(command: string[], options: ShellOptions = {}): Promise { - if (options.logger) { - options.logger(renderCommandLine(command)); - } - - const outputHandler = new ShellOutputHandler(); + globalOutputHandler.publishEvent(EventType.START, command.join(' ')); + globalOutputHandler.info(renderCommandLine(command)); const child = child_process.spawn(command[0], command.slice(1), { ...options, @@ -39,32 +34,37 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom child.stdout!.on('data', (chunk) => { if (!options.quiet) { - outputHandler.handleOutput(chunk, false); + globalOutputHandler.publishEvent(chunk, EventType.DEBUG); } stdout.push(chunk); }); child.stderr!.on('data', (chunk) => { if (!options.quiet) { - outputHandler.handleOutput(chunk, true); + globalOutputHandler.publishEvent(chunk, EventType.DEBUG); } stderr.push(chunk); }); - child.once('error', reject); + child.once('error', (error) => { + globalOutputHandler.publishEvent(EventType.FAIL, error.message); + reject(error); + }); child.once('close', (code, signal) => { if (code === 0) { - resolve(Buffer.concat(stdout).toString('utf-8')); + const output = Buffer.concat(stdout).toString('utf-8'); + globalOutputHandler.publishEvent(EventType.SUCCESS, output); + resolve(output); } else { - const out = Buffer.concat(stderr).toString('utf-8').trim(); - reject( - new ProcessFailed( - code, - signal, - `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${out}` - ) + const errorOutput = Buffer.concat(stderr).toString('utf-8').trim(); + const error = new ProcessFailed( + code, + signal, + `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${errorOutput}` ); + globalOutputHandler.publishEvent(EventType.FAIL, error.message); + reject(error); } }); }); @@ -145,34 +145,3 @@ function windowsEscape(x: string): string { .map((c) => (shellMeta.has(x) ? '^' + c : c)) .join(''); } - -export class ShellOutputHandler { - public handleOutput(chunk: any, isError: boolean = false) { - const text = chunk.toString(); - - // Send to progress listener if configured - if (shellProgressListener && text.length > 0) { - const progressEvent: IPublishProgress = { - message: text, - abort: () => {}, - percentComplete: globalCompletionProgress, - }; - shellProgressListener.onPublishEvent( - isError ? EventType.FAIL : EventType.DEBUG, - progressEvent - ); - } - } -} - -let shellProgressListener: IPublishProgressListener | undefined; - -let globalCompletionProgress: number; - -export function setShellProgressListener(listener: IPublishProgressListener) { - shellProgressListener = listener; -} - -export function setGlobalCompletionProgress(progress: number) { - globalCompletionProgress = progress; -} diff --git a/lib/progress.ts b/lib/progress.ts index b2c8e77..c61563b 100644 --- a/lib/progress.ts +++ b/lib/progress.ts @@ -84,3 +84,50 @@ export interface IPublishProgress { */ abort(): void; } + +class GlobalOutputHandler { + private progressListener: IPublishProgressListener | undefined; + private completionProgress: number; + + constructor(completionProgress: number = 0, progressListener?: IPublishProgressListener) { + this.progressListener = progressListener; + this.completionProgress = completionProgress; + } + + public setListener(listener: IPublishProgressListener) { + this.progressListener = listener; + } + + public setCompletionProgress(progress: number) { + this.completionProgress = progress; + } + + public publishEvent(eventType: EventType = EventType.DEBUG, text: string) { + const progressEvent: IPublishProgress = { + message: text, + abort: () => {}, + percentComplete: this.completionProgress, + }; + if (this.progressListener) { + this.progressListener.onPublishEvent(eventType, progressEvent); + } + } + + public verbose(text: string) { + this.publishEvent(EventType.DEBUG, text); + } + + public error(text: string) { + this.publishEvent(EventType.FAIL, text); + } + + public info(text: string) { + this.publishEvent(EventType.SUCCESS, text); + } + + public hasListener() { + return this.progressListener !== undefined; + } +} + +export let globalOutputHandler = new GlobalOutputHandler(); diff --git a/lib/publishing.ts b/lib/publishing.ts index fb0e4b4..1b4020c 100644 --- a/lib/publishing.ts +++ b/lib/publishing.ts @@ -4,8 +4,12 @@ import { IAssetHandler, IHandlerHost, type PublishOptions } from './private/asse import { DockerFactory } from './private/docker'; import { makeAssetHandler } from './private/handlers'; import { pLimit } from './private/p-limit'; -import { setGlobalCompletionProgress, setShellProgressListener } from './private/shell'; -import { EventType, IPublishProgress, IPublishProgressListener } from './progress'; +import { + EventType, + IPublishProgress, + IPublishProgressListener, + globalOutputHandler, +} from './progress'; export interface AssetPublishingOptions { /** @@ -115,9 +119,9 @@ export class AssetPublishing implements IPublishProgress { dockerFactory: new DockerFactory(), }; if (options.progressListener) { - setShellProgressListener(options.progressListener); + globalOutputHandler.setListener(options.progressListener); } - setGlobalCompletionProgress(this.percentComplete); + globalOutputHandler.setCompletionProgress(this.percentComplete); } /** @@ -258,7 +262,7 @@ export class AssetPublishing implements IPublishProgress { this.totalOperations === 0 ? 100 : Math.floor((this.completedOperations / this.totalOperations) * 100); - setGlobalCompletionProgress(completionProgress); + globalOutputHandler.setCompletionProgress(completionProgress); return completionProgress; } diff --git a/test/asset-publishing-logs.test.ts b/test/asset-publishing-logs.test.ts index 6bef321..3c1c667 100644 --- a/test/asset-publishing-logs.test.ts +++ b/test/asset-publishing-logs.test.ts @@ -1,8 +1,12 @@ jest.mock('child_process'); import { Manifest } from '@aws-cdk/cloud-assembly-schema'; +import { + DescribeImagesCommand, + DescribeRepositoriesCommand, + GetAuthorizationTokenCommand, +} from '@aws-sdk/client-ecr'; import { ListObjectsV2Command } from '@aws-sdk/client-s3'; -import { DescribeImagesCommand, DescribeRepositoriesCommand, GetAuthorizationTokenCommand } from '@aws-sdk/client-ecr'; import { MockAws, mockS3, mockEcr } from './mock-aws'; import { mockSpawn } from './mock-child_process'; import mockfs from './mock-fs'; @@ -237,343 +241,210 @@ describe('Console Logging', () => { }); describe('Shell Command Logging', () => { - // Store original console methods - const originalConsoleLog = console.log; - const originalConsoleError = console.error; - const originalConsoleWarn = console.warn; - const originalConsoleInfo = console.info; - const originalConsoleDebug = console.debug; - - // Create spies for console methods - let consoleLogSpy: jest.SpyInstance; - let consoleErrorSpy: jest.SpyInstance; - let consoleWarnSpy: jest.SpyInstance; - let consoleInfoSpy: jest.SpyInstance; - let consoleDebugSpy: jest.SpyInstance; - - beforeEach(() => { - // Mock filesystem with a docker asset that will trigger shell commands - mockfs({ - '/test/cdk.out/assets.json': JSON.stringify({ - version: Manifest.version(), - dockerImages: { - 'asset1': { - source: { - directory: 'docker-dir', - }, - destinations: { - dest1: { - repositoryName: 'test-repo', - imageTag: 'test-tag', - region: 'us-east-1', - }, + let consoleLogSpy: jest.SpyInstance; + let consoleErrorSpy: jest.SpyInstance; + + beforeEach(() => { + consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(() => {}); + consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); + + // Mock filesystem with docker test assets + mockfs({ + '/test/cdk.out/assets.json': JSON.stringify({ + version: Manifest.version(), + dockerImages: { + theDockerAsset: { + source: { + directory: 'dockerdir', + }, + destinations: { + theDestination: { + region: 'us-east-1', + repositoryName: 'repo', + imageTag: 'tag', }, }, }, - }), - '/test/cdk.out/docker-dir/Dockerfile': 'FROM node:14', - }); - - // Set up spies for all console methods - consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(() => {}); - consoleErrorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); - consoleWarnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {}); - consoleInfoSpy = jest.spyOn(console, 'info').mockImplementation(() => {}); - consoleDebugSpy = jest.spyOn(console, 'debug').mockImplementation(() => {}); - - // Reset and setup ECR mocks - mockEcr.reset(); - mockEcr.on(GetAuthorizationTokenCommand).resolves({ - authorizationData: [ - { authorizationToken: Buffer.from('user:pass').toString('base64'), proxyEndpoint: 'https://12345.dkr.ecr.region.amazonaws.com' } - ] - }); - mockEcr.on(DescribeRepositoriesCommand).resolves({ - repositories: [{ repositoryUri: '12345.dkr.ecr.region.amazonaws.com/test-repo' }] - }); - mockEcr.on(DescribeImagesCommand).rejects({ name: 'ImageNotFoundException' }); - - // Reset and setup S3 mocks - mockS3.reset(); - mockS3.on(ListObjectsV2Command).resolves({ - Contents: [], - }); - }); - - afterEach(() => { - mockfs.restore(); - - // Restore all console methods - console.log = originalConsoleLog; - console.error = originalConsoleError; - console.warn = originalConsoleWarn; - console.info = originalConsoleInfo; - console.debug = originalConsoleDebug; - - jest.clearAllMocks(); - }); - - test('captures stdout from shell commands through progress listener', async () => { - const debugMessages: string[] = []; - const aws = new MockAws(); - - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { - aws, - progressListener: { - onPublishEvent: (type, event) => { - if (type === EventType.DEBUG) { - debugMessages.push(event.message); - } - }, - } - }); - - // Mock successful shell commands with stdout - const expectAllSpawns = mockSpawn( - { - commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], - stdout: 'Login Succeeded\n', - }, - { - commandLine: ['docker', 'inspect', 'cdkasset-asset1'], - exitCode: 1 - }, - { - commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], - stdout: 'Building image...\nBuild completed\n', - }, - { - commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], }, - { - commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], - } - ); - - await pub.publish(); - - // Verify no direct console output - expect(consoleLogSpy).not.toHaveBeenCalled(); - expect(consoleErrorSpy).not.toHaveBeenCalled(); - expect(consoleWarnSpy).not.toHaveBeenCalled(); - expect(consoleInfoSpy).not.toHaveBeenCalled(); - expect(consoleDebugSpy).not.toHaveBeenCalled(); - - // Verify shell output was captured in progress listener - expect(debugMessages).toEqual(expect.arrayContaining([ - 'Login Succeeded', - 'Building image...', - 'Build completed', - ])); - - expectAllSpawns(); + }), + '/test/cdk.out/dockerdir/Dockerfile': 'FROM node:14', }); - - test('captures stderr from shell commands through progress listener', async () => { - const debugMessages: string[] = []; - const aws = new MockAws(); - - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { - aws, - progressListener: { - onPublishEvent: (type, event) => { - if (type === EventType.DEBUG) { - debugMessages.push(event.message); - } - }, - } - }); - - // Mock shell commands with stderr output - const expectAllSpawns = mockSpawn( - { - commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], - stderr: 'Warning: using default credentials\n', - }, - { - commandLine: ['docker', 'inspect', 'cdkasset-asset1'], - exitCode: 1 - }, - { - commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], - stderr: 'Warning: cache not found\n', - }, + + // Setup ECR mocks + mockEcr.reset(); + mockEcr.on(GetAuthorizationTokenCommand).resolves({ + authorizationData: [ { - commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + authorizationToken: Buffer.from('user:pass').toString('base64'), + proxyEndpoint: 'https://12345.dkr.ecr.region.amazonaws.com', }, - { - commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], - } - ); - - await pub.publish(); - - // Verify no direct console output - expect(consoleLogSpy).not.toHaveBeenCalled(); - expect(consoleErrorSpy).not.toHaveBeenCalled(); - expect(consoleWarnSpy).not.toHaveBeenCalled(); - expect(consoleInfoSpy).not.toHaveBeenCalled(); - expect(consoleDebugSpy).not.toHaveBeenCalled(); - - // Verify shell errors were captured in progress listener - expect(debugMessages).toEqual(expect.arrayContaining([ - 'Warning: using default credentials', - 'Warning: cache not found', - ])); - - expectAllSpawns(); + ], }); - - test('captures both stdout and stderr from shell commands', async () => { - const debugMessages: string[] = []; - const aws = new MockAws(); - - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { - aws, - progressListener: { - onPublishEvent: (type, event) => { - if (type === EventType.DEBUG) { - debugMessages.push(event.message); - } - }, - } - }); - - // Mock shell commands with both stdout and stderr - const expectAllSpawns = mockSpawn( - { - commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], - stdout: 'Login Succeeded\n', - stderr: 'Warning: using default credentials\n', - }, - { - commandLine: ['docker', 'inspect', 'cdkasset-asset1'], - exitCode: 1 - }, - { - commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], - }, - { - commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], - }, - { - commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], - } - ); - - await pub.publish(); - - // Verify no direct console output - expect(consoleLogSpy).not.toHaveBeenCalled(); - expect(consoleErrorSpy).not.toHaveBeenCalled(); - expect(consoleWarnSpy).not.toHaveBeenCalled(); - expect(consoleInfoSpy).not.toHaveBeenCalled(); - expect(consoleDebugSpy).not.toHaveBeenCalled(); - - // Verify both stdout and stderr were captured - expect(debugMessages).toEqual(expect.arrayContaining([ - 'Login Succeeded', - 'Warning: using default credentials', - ])); - - expectAllSpawns(); + mockEcr.on(DescribeRepositoriesCommand).resolves({ + repositories: [{ repositoryUri: '12345.dkr.ecr.region.amazonaws.com/repo' }], }); - - test('captures shell command output in quiet mode', async () => { - const debugMessages: string[] = []; - const aws = new MockAws(); - - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { - aws, - quiet: true, - progressListener: { - onPublishEvent: (type, event) => { - if (type === EventType.DEBUG) { - debugMessages.push(event.message); - } - }, - } - }); - - // Mock shell commands with output - const expectAllSpawns = mockSpawn( - { - commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], - stdout: 'Login Succeeded\n', - stderr: 'Warning message\n', - }, - { - commandLine: ['docker', 'inspect', 'cdkasset-asset1'], - exitCode: 1 + mockEcr.on(DescribeImagesCommand).rejects({ name: 'ImageNotFoundException' }); + }); + + afterEach(() => { + mockfs.restore(); + jest.clearAllMocks(); + }); + + test('captures both stdout and stderr from shell commands', async () => { + const messages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + progressListener: { + onPublishEvent: (type: EventType, event) => { + messages.push(event.message); }, - { - commandLine: ['docker', 'build', '--tag', 'cdkasset-asset1', '.'], + }, + }); + + // Mock Docker commands with output + const expectAllSpawns = mockSpawn( + { + commandLine: [ + 'docker', + 'login', + '--username', + 'user', + '--password-stdin', + 'https://12345.dkr.ecr.region.amazonaws.com', + ], + stdout: 'Login Succeeded', + }, + { + commandLine: ['docker', 'inspect', 'cdkasset-thedockerasset'], + exitCode: 1, + stderr: 'Warning: using default credentials\n', + }, + { + commandLine: ['docker', 'build', '--tag', 'cdkasset-thedockerasset', '.'], + cwd: '/test/cdk.out/dockerdir', + }, + { + commandLine: [ + 'docker', + 'tag', + 'cdkasset-thedockerasset', + '12345.dkr.ecr.region.amazonaws.com/repo:tag', + ], + }, + { + commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/repo:tag'], + } + ); + + await pub.publish(); + expectAllSpawns(); + + // Check that both stdout and stderr were captured + expect(messages).toEqual( + expect.arrayContaining([ + expect.stringContaining('Login Succeeded'), + expect.stringContaining('Warning: using default credentials'), + ]) + ); + }); + + test('captures shell command output in quiet mode', async () => { + const messages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + quiet: true, + progressListener: { + onPublishEvent: (type: EventType, event) => { + messages.push(event.message); }, - { - commandLine: ['docker', 'tag', 'cdkasset-asset1', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], + }, + }); + + const expectAllSpawns = mockSpawn( + { + commandLine: [ + 'docker', + 'login', + '--username', + 'user', + '--password-stdin', + 'https://12345.dkr.ecr.region.amazonaws.com', + ], + stdout: 'Login Succeeded\n', + stderr: 'Warning message\n', + }, + { + commandLine: ['docker', 'inspect', 'cdkasset-thedockerasset'], + exitCode: 1, + }, + { + commandLine: ['docker', 'build', '--tag', 'cdkasset-thedockerasset', '.'], + cwd: '/test/cdk.out/dockerdir', + }, + { + commandLine: [ + 'docker', + 'tag', + 'cdkasset-thedockerasset', + '12345.dkr.ecr.region.amazonaws.com/repo:tag', + ], + }, + { + commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/repo:tag'], + } + ); + + await pub.publish(); + expectAllSpawns(); + + // In quiet mode, shell outputs should not be captured + expect(messages).not.toContain('Login Succeeded'); + expect(messages).not.toContain('Warning message'); + + // Verify no direct console output + expect(consoleLogSpy).not.toHaveBeenCalled(); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + }); + + test('shell output is captured when command fails', async () => { + const messages: string[] = []; + const aws = new MockAws(); + + const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { + aws, + throwOnError: false, + progressListener: { + onPublishEvent: (type: EventType, event) => { + messages.push(event.message); }, - { - commandLine: ['docker', 'push', '12345.dkr.ecr.region.amazonaws.com/test-repo:test-tag'], - } - ); - - await pub.publish(); - - // Verify no direct console output - expect(consoleLogSpy).not.toHaveBeenCalled(); - expect(consoleErrorSpy).not.toHaveBeenCalled(); - expect(consoleWarnSpy).not.toHaveBeenCalled(); - expect(consoleInfoSpy).not.toHaveBeenCalled(); - expect(consoleDebugSpy).not.toHaveBeenCalled(); - - // In quiet mode, output should still be captured but not displayed - expect(debugMessages.length).toBe(0); - - expectAllSpawns(); + }, }); - - test('shell output is captured when command fails', async () => { - const debugMessages: string[] = []; - const failMessages: string[] = []; - const aws = new MockAws(); - - const pub = new AssetPublishing(AssetManifest.fromPath(mockfs.path('/test/cdk.out')), { - aws, - throwOnError: false, - progressListener: { - onPublishEvent: (type, event) => { - if (type === EventType.DEBUG) { - debugMessages.push(event.message); - } else if (type === EventType.FAIL) { - failMessages.push(event.message); - } - }, - } - }); - - // Mock failing shell command for initial docker login - const expectAllSpawns = mockSpawn( - { - commandLine: ['docker', 'login', '--username', 'user', '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com'], - stderr: 'Authentication failed\n', - exitCode: 1, - } - ); - - await pub.publish(); - - // Verify no direct console output - expect(consoleLogSpy).not.toHaveBeenCalled(); - expect(consoleErrorSpy).not.toHaveBeenCalled(); - expect(consoleWarnSpy).not.toHaveBeenCalled(); - expect(consoleInfoSpy).not.toHaveBeenCalled(); - expect(consoleDebugSpy).not.toHaveBeenCalled(); - - // Verify error output was captured - expect(debugMessages).toContain('Authentication failed'); - expect(failMessages.length).toBeGreaterThan(0); - expect(pub.hasFailures).toBe(true); - - expectAllSpawns(); + + const expectAllSpawns = mockSpawn({ + commandLine: [ + 'docker', + 'login', + '--username', + 'user', + '--password-stdin', + 'https://12345.dkr.ecr.region.amazonaws.com', + ], + stderr: 'Authentication failed', + exitCode: 1, }); + + await pub.publish(); + expectAllSpawns(); + + // Check error capture + expect(messages).toEqual( + expect.arrayContaining([expect.stringContaining('Authentication failed')]) + ); + expect(pub.hasFailures).toBe(true); }); +}); From 3b98e84ea9ac690f96fd4e3e4b63cdfde2dd78ad Mon Sep 17 00:00:00 2001 From: HBobertz Date: Mon, 30 Dec 2024 11:04:59 -0500 Subject: [PATCH 14/16] adjust tests --- lib/private/shell.ts | 2 -- test/asset-publishing-logs.test.ts | 11 ++++++----- 2 files changed, 6 insertions(+), 7 deletions(-) diff --git a/lib/private/shell.ts b/lib/private/shell.ts index 844d4a1..af909b6 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -54,7 +54,6 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom child.once('close', (code, signal) => { if (code === 0) { const output = Buffer.concat(stdout).toString('utf-8'); - globalOutputHandler.publishEvent(EventType.SUCCESS, output); resolve(output); } else { const errorOutput = Buffer.concat(stderr).toString('utf-8').trim(); @@ -63,7 +62,6 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom signal, `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${errorOutput}` ); - globalOutputHandler.publishEvent(EventType.FAIL, error.message); reject(error); } }); diff --git a/test/asset-publishing-logs.test.ts b/test/asset-publishing-logs.test.ts index 3c1c667..8d37d73 100644 --- a/test/asset-publishing-logs.test.ts +++ b/test/asset-publishing-logs.test.ts @@ -291,7 +291,7 @@ describe('Shell Command Logging', () => { jest.clearAllMocks(); }); - test('captures both stdout and stderr from shell commands', async () => { + test('docker successfully emits publishing events when publishing asset', async () => { const messages: string[] = []; const aws = new MockAws(); @@ -315,12 +315,10 @@ describe('Shell Command Logging', () => { '--password-stdin', 'https://12345.dkr.ecr.region.amazonaws.com', ], - stdout: 'Login Succeeded', }, { commandLine: ['docker', 'inspect', 'cdkasset-thedockerasset'], exitCode: 1, - stderr: 'Warning: using default credentials\n', }, { commandLine: ['docker', 'build', '--tag', 'cdkasset-thedockerasset', '.'], @@ -345,8 +343,11 @@ describe('Shell Command Logging', () => { // Check that both stdout and stderr were captured expect(messages).toEqual( expect.arrayContaining([ - expect.stringContaining('Login Succeeded'), - expect.stringContaining('Warning: using default credentials'), + expect.stringContaining('Publishing theDockerAsset:theDestination'), + expect.stringContaining('Check 12345.dkr.ecr.region.amazonaws.com/repo:tag'), + expect.stringContaining('Building Docker image at '), + expect.stringContaining('Push 12345.dkr.ecr.region.amazonaws.com/repo:tag'), + expect.stringContaining('Published theDockerAsset:theDestination'), ]) ); }); From 91359d1c8fb975a8deefc8d20ad16a634f7118da Mon Sep 17 00:00:00 2001 From: HBobertz Date: Mon, 30 Dec 2024 11:16:01 -0500 Subject: [PATCH 15/16] add comment --- lib/progress.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/progress.ts b/lib/progress.ts index c61563b..3db7fdf 100644 --- a/lib/progress.ts +++ b/lib/progress.ts @@ -108,6 +108,7 @@ class GlobalOutputHandler { abort: () => {}, percentComplete: this.completionProgress, }; + // if no listener is passed we just swallow everything. if (this.progressListener) { this.progressListener.onPublishEvent(eventType, progressEvent); } From cacbcf4a7fb8af3107e43331c5f9c3bb95f497b9 Mon Sep 17 00:00:00 2001 From: HBobertz Date: Mon, 30 Dec 2024 15:12:02 -0500 Subject: [PATCH 16/16] small changes --- lib/private/shell.ts | 20 +++++++++++--------- test/asset-publishing-logs.test.ts | 4 ---- 2 files changed, 11 insertions(+), 13 deletions(-) diff --git a/lib/private/shell.ts b/lib/private/shell.ts index af909b6..ab69d35 100644 --- a/lib/private/shell.ts +++ b/lib/private/shell.ts @@ -11,8 +11,8 @@ export interface ShellOptions extends child_process.SpawnOptions { /** * OS helpers * - * Shell function which both prints to stdout and collects the output into a - * string. + * Shell function which both emits the output to the configured output handler, and collects the output + * to return it as a string. */ export async function shell(command: string[], options: ShellOptions = {}): Promise { globalOutputHandler.publishEvent(EventType.START, command.join(' ')); @@ -29,21 +29,21 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom child.stdin!.end(); } - const stdout = new Array(); - const stderr = new Array(); + const stdoutChunks = new Array(); + const stderrChunks = new Array(); child.stdout!.on('data', (chunk) => { if (!options.quiet) { globalOutputHandler.publishEvent(chunk, EventType.DEBUG); } - stdout.push(chunk); + stdoutChunks.push(chunk); }); child.stderr!.on('data', (chunk) => { if (!options.quiet) { globalOutputHandler.publishEvent(chunk, EventType.DEBUG); } - stderr.push(chunk); + stderrChunks.push(chunk); }); child.once('error', (error) => { @@ -53,14 +53,16 @@ export async function shell(command: string[], options: ShellOptions = {}): Prom child.once('close', (code, signal) => { if (code === 0) { - const output = Buffer.concat(stdout).toString('utf-8'); + const output = Buffer.concat(stdoutChunks).toString('utf-8'); resolve(output); } else { - const errorOutput = Buffer.concat(stderr).toString('utf-8').trim(); + const errorOutput = Buffer.concat(stderrChunks).toString('utf-8').trim(); + const error_message = `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${errorOutput}`; + globalOutputHandler.publishEvent(EventType.FAIL, error_message); const error = new ProcessFailed( code, signal, - `${renderCommandLine(command)} exited with ${code != null ? 'error code' : 'signal'} ${code ?? signal}: ${errorOutput}` + error_message, ); reject(error); } diff --git a/test/asset-publishing-logs.test.ts b/test/asset-publishing-logs.test.ts index 8d37d73..ac3170b 100644 --- a/test/asset-publishing-logs.test.ts +++ b/test/asset-publishing-logs.test.ts @@ -403,10 +403,6 @@ describe('Shell Command Logging', () => { await pub.publish(); expectAllSpawns(); - // In quiet mode, shell outputs should not be captured - expect(messages).not.toContain('Login Succeeded'); - expect(messages).not.toContain('Warning message'); - // Verify no direct console output expect(consoleLogSpy).not.toHaveBeenCalled(); expect(consoleErrorSpy).not.toHaveBeenCalled();