chore: change logging to use a single base logging method (#32081)

HBobertz · web-flow · commit 069b72ca5613 · 2024-11-27T18:07:14.000Z
Closes #32039 Modified the existing logging mechanism to route to a single log function. Adapted the existing structure so that very minimal changes were required for existing logging functions and how they are used today ---- *By submitting this pull request, I confirm that my contribution is made under the terms of the Apache-2.0 license*
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
@@ -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
@@ -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<n
 
   const argv = await parseCommandLineArguments(args, makeBrowserDefault(), await availableInitLanguages(), MIGRATE_SUPPORTED_LANGUAGES as string[], version.DISPLAY_VERSION, yargsNegativeAlias);
 
+  // if one -v, log at a DEBUG level
+  // if 2 -v, log at a TRACE level
   if (argv.verbose) {
-    setLogLevel(argv.verbose);
+    let logLevel: LogLevel;
+    switch (argv.verbose) {
+      case 1:
+        logLevel = LogLevel.DEBUG;
+        break;
+      case 2:
+      default:
+        logLevel = LogLevel.TRACE;
+        break;
+    }
+    setLogLevel(logLevel);
   }
 
   // Debug should always imply tracing
diff --git a/packages/aws-cdk/lib/logging.ts b/packages/aws-cdk/lib/logging.ts
@@ -2,114 +2,202 @@ import { Writable } from 'stream';
 import * as util from 'util';
 import * as chalk from 'chalk';
 
-type StyleFn = (str: string) => 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<A>(block: () => Promise<A>): Promise<A> {
-  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<LogLevel, (str: string) => 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, number> = {
+  [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<T>(block: () => Promise<T>): Promise<T> {
+  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,
+  });
+}
diff --git 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
diff --git a/packages/aws-cdk/test/logging.test.ts b/packages/aws-cdk/test/logging.test.ts
