fixup! wrap t.log in 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,4 +1,11 @@
+/* global globalThis */
 import 'ses';
+import {
+  loggedErrorHandler,
+  makeCausalConsole,
+  consoleLevelMethods,
+  consoleOtherMethods,
+} from 'ses/console-tools.js';
 
 const { stringify } = JSON;
 const { defineProperty, freeze } = Object;
@@ -43,14 +50,23 @@ const isPromise = maybePromise =>
  * @param {unknown[]} args
  * @param {string} source
  * @param {Logger} logger
+ * @param {import('ses/console-tools.js').VirtualConsole} [optConsole]
  */
-const logErrorFirst = (func, args, source, logger) => {
+const logErrorFirst = (func, args, source, logger, optConsole = undefined) => {
+  const originalConsole = globalThis.console;
+  if (optConsole) {
+    globalThis.console = optConsole;
+  }
   let result;
   try {
     result = apply(func, undefined, args);
   } catch (err) {
     logger(`THROWN from ${source}:`, err);
     throw err;
+  } finally {
+    if (optConsole) {
+      globalThis.console = originalConsole;
+    }
   }
   if (isPromise(result)) {
     return result.then(
@@ -75,9 +91,35 @@ const overrideList = [
   'only',
 ];
 
+/**
+ * Implement the VirtualConsole API badly by turning all calls into
+ * calls on `tlogger`. We need to do this to have `console` logging
+ * turn into calls to Ava's `t.log`, so these console log messages
+ * are output in the right place.
+ *
+ * @param {Logger} tlogger
+ * @returns {import('ses/console-tools.js').VirtualConsole}
+ */
+const makeConsoleFromLogger = tlogger => {
+  const baseConsole = {};
+  for (const [name1, _] of consoleLevelMethods) {
+    baseConsole[name1] = tlogger;
+  }
+  for (const [name2, _] of [
+    ['group', 'log'],
+    ['groupCollapsed', 'log'],
+    ...consoleOtherMethods,
+  ]) {
+    baseConsole[name2] = (...args) => tlogger(name2, ...args);
+  }
+  harden(baseConsole);
+  return makeCausalConsole(baseConsole, loggedErrorHandler);
+};
+
 /**
  * @typedef {object} LoggingOptions
  * @property {boolean} [tlog]
+ * @property {boolean} [pushConsole]
  */
 
 /**
@@ -91,8 +133,8 @@ const getLogger = (tlogger, loggerOrOptions) => {
   } else if (typeof loggerOrOptions === 'object') {
     const { tlog } = loggerOrOptions;
     if (tlog) {
-      // TODO wrap with SES causal console
-      return tlogger;
+      const causalConsole = makeConsoleFromLogger(tlogger);
+      return causalConsole.error;
     } else {
       // Without causal console wrapper
       return tlogger;
@@ -140,7 +182,11 @@ const augmentLogging = (testerFunc, loggerOrOption) => {
         const source = `${testerFuncName}(${quotedRawTitle})${quotedResolvedTitle}`;
 
         const logger = getLogger(t.log, loggerOrOption);
-        return logErrorFirst(fn, [t, ...args], source, logger);
+        let optConsole;
+        if (typeof loggerOrOption === 'object' && loggerOrOption.pushConsole) {
+          optConsole = makeConsoleFromLogger(t.log);
+        }
+        return logErrorFirst(fn, [t, ...args], source, logger, optConsole);
       };
       const buildTitle = fn.title;
       if (buildTitle) {

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

@@ -0,0 +1,15 @@
+import { makeError, X, q } from '@endo/errors';
+
+const { freeze } = Object;
+
+export const exampleProblem = (label, optLogger = undefined) => {
+  const subError = makeError(X`nested ${q(label)} ${'REDACTED'}`);
+
+  const err = makeError(X`${q(label)} ${'NOTICE ME'} nest ${subError}`);
+
+  if (optLogger === undefined) {
+    throw err;
+  }
+  optLogger(label, err);
+};
+freeze(exampleProblem);

packages/ses-ava/test/prepare-test-env-ava.js

@@ -4,4 +4,4 @@ import rawTest from 'ava';
 import { wrapTest } from '../src/ses-ava-test.js';
 
 /** @type {typeof rawTest} */
-export const test = wrapTest(rawTest, { tlog: true });
+export const test = wrapTest(rawTest, { tlog: true, pushConsole: true });

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

@@ -1,5 +1,6 @@
 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
@@ -20,43 +21,18 @@ lockdown({
 
 test('raw ava reject console output', t => {
   t.assert(true);
-  // Uncomment this to see something like the text in the extended comment below
 
-  // return Promise.resolve(null)
-  //   .then(v => v)
-  //   .then(v => v)
-  //   .then(_ => {
-  //     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 reject console output
-
-  Rejected promise returned by test. Reason:
+  exampleProblem('t.log1:', t.log);
+  exampleProblem('console.log1:', console.log);
 
-  TypeError {
-    message: 'msg "NOTICE ME"',
-  }
+  return Promise.resolve(null)
+    .then(v => v)
+    .then(v => v)
+    .then(_ => {
+      exampleProblem('console.log2:', console.log);
+      exampleProblem('t.log2:', t.log);
 
-  › 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
-```
-*/
+      // Uncomment to see something how this test case fails
+      // exampleProblem('throw', undefined);
+    });
+});

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

@@ -1,5 +1,6 @@
 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
@@ -20,38 +21,10 @@ lockdown({
 
 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:
-
-  TypeError {
-    message: 'msg "NOTICE ME"',
-  }
+  exampleProblem('t.log:', t.log);
+  exampleProblem('console.log:', console.log);
 
-  › 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
+  // exampleProblem('throw', undefined);
+});

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

@@ -1,6 +1,7 @@
 import 'ses';
 import rawTest from 'ava';
 import { wrapTest } from '../src/ses-ava-test.js';
+import { exampleProblem } from './example-problem.js';
 
 lockdown({
   // Comment or uncomment each of these switches to see variations of the
@@ -19,44 +20,22 @@ lockdown({
   errorTaming: 'unsafe', // Disclose `error.stack` to ava
 });
 
-const test = wrapTest(rawTest, { tlog: true });
+const test = wrapTest(rawTest, { tlog: true, pushConsole: true });
 
 test('ses-ava reject console output', t => {
   t.assert(true);
-  // Uncomment this to see something like the text in the extended comment below
 
-  // return Promise.resolve(null)
-  //   .then(v => v)
-  //   .then(v => v)
-  //   .then(_ => {
-  //     assert.typeof(88, 'string', assert.details`msg ${'NOTICE ME'}`);
-  //   });
-});
-
-/*
-Uncommenting the test code above should produce something like the following.
-Some of this output still comes from ava. The stack-like display comes from
-the SES `console`, which shows the detailed error message including the
-redacted `'NOTICE ME'` that ava has no access to.
-
-We will revisit this example in `@agoric/eventual-send` using `E.when` instead
-of `then` to show deep stacks across multiple turns.
-```
-REJECTED from ava test: (TypeError#1)
-TypeError#1: msg NOTICE ME
-
-  at packages/ses-ava/test/test-ses-ava-reject.js:26:20
+  exampleProblem('t.log1:', t.log);
+  exampleProblem('console.log1:', console.log);
 
-  ses-ava reject console output
+  return Promise.resolve(null)
+    .then(v => v)
+    .then(v => v)
+    .then(_ => {
+      exampleProblem('console.log2:', console.log);
+      exampleProblem('t.log2:', t.log);
 
-  Rejected promise returned by test. Reason:
-
-  TypeError {
-    message: 'msg (a string)',
-  }
-
-  ─
-
-  1 test failed
-```
-*/
+      // Uncomment to see something how this test case fails
+      // exampleProblem('throw', undefined);
+    });
+});

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

@@ -1,6 +1,7 @@
 import 'ses';
 import rawTest from 'ava';
 import { wrapTest } from '../src/ses-ava-test.js';
+import { exampleProblem } from './example-problem.js';
 
 lockdown({
   // Comment or uncomment each of these switches to see variations of the
@@ -19,38 +20,14 @@ lockdown({
   errorTaming: 'unsafe', // Disclose `error.stack` to ava
 });
 
-const test = wrapTest(rawTest, { tlog: true });
+const test = wrapTest(rawTest, { tlog: true, pushConsole: true });
 
 test('ses-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.
-Some of this output still comes from ava. The stack-like display comes from
-the SES `console`, which shows the detailed error message including the
-redacted `'NOTICE ME'` that ava has no access to.
-```
-THROWN from ava test: (TypeError#1)
-TypeError#1: msg NOTICE ME
-
-  at packages/ses-ava/test/test-ses-ava-throw.js:21:16
-  at logErrorFirst (packages/ses-ava/src/ses-ava-test.js:32:14)
-  at testFuncWrapper (packages/ses-ava/src/ses-ava-test.js:73:14)
-
-  ses-ava throw console output
+  exampleProblem('t.log:', t.log);
+  exampleProblem('console.log:', console.log);
 
-  Error thrown in test:
-
-  TypeError {
-    message: 'msg (a string)',
-  }
-
-  ─
-
-  1 test failed
-```
-*/
+  // Uncomment to see something how this test case fails
+  // exampleProblem('throw', undefined);
+});