test(ses-ava): use causal console

packages/ses-ava/package.json

@@ -36,6 +36,7 @@
     "test": "ava"
   },
   "dependencies": {
+    "@endo/errors": "^1.1.0",
     "ses": "^1.3.0"
   },
   "devDependencies": {

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

@@ -1,16 +1,23 @@
+/* global globalThis */
 import 'ses';
-
-const { stringify } = JSON;
-const { defineProperty, freeze } = Object;
-const { apply } = Reflect;
+import { makeCausalConsoleFromLogger } from 'ses/console-tools.js';
 
 /**
- * @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 } = Object;
+const { apply } = Reflect;
 
 /**
  * Determine if the argument is a Promise.
@@ -23,40 +30,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 +86,34 @@ const overrideList = [
 ];
 
 /**
- * @template {import('ava').TestFn} T
+ * @param {import('ava').ExecutionContext} originalT
+ * @returns {import('ava').ExecutionContext}
+ */
+const makeVirtualExecutionContext = originalT => {
+  const causalConsole = makeCausalConsoleFromLogger(originalT.log);
+  // `harden` should be functional by the time a test callback is invoked.
+  return harden({
+    ...originalT,
+    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;
+      }
+    },
+  });
+};
+
+/**
+ * @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 +134,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 +211,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,10 @@
+import { makeError, X, q } from '@endo/errors';
+
+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
-```
-*/

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

@@ -1,52 +1,30 @@
 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 throw console output', t => {
   t.assert(true);
-  // Uncomment this to see something like the text in the extended comment below
-
-  /*
-  assert.typeof(88, 'string', assert.details`msg ${'NOTICE ME'}`);
-  */
-});
-
-/*
-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 throw console output
 
-  Error thrown in test:
+  t.log('t.log1:', exampleProblem('t.log1'));
+  console.log('console.log2:', exampleProblem('console.log2'));
 
-  TypeError {
-    message: 'msg "NOTICE ME"',
-  }
-
-  › makeError (file:///Users/alice/agoric/SES-shim/packages/ses/src/error/assert.js:141:17)
-  › fail (file:///Users/alice/agoric/SES-shim/packages/ses/src/error/assert.js:260:20)
-  › baseAssert (file:///Users/alice/agoric/SES-shim/packages/ses/src/error/assert.js:278:13)
-  › equal (file:///Users/alice/agoric/SES-shim/packages/ses/src/error/assert.js:289:5)
-  › Function.assertTypeof [as typeof] (file:///Users/alice/agoric/SES-shim/packages/ses/src/error/assert.js:308:5)
-  › file://test/test-raw-ava-throw.js:17:16
-
-  ─
-
-  1 test failed
-```
-*/
+  // Uncomment to see something how this test case fails
+  // throw exampleProblem('throw3');
+});