test(ses-ava): use causal console (#2109)

packages/eventual-send/test/test-deep-send.js

@@ -1,4 +1,4 @@
-// This file does not start with "test-" because it is useful as an
+// This file is not really useful as an
 // automated test. Rather, its purpose is just to run it to see what a
 // deep stack looks like.
 
@@ -10,21 +10,30 @@ import { E } from './get-hp.js';
 const { freeze } = Object;
 
 const carol = freeze({
-  bar: () => assert.fail('Wut?'),
+  // Throw an error with redacted contents (here, a string and a number).
+  bar: label => assert.Fail`[${assert.quote(label)}] ${'blue'} is not ${42}`,
 });
 
 const bob = freeze({
-  foo: carolP => E(carolP).bar(),
+  foo: (label, carolP) => E(carolP).bar(label),
 });
 
 const alice = freeze({
-  test: () => E(bob).foo(carol),
+  test: label => E(bob).foo(label, carol),
 });
 
-test('deep-stacks E', t => {
-  const q = alice.test();
-  return q.catch(reason => {
-    t.assert(reason instanceof Error);
-    console.log('expected failure', reason);
-  });
+const testDeepStacksE = test.macro({
+  title: (title, loggerDescription, _getLogger) =>
+    `deep-stacks E with ${loggerDescription}${title ? ` (${title})` : ''}`,
+  exec: (t, loggerDescription, getLogger) => {
+    const p = alice.test(loggerDescription);
+    return p.catch(reason => {
+      t.true(reason instanceof Error);
+      const log = getLogger(t);
+      log('expected failure', reason);
+    });
+  },
 });
+
+test(testDeepStacksE, 'console.log', _t => console.log.bind(console));
+test(testDeepStacksE, 'ses-ava t.log', t => t.log.bind(t));

packages/eventual-send/test/test-deep-stacks.js

@@ -1,18 +1,26 @@
-// This file does not start with "test-" because it is useful as an
+// This file is not really useful as an
 // automated test. Rather, its purpose is just to run it to see what a
 // deep stack looks like.
 
 import { test } from './prepare-test-env-ava.js';
 
 import { E } from './get-hp.js';
 
-test('deep-stacks when', t => {
-  let r;
-  const p = new Promise(res => (r = res));
-  const q = E.when(p, v1 => E.when(v1 + 1, v2 => assert.equal(v2, 22)));
-  r(33);
-  return q.catch(reason => {
-    t.assert(reason instanceof Error);
-    console.log('expected failure', reason);
-  });
+const testDeepStacksWhen = test.macro({
+  title: (title, loggerDescription, _getLogger) =>
+    `deep-stacks E.when with ${loggerDescription}${title ? ` (${title})` : ''}`,
+  exec: (t, _loggerDescription, getLogger) => {
+    let r;
+    const p = new Promise(res => (r = res));
+    const q = E.when(p, v1 => E.when(v1 + 1, v2 => assert.equal(v2, 22)));
+    r(33);
+    return q.catch(reason => {
+      t.assert(reason instanceof Error);
+      const log = getLogger(t);
+      log('expected failure', reason);
+    });
+  },
 });
+
+test(testDeepStacksWhen, 'console.log', _t => console.log.bind(console));
+test(testDeepStacksWhen, 'ses-ava t.log', t => t.log.bind(t));

packages/ses-ava/NEWS.md

@@ -1,4 +1,14 @@
-User-visible changes in SES-Ava:
+User-visible changes in `@endo/ses-ava`:
+
+# Next release
+
+- Ava's `t.log` buffers logged messages, so it can be output later with its
+  test case. But this uses Ava's own console emulation.
+  This loses all the redacted error information printed by SES's `console`.
+  Ses-ava's virtual `t.log` now combines these advantages,
+  using SES's console logic to show an error's hidden information,
+  while directing the output from that logic through Ava's original `t.log`,
+  so it appears at the right position.
 
 # 0.2.38 (2023-03-07)
 

packages/ses-ava/src/ses-ava-test.js

@@ -1,16 +1,59 @@
+/* global globalThis */
 import 'ses';
 
-const { stringify } = JSON;
-const { defineProperty, freeze } = Object;
-const { apply } = Reflect;
+/**
+ * Copied from the ses-shim's console-shim.js file, since the idea is that
+ * these communicate not by export import, but rather by convention plus
+ * feature testing. The following test is from there:
+ *
+ *`makeCausalConsoleFromLoggerForSesAva` is privileged because it exposes
+ * unredacted error info onto the `Logger` provided by the caller. It
+ * should not be made available to non-privileged code.
+ *
+ * Further, we consider this particular API choice to be experimental
+ * and may change in the future. It is currently only intended for use by
+ * `@endo/ses-ava`, with which it will be co-maintained.
+ *
+ * Thus, the SES console-shim.js makes `makeCausalConsoleFromLoggerForSesAva`
+ * available on `globalThis` which it *assumes* is the global of the start
+ * compartment and is therefore allowed to hold powers that should not be
+ * available in constructed compartments. It makes it available as the value of
+ * a global property named by a registered symbol named
+ * `MAKE_CAUSAL_CONSOLE_FROM_LOGGER_KEY_FOR_SES_AVA`.
+ *
+ * Anyone accessing this, including `@endo/ses-ava`, should feature test for
+ * this and be tolerant of its absence. It may indeed disappear from later
+ * versions of the ses-shim.
+ */
+const MAKE_CAUSAL_CONSOLE_FROM_LOGGER_KEY_FOR_SES_AVA = Symbol.for(
+  'MAKE_CAUSAL_CONSOLE_FROM_LOGGER_KEY_FOR_SES_AVA',
+);
+
+const optMakeCausalConsoleFromLoggerForSesAva =
+  globalThis[MAKE_CAUSAL_CONSOLE_FROM_LOGGER_KEY_FOR_SES_AVA];
 
 /**
- * @typedef {(...args: unknown[]) => void} Logger
+ * TODO For some reason, the following declaration (with "at-" as "@")
+ * doesn't work well for either TS or typedoc. For TS it seems to type
+ * `VirtualConsole` as `any` in a vscode hover. For typedoc it results in
+ * errors.
+ *
+ * at-typedef {import('ses/console-tools.js').VirtualConsole} VirtualConsole
+ *
+ * so instead, for now, we just declare it as `any`. TODO is to repair this.
+ *
+ * @typedef {any} VirtualConsole
  */
 
-const defaultLogger = (...args) => {
-  console.error(...args);
-};
+const { stringify } = JSON;
+const {
+  defineProperty,
+  freeze,
+  getPrototypeOf,
+  getOwnPropertyDescriptors,
+  entries,
+} = Object;
+const { apply } = Reflect;
 
 /**
  * Determine if the argument is a Promise.
@@ -23,40 +66,43 @@ const isPromise = maybePromise =>
   Promise.resolve(maybePromise) === maybePromise;
 
 /**
- * Calls `func(...args)` passing back approximately its outcome, but first
- * logging any erroneous outcome to the `logger`.
+ * Calls `func(virtualT, ...args)` passing back approximately its outcome,
+ * but first logging any erroneous outcome to the `virtualT.log`.
  *
- *    * If `func(...args)` returns a non-promise, silently return it.
- *    * If `func(...args)` throws, log what was thrown and then rethrow it.
- *    * If `func(...args)` returns a promise, immediately return a new
+ *    * If `func(...)` returns a non-promise, silently return it.
+ *    * If `func(...)` throws, log what was thrown and then rethrow it.
+ *    * If `func(...)` returns a promise, immediately return a new
  *      unresolved promise.
  *       * If the first promise fulfills, silently fulfill the returned promise
  *         even if the fulfillment was an error.
  *       * If the first promise rejects, log the rejection reason and then
  *         reject the returned promise with the same reason.
  *
  * The delayed rejection of the returned promise is an observable difference
- * from directly calling `func(...args)` but will be equivalent enough for most
- * purposes.
+ * from directly calling `func(...)` but will be equivalent enough for most
+ * testing purposes.
  *
- * @param {(...unknown) => unknown} func
+ * @param {(
+ *   t: import('ava').ExecutionContext,
+ *   ...args: unknown[]
+ * ) => unknown} func
+ * @param {import('ava').ExecutionContext} virtualT
  * @param {unknown[]} args
  * @param {string} source
- * @param {Logger} logger
  */
-const logErrorFirst = (func, args, source, logger) => {
+const logErrorFirst = (func, virtualT, args, source) => {
   let result;
   try {
-    result = apply(func, undefined, args);
+    result = apply(func, undefined, [virtualT, ...args]);
   } catch (err) {
-    logger(`THROWN from ${source}:`, err);
+    virtualT.log(`THROWN from ${source}:`, err);
     throw err;
   }
   if (isPromise(result)) {
     return result.then(
       v => v,
       reason => {
-        logger(`REJECTED from ${source}:`, reason);
+        virtualT.log(`REJECTED from ${source}:`, reason);
         return result;
       },
     );
@@ -76,12 +122,65 @@ const overrideList = [
 ];
 
 /**
- * @template {import('ava').TestFn} T
+ * @param {import('ava').ExecutionContext} originalT
+ * @returns {import('ava').ExecutionContext}
+ */
+const makeVirtualExecutionContext = originalT => {
+  if (optMakeCausalConsoleFromLoggerForSesAva === undefined) {
+    // Must tolerate absence as a failure of the feature test. In this
+    // case, we fallback to `originalT` itself.
+    return originalT;
+  }
+  const causalConsole = optMakeCausalConsoleFromLoggerForSesAva(originalT.log);
+  const virtualT = {
+    log: /** @type {import('ava').LogFn} */ (causalConsole.error),
+    console: causalConsole,
+  };
+  // Mirror properties from originalT and its prototype onto virtualT
+  // except for those already defined above.
+  const originalProto = getPrototypeOf(originalT);
+  const descs = {
+    // Spread from originalProto before originalT
+    // so we wrap properties of the latter in case of collision.
+    ...getOwnPropertyDescriptors(originalProto),
+    ...getOwnPropertyDescriptors(originalT),
+  };
+  for (const [name, desc] of entries(descs)) {
+    if (!(name in virtualT)) {
+      if ('get' in desc) {
+        defineProperty(virtualT, name, {
+          ...desc,
+          get() {
+            return originalT[name];
+          },
+          set(newVal) {
+            originalT[name] = newVal;
+          },
+        });
+      } else if (typeof desc.value === 'function') {
+        defineProperty(virtualT, name, {
+          ...desc,
+          value(...args) {
+            return originalT[name](...args);
+          },
+        });
+      } else {
+        defineProperty(virtualT, name, desc);
+      }
+    }
+  }
+
+  // `harden` should be functional by the time a test callback is invoked.
+  // @ts-ignore has extra properties outside type
+  return harden(virtualT);
+};
+
+/**
+ * @template {import('ava').TestFn} [T=import('ava').TestFn]
  * @param {T} testerFunc
- * @param {Logger} logger
  * @returns {T} Not yet frozen!
  */
-const augmentLogging = (testerFunc, logger) => {
+const augmentLogging = testerFunc => {
   const testerFuncName = `ava ${testerFunc.name || 'test'}`;
   const augmented = (...args) => {
     // Align with ava argument parsing.
@@ -102,17 +201,19 @@ const augmentLogging = (testerFunc, logger) => {
       return freeze(wrappedBuildTitle);
     };
     const wrapImplFunc = fn => {
-      const wrappedFunc = t => {
-        // `harden` should be functional by the time a test callback is invoked.
-        harden(t);
+      /**
+       * @param {import('ava').ExecutionContext} originalT
+       */
+      const wrappedFunc = originalT => {
+        const virtualT = makeVirtualExecutionContext(originalT);
         // Format source like `test("$rawTitle") "$resolvedTitle"`.
         const quotedRawTitle = hasRawTitle ? stringify(rawTitle) : '';
         const quotedResolvedTitle =
           typeof resolvedTitle === 'string' && resolvedTitle !== rawTitle
             ? ` ${stringify(resolvedTitle)}`
             : '';
         const source = `${testerFuncName}(${quotedRawTitle})${quotedResolvedTitle}`;
-        return logErrorFirst(fn, [t, ...args], source, logger);
+        return logErrorFirst(fn, virtualT, args, source);
       };
       const buildTitle = fn.title;
       if (buildTitle) {
@@ -177,16 +278,15 @@ const augmentLogging = (testerFunc, logger) => {
  * (which defaults to using the SES-aware `console.error`)
  * before propagating into `rawTest`.
  *
- * @template {import('ava').TestFn} T ava `test`
+ * @template {import('ava').TestFn} [T=import('ava').TestFn] ava `test`
  * @param {T} avaTest
- * @param {Logger} [logger]
  * @returns {T}
  */
-const wrapTest = (avaTest, logger = defaultLogger) => {
-  const sesAvaTest = augmentLogging(avaTest, logger);
+const wrapTest = avaTest => {
+  const sesAvaTest = augmentLogging(avaTest);
   for (const methodName of overrideList) {
     defineProperty(sesAvaTest, methodName, {
-      value: augmentLogging(avaTest[methodName], logger),
+      value: augmentLogging(avaTest[methodName]),
       writable: true,
       enumerable: true,
       configurable: true,

packages/ses-ava/test/example-problem.js

@@ -0,0 +1,11 @@
+// Avoid importing from @endo/errors to avoid more dependence cycles
+const { error: makeError, details: X, quote: q } = assert;
+
+const { freeze } = Object;
+
+export const exampleProblem = label => {
+  const subError = makeError(X`nested ${q(label)} ${'REDACTED'}`);
+
+  return makeError(X`${q(label)} ${'NOTICE ME'} nest ${subError}`);
+};
+freeze(exampleProblem);