diff --git a/packages/aws-cdk/lib/api/util/cloudformation/stack-activity-monitor.ts b/packages/aws-cdk/lib/api/util/cloudformation/stack-activity-monitor.ts index 3c8af416cc274..d3f6e843d0965 100644 --- a/packages/aws-cdk/lib/api/util/cloudformation/stack-activity-monitor.ts +++ b/packages/aws-cdk/lib/api/util/cloudformation/stack-activity-monitor.ts @@ -3,7 +3,7 @@ import { ArtifactMetadataEntryType, type MetadataEntry } from '@aws-cdk/cloud-as import type { CloudFormationStackArtifact } from '@aws-cdk/cx-api'; import * as chalk from 'chalk'; import { ResourceEvent, StackEventPoller } from './stack-event-poller'; -import { error, logLevel, LogLevel, setLogLevel } from '../../../logging'; +import { error, LogLevel, setLogLevel } from '../../../logging'; import type { ICloudFormationClient } from '../../aws-auth'; import { RewritableBlock } from '../display'; @@ -102,7 +102,7 @@ export class StackActivityMonitor { }; const isWindows = process.platform === 'win32'; - const verbose = options.logLevel ?? logLevel; + const verbose = options.logLevel ?? LogLevel.INFO; // On some CI systems (such as CircleCI) output still reports as a TTY so we also // need an individual check for whether we're running on CI. // see: https://discuss.circleci.com/t/circleci-terminal-is-a-tty-but-term-is-not-set/9965 @@ -626,7 +626,7 @@ export class CurrentActivityPrinter extends ActivityPrinterBase { */ public readonly updateSleep: number = 2_000; - private oldLogLevel: LogLevel = LogLevel.DEFAULT; + private oldLogLevel: LogLevel = LogLevel.INFO; private block = new RewritableBlock(this.stream); constructor(props: PrinterProps) { @@ -674,8 +674,7 @@ export class CurrentActivityPrinter extends ActivityPrinterBase { public start() { // Need to prevent the waiter from printing 'stack not stable' every 5 seconds, it messes // with the output calculations. - this.oldLogLevel = logLevel; - setLogLevel(LogLevel.DEFAULT); + setLogLevel(LogLevel.INFO); } public stop() { diff --git a/packages/aws-cdk/lib/cli.ts b/packages/aws-cdk/lib/cli.ts index 567dfd6201ab9..3ae17cbd268bd 100644 --- a/packages/aws-cdk/lib/cli.ts +++ b/packages/aws-cdk/lib/cli.ts @@ -22,7 +22,7 @@ import { realHandler as docs } from '../lib/commands/docs'; import { realHandler as doctor } from '../lib/commands/doctor'; import { MIGRATE_SUPPORTED_LANGUAGES, getMigrateScanType } from '../lib/commands/migrate'; import { availableInitLanguages, cliInit, printAvailableTemplates } from '../lib/init'; -import { data, debug, error, print, setLogLevel, setCI } from '../lib/logging'; +import { data, debug, error, print, setCI, setLogLevel, LogLevel } from '../lib/logging'; import { Notices } from '../lib/notices'; import { Command, Configuration, Settings } from '../lib/settings'; import * as version from '../lib/version'; @@ -48,8 +48,20 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise string; -const { stdout, stderr } = process; - -type WritableFactory = () => Writable; +/** + * Available log levels in order of increasing verbosity. + */ +export enum LogLevel { + ERROR = 'error', + WARN = 'warn', + INFO = 'info', + DEBUG = 'debug', + TRACE = 'trace', +} -export async function withCorkedLogging(block: () => Promise): Promise { - corkLogging(); - try { - return await block(); - } finally { - uncorkLogging(); - } +/** + * Configuration options for a log entry. + */ +export interface LogEntry { + level: LogLevel; + message: string; + timestamp?: boolean; + prefix?: string; + style?: ((str: string) => string); + forceStdout?: boolean; } +const { stdout, stderr } = process; + +// Corking mechanism let CORK_COUNTER = 0; const logBuffer: [Writable, string][] = []; -function corked() { - return CORK_COUNTER !== 0; -} +// Style mappings +const styleMap: Record string> = { + [LogLevel.ERROR]: chalk.red, + [LogLevel.WARN]: chalk.yellow, + [LogLevel.INFO]: chalk.white, + [LogLevel.DEBUG]: chalk.gray, + [LogLevel.TRACE]: chalk.gray, +}; -function corkLogging() { - CORK_COUNTER += 1; -} +// Stream selection +let CI = false; -function uncorkLogging() { - CORK_COUNTER -= 1; - if (!corked()) { - logBuffer.forEach(([stream, str]) => stream.write(str + '\n')); - logBuffer.splice(0); +/** + * Determines which output stream to use based on log level and configuration. + * @param level - The log level to determine stream for + * @param forceStdout - Whether to force stdout regardless of level + * @returns The appropriate Writable stream + */ +const getStream = (level: LogLevel, forceStdout?: boolean): Writable => { + // Special case - data() calls should always go to stdout + if (forceStdout) { + return stdout; } + if (level === LogLevel.ERROR) return stderr; + return CI ? stdout : stderr; +}; + +const levelPriority: Record = { + [LogLevel.ERROR]: 0, + [LogLevel.WARN]: 1, + [LogLevel.INFO]: 2, + [LogLevel.DEBUG]: 3, + [LogLevel.TRACE]: 4, +}; + +let currentLogLevel: LogLevel = LogLevel.INFO; + +/** + * Sets the current log level. Messages with a lower priority level will be filtered out. + * @param level - The new log level to set + */ +export function setLogLevel(level: LogLevel) { + currentLogLevel = level; } -const logger = (stream: Writable | WritableFactory, styles?: StyleFn[], timestamp?: boolean) => (fmt: string, ...args: unknown[]) => { - const ts = timestamp ? `[${formatTime(new Date())}] ` : ''; +/** + * Sets whether the logger is running in CI mode. + * In CI mode, all non-error output goes to stdout instead of stderr. + * @param newCI - Whether CI mode should be enabled + */ +export function setCI(newCI: boolean) { + CI = newCI; +} - let str = ts + util.format(fmt, ...args); - if (styles && styles.length) { - str = styles.reduce((a, style) => style(a), str); - } +/** + * Formats a date object into a timestamp string (HH:MM:SS). + * @param d - Date object to format + * @returns Formatted time string + */ +function formatTime(d: Date): string { + const pad = (n: number): string => n.toString().padStart(2, '0'); + return `${pad(d.getHours())}:${pad(d.getMinutes())}:${pad(d.getSeconds())}`; +} - const realStream = typeof stream === 'function' ? stream() : stream; +/** + * Executes a block of code with corked logging. All log messages during execution + * are buffered and only written after the block completes. + * @param block - Async function to execute with corked logging + * @returns Promise that resolves with the block's return value + */ +export async function withCorkedLogging(block: () => Promise): Promise { + CORK_COUNTER++; + try { + return await block(); + } finally { + CORK_COUNTER--; + if (CORK_COUNTER === 0) { + logBuffer.forEach(([stream, str]) => stream.write(str + '\n')); + logBuffer.splice(0); + } + } +} - // Logger is currently corked, so we store the message to be printed - // later when we are uncorked. - if (corked()) { - logBuffer.push([realStream, str]); +/** + * Core logging function that handles all log output. + * @param entry - LogEntry object or log level + * @param fmt - Format string (when using with log level) + * @param args - Format arguments (when using with log level) + */ +export function log(entry: LogEntry): void; +export function log(level: LogLevel, fmt: string, ...args: unknown[]): void; +export function log(levelOrEntry: LogLevel | LogEntry, fmt?: string, ...args: unknown[]): void { + // Normalize input + const entry: LogEntry = typeof levelOrEntry === 'string' + ? { level: levelOrEntry as LogLevel, message: util.format(fmt!, ...args) } + : levelOrEntry; + + // Check if we should log this level + if (levelPriority[entry.level] > levelPriority[currentLogLevel]) { return; } - realStream.write(str + '\n'); -}; + // Format the message + let finalMessage = entry.message; -function formatTime(d: Date) { - return `${lpad(d.getHours(), 2)}:${lpad(d.getMinutes(), 2)}:${lpad(d.getSeconds(), 2)}`; - - function lpad(x: any, w: number) { - const s = `${x}`; - return '0'.repeat(Math.max(w - s.length, 0)) + s; + // Add timestamp first if requested + if (entry.timestamp) { + finalMessage = `[${formatTime(new Date())}] ${finalMessage}`; } -} -export enum LogLevel { - /** Not verbose at all */ - DEFAULT = 0, - /** Pretty verbose */ - DEBUG = 1, - /** Extremely verbose */ - TRACE = 2, -} + // Add prefix AFTER timestamp + if (entry.prefix) { + finalMessage = `${entry.prefix} ${finalMessage}`; + } -export let logLevel = LogLevel.DEFAULT; -export let CI = false; + // Apply custom style if provided, otherwise use level-based style + const style = entry.style || styleMap[entry.level]; + finalMessage = style(finalMessage); -export function setLogLevel(newLogLevel: LogLevel) { - logLevel = newLogLevel; -} + // Get appropriate stream - pass through forceStdout flag + const stream = getStream(entry.level, entry.forceStdout); -export function setCI(newCI: boolean) { - CI = newCI; -} + // Handle corking + if (CORK_COUNTER > 0) { + logBuffer.push([stream, finalMessage]); + return; + } -export function increaseVerbosity() { - logLevel += 1; + // Write to stream + stream.write(finalMessage + '\n'); } -const stream = () => CI ? stdout : stderr; -const _debug = logger(stream, [chalk.gray], true); - -export const trace = (fmt: string, ...args: unknown[]) => logLevel >= LogLevel.TRACE && _debug(fmt, ...args); -export const debug = (fmt: string, ...args: unknown[]) => logLevel >= LogLevel.DEBUG && _debug(fmt, ...args); -export const error = logger(stderr, [chalk.red]); -export const warning = logger(stream, [chalk.yellow]); -export const success = logger(stream, [chalk.green]); -export const highlight = logger(stream, [chalk.bold]); -export const print = logger(stream); -export const data = logger(stdout); - -export type LoggerFunction = (fmt: string, ...args: unknown[]) => void; +// Convenience logging methods +export const error = (fmt: string, ...args: unknown[]) => log(LogLevel.ERROR, fmt, ...args); +export const warning = (fmt: string, ...args: unknown[]) => log(LogLevel.WARN, fmt, ...args); +export const info = (fmt: string, ...args: unknown[]) => log(LogLevel.INFO, fmt, ...args); +export const print = (fmt: string, ...args: unknown[]) => log(LogLevel.INFO, fmt, ...args); +export const data = (fmt: string, ...args: unknown[]) => log({ + level: LogLevel.INFO, + message: util.format(fmt, ...args), + forceStdout: true, +}); +export const debug = (fmt: string, ...args: unknown[]) => log(LogLevel.DEBUG, fmt, ...args); +export const trace = (fmt: string, ...args: unknown[]) => log(LogLevel.TRACE, fmt, ...args); + +export const success = (fmt: string, ...args: unknown[]) => log({ + level: LogLevel.INFO, + message: util.format(fmt, ...args), + style: chalk.green, +}); + +export const highlight = (fmt: string, ...args: unknown[]) => log({ + level: LogLevel.INFO, + message: util.format(fmt, ...args), + style: chalk.bold, +}); /** - * Create a logger output that features a constant prefix string. - * - * @param prefixString the prefix string to be appended before any log entry. - * @param fn the logger function to be used (typically one of the other functions in this module) - * - * @returns a new LoggerFunction. + * Creates a logging function that prepends a prefix to all messages. + * @param prefixString - String to prepend to all messages + * @param level - Log level to use (defaults to INFO) + * @returns Logging function that accepts format string and arguments */ -export function prefix(prefixString: string, fn: LoggerFunction): LoggerFunction { - return (fmt: string, ...args: any[]) => fn(`%s ${fmt}`, prefixString, ...args); -} +export function prefix(prefixString: string, level: LogLevel = LogLevel.INFO): (fmt: string, ...args: unknown[]) => void { + return (fmt: string, ...args: unknown[]) => log({ + level, + message: util.format(fmt, ...args), + prefix: prefixString, + }); +} \ No newline at end of file diff --git a/packages/aws-cdk/test/api/exec.test.ts b/packages/aws-cdk/test/api/exec.test.ts index ece738356d1db..2eceefc3fc1a6 100644 --- a/packages/aws-cdk/test/api/exec.test.ts +++ b/packages/aws-cdk/test/api/exec.test.ts @@ -37,7 +37,7 @@ beforeEach(() => { }); afterEach(() => { - setLogLevel(LogLevel.DEFAULT); + setLogLevel(LogLevel.INFO); sinon.restore(); bockfs.restore(); diff --git a/packages/aws-cdk/test/cli.test.ts b/packages/aws-cdk/test/cli.test.ts new file mode 100644 index 0000000000000..5ec5a353fae52 --- /dev/null +++ b/packages/aws-cdk/test/cli.test.ts @@ -0,0 +1,104 @@ +import { exec } from '../lib/cli'; +import { LogLevel, setLogLevel } from '../lib/logging'; + +// Store original version module exports so we don't conflict with other tests +const originalVersion = jest.requireActual('../lib/version'); + +// Mock the dependencies +jest.mock('../lib/logging', () => ({ + LogLevel: { + DEBUG: 'DEBUG', + TRACE: 'TRACE', + }, + setLogLevel: jest.fn(), + debug: jest.fn(), + error: jest.fn(), + print: jest.fn(), + data: jest.fn(), +})); + +jest.mock('@aws-cdk/cx-api'); +jest.mock('@jsii/check-node/run'); +jest.mock('../lib/platform-warnings', () => ({ + checkForPlatformWarnings: jest.fn().mockResolvedValue(undefined), +})); + +jest.mock('../lib/settings', () => ({ + Configuration: jest.fn().mockImplementation(() => ({ + load: jest.fn().mockResolvedValue(undefined), + settings: { + get: jest.fn().mockReturnValue(undefined), + }, + context: { + get: jest.fn().mockReturnValue([]), + }, + })), +})); + +jest.mock('../lib/notices', () => ({ + Notices: { + create: jest.fn().mockReturnValue({ + refresh: jest.fn().mockResolvedValue(undefined), + display: jest.fn(), + }), + }, +})); + +jest.mock('../lib/parse-command-line-arguments', () => ({ + parseCommandLineArguments: jest.fn().mockImplementation((args) => Promise.resolve({ + _: ['version'], + verbose: args.includes('-v') ? ( + args.filter((arg: string) => arg === '-v').length + ) : args.includes('--verbose') ? ( + parseInt(args[args.indexOf('--verbose') + 1]) || true + ) : undefined, + })), +})); + +describe('exec verbose flag tests', () => { + beforeEach(() => { + jest.clearAllMocks(); + // Set up version module for our tests + jest.mock('../lib/version', () => ({ + ...originalVersion, + DISPLAY_VERSION: 'test-version', + displayVersionMessage: jest.fn().mockResolvedValue(undefined), + })); + }); + + afterEach(() => { + // Restore the version module to its original state + jest.resetModules(); + jest.setMock('../lib/version', originalVersion); + }); + + test('should not set log level when no verbose flag is present', async () => { + await exec(['version']); + expect(setLogLevel).not.toHaveBeenCalled(); + }); + + test('should set DEBUG level with single -v flag', async () => { + await exec(['-v', 'version']); + expect(setLogLevel).toHaveBeenCalledWith(LogLevel.DEBUG); + }); + + test('should set TRACE level with double -v flag', async () => { + await exec(['-v', '-v', 'version']); + expect(setLogLevel).toHaveBeenCalledWith(LogLevel.TRACE); + }); + + test('should set DEBUG level with --verbose=1', async () => { + await exec(['--verbose', '1', 'version']); + expect(setLogLevel).toHaveBeenCalledWith(LogLevel.DEBUG); + }); + + test('should set TRACE level with --verbose=2', async () => { + await exec(['--verbose', '2', 'version']); + expect(setLogLevel).toHaveBeenCalledWith(LogLevel.TRACE); + }); + + test('should set TRACE level with verbose level > 2', async () => { + await exec(['--verbose', '3', 'version']); + expect(setLogLevel).toHaveBeenCalledWith(LogLevel.TRACE); + }); +}); \ No newline at end of file diff --git a/packages/aws-cdk/test/logging.test.ts b/packages/aws-cdk/test/logging.test.ts new file mode 100644 index 0000000000000..68db36d3b45ed --- /dev/null +++ b/packages/aws-cdk/test/logging.test.ts @@ -0,0 +1,152 @@ +import { LogLevel, log, setLogLevel, setCI, data, print, error, warning, success, debug, trace, prefix, withCorkedLogging } from '../lib/logging'; + +describe('logging', () => { + // Mock streams to capture output + let mockStdout: jest.Mock; + let mockStderr: jest.Mock; + + beforeEach(() => { + // Reset log level before each test + setLogLevel(LogLevel.INFO); + setCI(false); + + // Create mock functions to capture output + mockStdout = jest.fn(); + mockStderr = jest.fn(); + + // Mock the write methods directly + jest.spyOn(process.stdout, 'write').mockImplementation((chunk: any) => { + mockStdout(chunk.toString()); + return true; + }); + + jest.spyOn(process.stderr, 'write').mockImplementation((chunk: any) => { + mockStderr(chunk.toString()); + return true; + }); + }); + + afterEach(() => { + jest.restoreAllMocks(); + }); + describe('stream selection', () => { + test('data() always writes to stdout', () => { + data('test message'); + expect(mockStdout).toHaveBeenCalledWith(expect.stringContaining('test message\n')); + expect(mockStderr).not.toHaveBeenCalled(); + }); + + test('error() always writes to stderr', () => { + error('test error'); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('test error\n')); + expect(mockStdout).not.toHaveBeenCalled(); + }); + + test('print() writes to stderr by default', () => { + print('test print'); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('test print\n')); + expect(mockStdout).not.toHaveBeenCalled(); + }); + + test('print() writes to stdout in CI mode', () => { + setCI(true); + print('test print'); + expect(mockStdout).toHaveBeenCalledWith(expect.stringContaining('test print\n')); + expect(mockStderr).not.toHaveBeenCalled(); + }); + }); + + describe('log levels', () => { + test('respects log level settings', () => { + setLogLevel(LogLevel.ERROR); + error('error message'); + warning('warning message'); + print('print message'); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('error message\n')); + expect(mockStderr).not.toHaveBeenCalledWith(expect.stringContaining('warning message\n')); + expect(mockStderr).not.toHaveBeenCalledWith(expect.stringContaining('print message\n')); + }); + + test('debug messages only show at debug level', () => { + setLogLevel(LogLevel.INFO); + debug('debug message'); + expect(mockStderr).not.toHaveBeenCalled(); + + setLogLevel(LogLevel.DEBUG); + debug('debug message'); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('debug message\n')); + }); + + test('trace messages only show at trace level', () => { + setLogLevel(LogLevel.DEBUG); + trace('trace message'); + expect(mockStderr).not.toHaveBeenCalled(); + + setLogLevel(LogLevel.TRACE); + trace('trace message'); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('trace message\n')); + }); + }); + + describe('message formatting', () => { + test('formats messages with multiple arguments', () => { + print('Value: %d, String: %s', 42, 'test'); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('Value: 42, String: test\n')); + }); + + test('handles prefix correctly', () => { + const prefixedLog = prefix('PREFIX'); + prefixedLog('test message'); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('PREFIX test message\n')); + }); + + test('handles custom styles', () => { + success('success message'); + // Note: actual styling will depend on chalk, but we can verify the message is there + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('success message\n')); + }); + }); + + describe('corked logging', () => { + test('buffers messages when corked', async () => { + await withCorkedLogging(async () => { + print('message 1'); + print('message 2'); + expect(mockStderr).not.toHaveBeenCalled(); + }); + + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('message 1\n')); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('message 2\n')); + }); + + test('handles nested corking correctly', async () => { + await withCorkedLogging(async () => { + print('outer 1'); + await withCorkedLogging(async () => { + print('inner'); + }); + print('outer 2'); + expect(mockStderr).not.toHaveBeenCalled(); + }); + + expect(mockStderr).toHaveBeenCalledTimes(3); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('outer 1\n')); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('inner\n')); + expect(mockStderr).toHaveBeenCalledWith(expect.stringContaining('outer 2\n')); + }); + }); + + describe('timestamp and prefix handling', () => { + test('combines timestamp and prefix correctly', () => { + log({ + level: LogLevel.INFO, + message: 'test message', + timestamp: true, + prefix: 'PREFIX', + }); + expect(mockStderr).toHaveBeenCalledWith( + expect.stringMatching(/PREFIX \[\d{2}:\d{2}:\d{2}\] test message\n/), + ); + }); + }); +}); \ No newline at end of file