Improve our error messages when tests fail (#896)

* Add better error reporting for tests.

* Control the streams that a logger writes to

* In tests, write a debug log of events and print it when a test fails

* Fix a couple little things.

* Rename uvu-timeout.ts to rig-test.ts

* Rename env variable to WIREIT_DEBUG_LOG_FILE

.eslintrc.cjs

@@ -17,5 +17,9 @@ module.exports = {
     // maybe we should turn this on, but it started suddenly triggering in
     // an unrelated change.
     '@typescript-eslint/no-non-null-assertion': 'off',
+    '@typescript-eslint/no-unused-vars': [
+      'error',
+      {argsIgnorePattern: '^_', varsIgnorePattern: '^_'},
+    ],
   },
 };

src/cli-options.ts

@@ -12,7 +12,7 @@ import {MetricsLogger} from './logging/metrics-logger.js';
 import {ScriptReference} from './config.js';
 import {FailureMode} from './executor.js';
 import {unreachable} from './util/unreachable.js';
-import {Logger} from './logging/logger.js';
+import {Console, Logger} from './logging/logger.js';
 import {QuietCiLogger, QuietLogger} from './logging/quiet-logger.js';
 import {DefaultLogger} from './logging/default-logger.js';
 
@@ -58,7 +58,7 @@ export interface Options {
   logger: Logger;
 }
 
-export const getOptions = (): Result<Options> => {
+export const getOptions = async (): Promise<Result<Options>> => {
   // This environment variable is set by npm, yarn, and pnpm, and tells us which
   // script is running.
   const scriptName = process.env.npm_lifecycle_event;
@@ -185,26 +185,27 @@ export const getOptions = (): Result<Options> => {
 
   const agent = getNpmUserAgent();
 
+  const console = new Console(process.stdout, process.stderr);
+  const packageRoot = packageDir ?? process.cwd();
   const loggerResult = ((): Result<Logger> => {
-    const packageRoot = packageDir ?? process.cwd();
     const str = process.env['WIREIT_LOGGER'];
     if (!str) {
       if (process.env.CI) {
-        return {ok: true, value: new QuietCiLogger(packageRoot)};
+        return {ok: true, value: new QuietCiLogger(packageRoot, console)};
       }
-      return {ok: true, value: new QuietLogger(packageRoot)};
+      return {ok: true, value: new QuietLogger(packageRoot, console)};
     }
     if (str === 'quiet') {
-      return {ok: true, value: new QuietLogger(packageRoot)};
+      return {ok: true, value: new QuietLogger(packageRoot, console)};
     }
     if (str === 'quiet-ci') {
-      return {ok: true, value: new QuietCiLogger(packageRoot)};
+      return {ok: true, value: new QuietCiLogger(packageRoot, console)};
     }
     if (str === 'simple') {
-      return {ok: true, value: new DefaultLogger(packageRoot)};
+      return {ok: true, value: new DefaultLogger(packageRoot, console)};
     }
     if (str === 'metrics') {
-      return {ok: true, value: new MetricsLogger(packageRoot)};
+      return {ok: true, value: new MetricsLogger(packageRoot, console)};
     }
     return {
       ok: false,
@@ -222,6 +223,22 @@ export const getOptions = (): Result<Options> => {
     return loggerResult;
   }
 
+  let logger = loggerResult.value;
+  if (process.env['WIREIT_DEBUG_LOG_FILE']) {
+    const [{DebugLogger}, {CombinationLogger}] = await Promise.all([
+      import('./logging/debug-logger.js'),
+      import('./logging/combination-logger.js'),
+    ]);
+    const debugLogStream = await fs.createWriteStream(
+      process.env['WIREIT_DEBUG_LOG_FILE']!,
+    );
+    const debugLogConsole = new Console(debugLogStream, debugLogStream, true);
+    logger = new CombinationLogger(
+      [logger, new DebugLogger(packageRoot, debugLogConsole)],
+      console,
+    );
+  }
+
   return {
     ok: true,
     value: {
@@ -230,7 +247,7 @@ export const getOptions = (): Result<Options> => {
       cache: cacheResult.value,
       failureMode: failureModeResult.value,
       agent,
-      logger: loggerResult.value,
+      logger,
       ...getArgvOptions(script, agent),
     },
   };

src/cli.ts

@@ -12,6 +12,7 @@ import {unreachable} from './util/unreachable.js';
 import {Failure} from './event.js';
 import {packageDir, getOptions, Options} from './cli-options.js';
 import {DefaultLogger} from './logging/default-logger.js';
+import {Console} from './logging/logger.js';
 
 const run = async (options: Options): Promise<Result<void, Failure[]>> => {
   using logger = options.logger;
@@ -116,11 +117,12 @@ const run = async (options: Options): Promise<Result<void, Failure[]>> => {
   }
 };
 
-const optionsResult = getOptions();
+const optionsResult = await getOptions();
 if (!optionsResult.ok) {
   // if we can't figure out our options, we can't figure out what logger
   // we should use here, so just use the default logger.
-  const logger = new DefaultLogger(packageDir ?? process.cwd());
+  const console = new Console(process.stderr, process.stderr);
+  const logger = new DefaultLogger(packageDir ?? process.cwd(), console);
   logger.log(optionsResult.error);
   process.exit(1);
 }

src/logging/combination-logger.ts

@@ -0,0 +1,51 @@
+/**
+ * @license
+ * Copyright 2023 Google LLC
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import {Event} from '../event.js';
+import {Console, Logger} from './logger.js';
+
+// To prevent using the global console accidentally, we shadow it with
+// undefined
+const console = undefined;
+function markAsUsed(_: unknown) {}
+markAsUsed(console);
+
+/**
+ * A {@link Logger} that logs to multiple loggers.
+ */
+export class CombinationLogger implements Logger {
+  readonly console: Console;
+  readonly #loggers: readonly Logger[];
+
+  constructor(loggers: readonly Logger[], console: Console) {
+    this.console = console;
+    this.#loggers = loggers;
+  }
+
+  log(event: Event): void {
+    for (const logger of this.#loggers) {
+      logger.log(event);
+    }
+  }
+  printMetrics(): void {
+    for (const logger of this.#loggers) {
+      logger.printMetrics?.();
+    }
+  }
+  getWatchLogger?(): Logger {
+    const watchLoggers = this.#loggers.map(
+      (logger) => logger.getWatchLogger?.() ?? logger,
+    );
+    return new CombinationLogger(watchLoggers, this.console);
+  }
+
+  [Symbol.dispose](): void {
+    for (const logger of this.#loggers) {
+      logger[Symbol.dispose]?.();
+    }
+    this.console[Symbol.dispose]();
+  }
+}

src/logging/debug-logger.ts

@@ -0,0 +1,47 @@
+/**
+ * @license
+ * Copyright 2023 Google LLC
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import {DefaultLogger} from './default-logger.js';
+import {Event} from '../event.js';
+import {inspect} from 'node:util';
+
+// To prevent using the global console accidentally, we shadow it with
+// undefined
+const console = undefined;
+function markAsUsed(_: unknown) {}
+markAsUsed(console);
+
+/**
+ * A {@link Logger} for logging debug information, mainly in tests.
+ */
+export class DebugLogger extends DefaultLogger {
+  override log(event: Event) {
+    switch (event.type) {
+      case 'info':
+        this.console.log(`<info> ${event.detail}`);
+        break;
+      case 'failure':
+        this.console.log(`<failure> ${event.reason}`);
+        break;
+      case 'output':
+        // too verbose, log nothing
+        return;
+      case 'success':
+        this.console.log(`<success> ${event.reason}`);
+        break;
+      default: {
+        const never: never = event;
+        throw new Error(`Unknown event type: ${inspect(never)}`);
+      }
+    }
+    super.log(event);
+  }
+
+  [Symbol.dispose](): void {
+    super[Symbol.dispose]();
+    this.console[Symbol.dispose]();
+  }
+}