From b1c7851321aa0193163076c62c8cc047387f8fee Mon Sep 17 00:00:00 2001 From: HBobertz Date: Thu, 26 Dec 2024 14:48:27 -0500 Subject: [PATCH] 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