Merge pull request #1107 from chromaui/logging-config

Add support for `logLevel` and `logPrefix` options, use local timestamp as default prefix

action-src/main.ts

@@ -116,6 +116,8 @@ async function run() {
     const forceRebuild = getInput('forceRebuild');
     const ignoreLastBuildOnBranch = getInput('ignoreLastBuildOnBranch');
     const logFile = getInput('logFile');
+    const logLevel = getInput('logLevel');
+    const logPrefix = getInput('logPrefix');
     const only = getInput('only');
     const onlyChanged = getInput('onlyChanged');
     const onlyStoryFiles = getMultilineInput('onlyStoryFiles');
@@ -169,6 +171,8 @@ async function run() {
         ignoreLastBuildOnBranch: maybe(ignoreLastBuildOnBranch),
         interactive: false,
         logFile: maybe(logFile),
+        logLevel: maybe(logLevel),
+        logPrefix: maybe(logPrefix),
         only: maybe(only),
         onlyChanged: maybe(onlyChanged),
         onlyStoryFiles: maybe(onlyStoryFiles),

action.yml

@@ -59,6 +59,12 @@ inputs:
   logFile:
     description: 'Write CLI logs to a file'
     required: false
+  logLevel:
+    description: 'One of: silent, error, warn, info, debug (default: info)'
+    required: false
+  logPrefix:
+    description: 'Custom prefix for log messages (default: current timestamp)'
+    required: false
   only:
     description: 'Deprecated, replaced by onlyStoryNames'
     required: false

node-src/index.ts

@@ -105,10 +105,15 @@ export async function run({
   flags?: Flags;
   options?: Partial<Options>;
 }): Promise<Partial<Output>> {
+  const config = {
+    ...parseArguments(argv),
+    ...(flags && { flags }),
+    ...(extraOptions && { extraOptions }),
+  };
   const {
     sessionId = uuid(),
     env: environment = getEnvironment(),
-    log = createLogger(),
+    log = createLogger(config.flags, config.extraOptions),
   } = extraOptions || {};
 
   const packageInfo = await readPackageUp({ cwd: process.cwd() });
@@ -119,9 +124,7 @@ export async function run({
 
   const { path: packagePath, packageJson } = packageInfo;
   const ctx: InitialContext = {
-    ...parseArguments(argv),
-    ...(flags && { flags }),
-    ...(extraOptions && { extraOptions }),
+    ...config,
     packagePath,
     packageJson,
     env: environment,

node-src/lib/log.test.ts

@@ -0,0 +1,167 @@
+import { afterEach, beforeEach, describe, expect, it, MockInstance, vi } from 'vitest';
+
+import { createLogger } from './log';
+
+let consoleError: MockInstance<typeof console.error>;
+let consoleWarn: MockInstance<typeof console.warn>;
+let consoleInfo: MockInstance<typeof console.info>;
+let consoleDebug: MockInstance<typeof console.debug>;
+
+beforeEach(() => {
+  consoleError = vi.spyOn(console, 'error').mockImplementation(() => undefined);
+  consoleWarn = vi.spyOn(console, 'warn').mockImplementation(() => undefined);
+  consoleInfo = vi.spyOn(console, 'info').mockImplementation(() => undefined);
+  consoleDebug = vi.spyOn(console, 'debug').mockImplementation(() => undefined);
+
+  vi.useFakeTimers();
+  vi.setSystemTime(new Date().setTime(0));
+});
+
+afterEach(() => {
+  delete process.env.DISABLE_LOGGING;
+  delete process.env.LOG_LEVEL;
+  delete process.env.LOG_PREFIX;
+
+  consoleError.mockReset();
+  consoleWarn.mockReset();
+  consoleInfo.mockReset();
+  consoleDebug.mockReset();
+
+  vi.useRealTimers();
+});
+
+const timestamp = expect.stringMatching(/\d\d:\d\d:\d\d.\d\d\d/);
+
+describe('log prefix', () => {
+  it('should use the log prefix from environment variables', () => {
+    process.env.LOG_PREFIX = 'env-prefix';
+    const logger = createLogger({});
+    logger.info('message');
+    expect(consoleInfo).toHaveBeenCalledWith('env-prefix', 'message');
+  });
+
+  it('should use the log prefix from flags', () => {
+    process.env.LOG_PREFIX = 'env-prefix';
+    const logger = createLogger({ logPrefix: 'flag-prefix' });
+    logger.info('message');
+    expect(consoleInfo).toHaveBeenCalledWith('flag-prefix', 'message');
+  });
+
+  it('should prefer the log prefix from options', () => {
+    process.env.LOG_PREFIX = 'env-prefix';
+    const logger = createLogger({ logPrefix: 'flag-prefix' }, { logPrefix: 'option-prefix' });
+    logger.info('message');
+    expect(consoleInfo).toHaveBeenCalledWith('option-prefix', 'message');
+  });
+
+  it('should use a timestamp as prefix by default', () => {
+    const logger = createLogger({});
+    logger.info('message');
+    expect(consoleInfo).toHaveBeenCalledWith(timestamp, 'message');
+  });
+
+  it('should not use a prefix if set to an empty string', () => {
+    process.env.LOG_PREFIX = '';
+    const logger = createLogger({});
+    logger.info('message');
+    expect(consoleInfo).toHaveBeenCalledWith('message');
+  });
+
+  it('should not use a prefix in interactive mode', () => {
+    process.env.LOG_PREFIX = 'env-prefix';
+    const logger = createLogger({ interactive: true, logPrefix: 'flag-prefix' });
+    logger.info('message');
+    expect(consoleInfo).toHaveBeenCalledWith('message');
+  });
+});
+
+describe('log levels', () => {
+  it('should ignore debug messages by default', () => {
+    const logger = createLogger({});
+
+    logger.error('error', 1, 2);
+    expect(consoleError).toHaveBeenCalledWith(timestamp, 'error', '1', '2');
+
+    logger.warn('warning', 1, 2);
+    expect(consoleWarn).toHaveBeenCalledWith(timestamp, 'warning', '1', '2');
+
+    logger.info('message', 1, 2);
+    expect(consoleInfo).toHaveBeenCalledWith(timestamp, 'message', '1', '2');
+
+    logger.debug('data', 1, 2);
+    expect(consoleDebug).not.toHaveBeenCalled();
+  });
+
+  it('should use the log level from environment variables', () => {
+    process.env.LOG_LEVEL = 'debug';
+    const logger = createLogger({});
+
+    logger.error('error');
+    expect(consoleError).toHaveBeenCalledWith(timestamp, 'error');
+
+    logger.warn('warning');
+    expect(consoleWarn).toHaveBeenCalledWith(timestamp, 'warning');
+
+    logger.info('message');
+    expect(consoleInfo).toHaveBeenCalledWith(timestamp, 'message');
+
+    logger.debug('data');
+    expect(consoleDebug).toHaveBeenCalledWith(timestamp, 'data');
+  });
+
+  it('should use the log level from flags', () => {
+    process.env.LOG_LEVEL = 'debug';
+    const logger = createLogger({ logLevel: 'warn' });
+
+    logger.error('error');
+    expect(consoleError).toHaveBeenCalledWith(timestamp, 'error');
+
+    logger.warn('warning');
+    expect(consoleWarn).toHaveBeenCalledWith(timestamp, 'warning');
+
+    logger.info('message');
+    expect(consoleInfo).not.toHaveBeenCalled();
+
+    logger.debug('data');
+    expect(consoleDebug).not.toHaveBeenCalled();
+  });
+
+  it('should prefer the log level from options', () => {
+    process.env.LOG_LEVEL = 'debug';
+    const logger = createLogger({ logLevel: 'warn' }, { logLevel: 'error' });
+
+    logger.error('error');
+    expect(consoleError).toHaveBeenCalledWith(timestamp, 'error');
+
+    logger.warn('warning');
+    expect(consoleWarn).not.toHaveBeenCalled();
+
+    logger.info('message');
+    expect(consoleInfo).not.toHaveBeenCalled();
+
+    logger.debug('data');
+    expect(consoleDebug).not.toHaveBeenCalled();
+  });
+
+  it('should respect DISABLE_LOGGING regardless of logLevel flag or option', () => {
+    process.env.DISABLE_LOGGING = 'true';
+    process.env.LOG_LEVEL = 'debug';
+    const logger = createLogger({ logLevel: 'warn' }, { logLevel: 'error' });
+    logger.error('error');
+    expect(consoleError).not.toHaveBeenCalled();
+  });
+});
+
+it('stringifies non-primitive values', () => {
+  const logger = createLogger({});
+  logger.info('message', 1, true, null, undefined, { key: 'value' });
+  expect(consoleInfo).toHaveBeenCalledWith(
+    timestamp,
+    'message',
+    '1',
+    'true',
+    'null',
+    undefined,
+    JSON.stringify({ key: 'value' })
+  );
+});

node-src/lib/log.ts

@@ -4,47 +4,71 @@ import { createWriteStream, rm } from 'fs';
 import stripAnsi from 'strip-ansi';
 import { format } from 'util';
 
+import { Flags, Options } from '../types';
 import { errorSerializer } from './logSerializers';
 
 interface QueueMessage {
   type: LogType;
   messages: string[];
 }
 
-const { DISABLE_LOGGING, LOG_LEVEL = '' } = process.env;
 const LOG_LEVELS = { silent: 0, error: 1, warn: 2, info: 3, debug: 4 };
 const DEFAULT_LEVEL = 'info';
 
 // Top-level promise rejection handler to deal with initialization errors
 const handleRejection = (reason: string) => console.error('Unhandled promise rejection:', reason);
 process.on('unhandledRejection', handleRejection);
 
+const isPrintable = (value: any) => {
+  const type = typeof value;
+  return type === 'string' || type === 'number' || type === 'boolean';
+};
+
 // Omits any JSON metadata, returning only the message string
 const logInteractive = (args: any[]): string[] =>
   args
     .map((argument) => (argument && argument.message) || argument)
-    .filter((argument) => typeof argument === 'string');
+    .filter((argument) => isPrintable(argument))
+    .map(String);
 
-// Strips ANSI codes from messages and stringifies metadata to JSON
+// Stringifies metadata to JSON
 const logVerbose = (type: string, args: any[]) => {
   const stringify =
     type === 'error' ? (err: any) => JSON.stringify(errorSerializer(err)) : JSON.stringify;
-  return args.map((argument) =>
-    typeof argument === 'string' ? stripAnsi(argument) : stringify(argument)
-  );
+  return args.map((argument) => (isPrintable(argument) ? String(argument) : stringify(argument)));
 };
 
-const withTime = (messages: string[], color = false) => {
-  if (messages.every((message) => /^\s*$/.test(message))) return messages;
-  let time = new Date().toISOString().slice(11, 23);
-  if (color) time = chalk.dim(time);
-  return [
-    time + ' ',
-    ...messages.map((message) =>
-      typeof message === 'string' ? message.replaceAll('\n', `\n              `) : message
-    ),
-  ];
-};
+// Generate a timestamp like "14:30:00.123" in local time
+const getTimeString = () =>
+  new Date().toLocaleTimeString('en-US', {
+    hour: '2-digit',
+    minute: '2-digit',
+    second: '2-digit',
+    fractionalSecondDigits: 3,
+    hour12: false,
+  });
+
+const createPrefixer =
+  (color = false, prefix?: string) =>
+  (messages: string[]) => {
+    // Ignore empty log lines
+    if (messages.every((message) => /^\s*$/.test(message))) return messages;
+
+    // Use a timestamp as default prefix
+    const pre = prefix ?? chalk.dim(getTimeString());
+    if (pre === '') return color ? messages : messages.map((message) => stripAnsi(message));
+
+    // Pad lines with spaces to align with the prefix
+    const padding = ' '.repeat(stripAnsi(pre).length + 1);
+    return [
+      color ? pre : stripAnsi(pre),
+      ...messages.map((message) => {
+        if (typeof message !== 'string') return message;
+        const string = color ? message : stripAnsi(message);
+        return string.replaceAll('\n', `\n${padding}`);
+      }),
+    ];
+  };
 
 type LogType = 'error' | 'warn' | 'info' | 'debug';
 type LogFunction = (...args: any[]) => void;
@@ -93,25 +117,36 @@ const fileLogger = {
   },
 };
 
-export const createLogger = () => {
-  let level = (LOG_LEVEL.toLowerCase() as keyof typeof LOG_LEVELS) || DEFAULT_LEVEL;
-  if (DISABLE_LOGGING === 'true') level = 'silent';
+/* eslint-disable-next-line complexity */
+export const createLogger = (flags: Flags, options?: Partial<Options>) => {
+  const { DISABLE_LOGGING, LOG_LEVEL = '', LOG_PREFIX } = process.env;
+
+  let level =
+    options?.logLevel ||
+    flags.logLevel ||
+    (LOG_LEVEL.toLowerCase() as Flags['logLevel']) ||
+    DEFAULT_LEVEL;
+
+  if (DISABLE_LOGGING === 'true') {
+    level = 'silent';
+  }
 
-  const args = new Set(process.argv.slice(2));
-  let interactive = !args.has('--debug') && !args.has('--no-interactive');
+  let interactive = (options?.interactive || flags.interactive) && !(options?.debug || flags.debug);
   let enqueue = false;
   const queue: QueueMessage[] = [];
 
+  const logPrefixer = createPrefixer(true, options?.logPrefix || flags.logPrefix || LOG_PREFIX);
+  const filePrefixer = createPrefixer(false, options?.logPrefix || flags.logPrefix || LOG_PREFIX);
   const log =
     (type: LogType, logFileOnly?: boolean) =>
     (...args: any[]) => {
       if (LOG_LEVELS[level] < LOG_LEVELS[type]) return;
 
       const logs = logVerbose(type, args);
-      fileLogger.append(...withTime(logs));
+      fileLogger.append(...filePrefixer(logs));
       if (logFileOnly) return;
 
-      const messages = interactive ? logInteractive(args) : withTime(logs, true);
+      const messages = interactive ? logInteractive(args) : logPrefixer(logs);
       if (messages.length === 0) return;
 
       // Queue up the logs or print them right away

node-src/lib/parseArguments.ts

@@ -56,6 +56,8 @@ export default function parseArguments(argv: string[]) {
       --junit-report [filepath]        Write build results to a JUnit XML file. {buildNumber} will be replaced with the actual build number. [chromatic-build-{buildNumber}.xml]
       --list                           List available stories. This requires running a full build.
       --log-file [filepath]            Write log output to a file. Disable via --no-log-file. [chromatic.log]
+      --log-level <level>              One of "silent", "error", "warn", "info", "debug". Defaults to "info".
+      --log-prefix <prefix>            Prefix for each log line. Defaults to current timestamp except in interactive mode. Set to "" to disable.
       --no-file-hashing                Disable file hashing. This will cause all files to be uploaded on every build.
       --no-interactive                 Don't ask interactive questions about your setup and don't overwrite output. Always true in non-TTY environments.
       --storybook-log-file [filepath]  Write Storybook build output to a file. Disable via --no-storybook-log-file. [storybook-build.log]
@@ -113,6 +115,8 @@ export default function parseArguments(argv: string[]) {
         junitReport: { type: 'string' },
         list: { type: 'boolean' },
         logFile: { type: 'string' },
+        logLevel: { type: 'string', choices: ['silent', 'error', 'warn', 'info', 'debug'] },
+        logPrefix: { type: 'string' },
         storybookLogFile: { type: 'string' },
         traceChanged: { type: 'string' },
         uploadMetadata: { type: 'boolean' },

node-src/types.ts

@@ -51,6 +51,8 @@ export interface Flags {
   junitReport?: string;
   list?: boolean;
   logFile?: string;
+  logLevel?: 'silent' | 'error' | 'warn' | 'info' | 'debug';
+  logPrefix?: string;
   storybookLogFile?: string;
   traceChanged?: string;
   uploadMetadata?: boolean;
@@ -69,6 +71,8 @@ export interface Options extends Configuration {
 
   configFile?: Flags['configFile'];
   logFile?: Flags['logFile'];
+  logLevel?: Flags['logLevel'];
+  logPrefix?: Flags['logPrefix'];
   onlyChanged: boolean | string;
   onlyStoryFiles: Flags['onlyStoryFiles'];
   onlyStoryNames: Flags['onlyStoryNames'];