test(ses-ava): use causal console if possible

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

@@ -0,0 +1,30 @@
+// This file does not start with "test-" because it is useful as an
+// automated test. Rather, its purpose is just to run it to see what a
+// deep stack looks like.
+
+// eslint-disable-next-line import/no-extraneous-dependencies
+import { test } from './prepare-test-env-ava.js';
+
+import { E } from './get-hp.js';
+
+const { freeze } = Object;
+
+const carol = freeze({
+  bar: () => assert.fail('Wut?'),
+});
+
+const bob = freeze({
+  foo: carolP => E(carolP).bar(),
+});
+
+const alice = freeze({
+  test: () => E(bob).foo(carol),
+});
+
+test('deep-stacks E ses-ava', t => {
+  const q = alice.test();
+  return q.catch(reason => {
+    t.assert(reason instanceof Error);
+    t.log('expected failure', reason);
+  });
+});

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

@@ -0,0 +1,18 @@
+// This file does not start with "test-" because it is 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 ses-ava', 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);
+    t.log('expected failure', reason);
+  });
+});

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, this `console-shim.js` makes `makeCausalConsoleFromLoggerForSesAva` for
+ * on `globalThis` which it *assumes* is the global of the start compartment,
+ * which 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,70 @@ 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,
+    withConsole: thunk => {
+      const originalConsole = globalThis.console;
+      globalThis.console = /** @type {Console} */ (causalConsole);
+      try {
+        thunk();
+      } finally {
+        globalThis.console = originalConsole;
+      }
+    },
+  };
+  const originalProto = getPrototypeOf(originalT);
+  const descs = {
+    ...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 +206,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 +283,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);

packages/ses-ava/test/test-raw-ava-reject.js

@@ -1,57 +1,38 @@
 import 'ses';
 import test from 'ava';
+import { exampleProblem } from './example-problem.js';
 
 lockdown({
   // Comment or uncomment each of these switches to see variations of the
   // output shown below. When all the switches are uncommented, you should
   // see that output.
   //
-  stackFiltering: 'verbose', // Exclude `assert` infrastructure
-  consoleTaming: 'unsafe', // Doesn't make a difference here
-  errorTaming: 'unsafe', // Redacts entire `error.stack`
+  // Commenting out all settings for a given switch defaults to using
+  // the current relevant environment variable setting. To get results
+  // independent of that, always uncomment one setting for each switch.
+  //
+  stackFiltering: 'concise', // Default. Hide infrastructure, shorten paths
+  // stackFiltering: 'verbose', // Include `assert` infrastructure
+  consoleTaming: 'safe', // Default. Console with access to redacted info
+  // consoleTaming: 'unsafe', // Console without access to redacted info
+  errorTaming: 'safe', // Default. Hide redacted info on error
+  // errorTaming: 'unsafe', // Disclose redacted info on error
 });
 
 test('raw ava reject console output', t => {
   t.assert(true);
-  // Uncomment this to see something like the text in the extended comment below
 
-  /*
+  t.log('t.log1:', exampleProblem('t.log1'));
+  console.log('console.log2:', exampleProblem('console.log2'));
+
   return Promise.resolve(null)
     .then(v => v)
     .then(v => v)
     .then(_ => {
-      assert.typeof(88, 'string', assert.details`msg ${'NOTICE ME'}`);
+      t.log('t.log3:', exampleProblem('t.log3'));
+      console.log('console.log4:', exampleProblem('console.log4'));
+
+      // Uncomment to see something how this test case fails
+      // throw exampleProblem('throw5');
     });
-  */
 });
-
-/*
-Uncommenting the test code above should produce something like the following.
-This output is all from ava. The stack-like display comes from ava's direct
-use of the `error.stack` property. Ava bypasses the normal `console`.
-For the error message, ava has access only to the `message` string carried
-by the error instance, which would normally be redacted to
-`'msg (a string)'`. But `errorTaming: 'unsafe'` suppresses that redaction along
-with suppressing the redaction of the stack, so the console blabs
-`'msg "NOTICE ME"'` instead.
-```
-  raw ava reject console output
-
-  Rejected promise returned by test. Reason:
-
-  TypeError {
-    message: 'msg "NOTICE ME"',
-  }
-
-  › makeError (file:///Users/markmiller/src/ongithub/agoric/SES-shim/packages/ses/src/error/assert.js:141:17)
-  › fail (file:///Users/markmiller/src/ongithub/agoric/SES-shim/packages/ses/src/error/assert.js:260:20)
-  › baseAssert (file:///Users/markmiller/src/ongithub/agoric/SES-shim/packages/ses/src/error/assert.js:278:13)
-  › equal (file:///Users/markmiller/src/ongithub/agoric/SES-shim/packages/ses/src/error/assert.js:289:5)
-  › Function.assertTypeof [as typeof] (file:///Users/markmiller/src/ongithub/agoric/SES-shim/packages/ses/src/error/assert.js:308:5)
-  › file://test/test-raw-ava-reject.js:22:20
-
-  ─
-
-  1 test failed
-```
-*/