From a24136d44009a04875df0dc645e11bb3936a1796 Mon Sep 17 00:00:00 2001 From: "Mark S. Miller" Date: Tue, 5 Mar 2024 15:56:10 -0800 Subject: [PATCH] test(ses-ava): use causal console if possible --- .../test/test-deep-send-ses-ava.js | 30 ++++ .../test/test-deep-stacks-ses-ava.js | 18 ++ packages/ses-ava/NEWS.md | 12 +- packages/ses-ava/src/ses-ava-test.js | 169 ++++++++++++++---- packages/ses-ava/test/example-problem.js | 11 ++ packages/ses-ava/test/test-raw-ava-reject.js | 57 ++---- packages/ses-ava/test/test-raw-ava-throw.js | 54 ++---- packages/ses-ava/test/test-ses-ava-reject.js | 63 +++---- packages/ses-ava/test/test-ses-ava-throw.js | 50 ++---- packages/ses/index.js | 1 + packages/ses/src/console-shim.js | 50 ++++++ packages/ses/src/error/README.md | 10 +- packages/ses/src/error/console.js | 104 +++++++++-- 13 files changed, 434 insertions(+), 195 deletions(-) create mode 100644 packages/eventual-send/test/test-deep-send-ses-ava.js create mode 100644 packages/eventual-send/test/test-deep-stacks-ses-ava.js create mode 100644 packages/ses-ava/test/example-problem.js create mode 100644 packages/ses/src/console-shim.js diff --git a/packages/eventual-send/test/test-deep-send-ses-ava.js b/packages/eventual-send/test/test-deep-send-ses-ava.js new file mode 100644 index 0000000000..ec0418d974 --- /dev/null +++ b/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); + }); +}); diff --git a/packages/eventual-send/test/test-deep-stacks-ses-ava.js b/packages/eventual-send/test/test-deep-stacks-ses-ava.js new file mode 100644 index 0000000000..bf513f9254 --- /dev/null +++ b/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); + }); +}); diff --git a/packages/ses-ava/NEWS.md b/packages/ses-ava/NEWS.md index 78d395d15c..c928fd561a 100644 --- a/packages/ses-ava/NEWS.md +++ b/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) diff --git a/packages/ses-ava/src/ses-ava-test.js b/packages/ses-ava/src/ses-ava-test.js index 8dbcdf97c3..573d75c929 100644 --- a/packages/ses-ava/src/ses-ava-test.js +++ b/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,12 +66,12 @@ 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. @@ -36,27 +79,30 @@ const isPromise = maybePromise => * 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,9 +206,11 @@ 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 = @@ -112,7 +218,7 @@ const augmentLogging = (testerFunc, logger) => { ? ` ${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, diff --git a/packages/ses-ava/test/example-problem.js b/packages/ses-ava/test/example-problem.js new file mode 100644 index 0000000000..4f803c6666 --- /dev/null +++ b/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); diff --git a/packages/ses-ava/test/test-raw-ava-reject.js b/packages/ses-ava/test/test-raw-ava-reject.js index 474999642b..bf51b7ce9a 100644 --- a/packages/ses-ava/test/test-raw-ava-reject.js +++ b/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 -``` -*/ diff --git a/packages/ses-ava/test/test-raw-ava-throw.js b/packages/ses-ava/test/test-raw-ava-throw.js index 1ff778c3da..980dae1bdf 100644 --- a/packages/ses-ava/test/test-raw-ava-throw.js +++ b/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'); +}); diff --git a/packages/ses-ava/test/test-ses-ava-reject.js b/packages/ses-ava/test/test-ses-ava-reject.js index 005f96d980..458ce6fbbe 100644 --- a/packages/ses-ava/test/test-ses-ava-reject.js +++ b/packages/ses-ava/test/test-ses-ava-reject.js @@ -1,57 +1,48 @@ 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 // output shown below. When all the switches are commented, you should // see that output. // - // stackFiltering: 'verbose', // Include `assert` infrastructure - // consoleTaming: 'unsafe', // console without access to redacted info - // errorTaming: 'unsafe', // Disclose `error.stack` to ava + // 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 }); -const test = wrapTest(rawTest); +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 - /* + t.log('t.log1:', exampleProblem('t.log1')); + console.log('console.log2:', exampleProblem('console.log2')); + + t.withConsole(() => + console.log('console.log3:', exampleProblem('console.log3')), + ); + return Promise.resolve(null) .then(v => v) .then(v => v) .then(_ => { - assert.typeof(88, 'string', assert.details`msg ${'NOTICE ME'}`); + t.log('t.log4:', exampleProblem('t.log4')); + console.log('console.log5:', exampleProblem('console.log5')); + t.withConsole(() => + console.log('console.log6:', exampleProblem('console.log6')), + ); + + // Uncomment to see something how this test case fails + // throw exampleProblem('throw7'); }); - */ }); - -/* -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 - - ses-ava reject console output - - Rejected promise returned by test. Reason: - - TypeError { - message: 'msg (a string)', - } - - ─ - - 1 test failed -``` -*/ diff --git a/packages/ses-ava/test/test-ses-ava-throw.js b/packages/ses-ava/test/test-ses-ava-throw.js index c7483f4bc5..fcfb60cf5a 100644 --- a/packages/ses-ava/test/test-ses-ava-throw.js +++ b/packages/ses-ava/test/test-ses-ava-throw.js @@ -1,51 +1,37 @@ 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 // output shown below. When all the switches are commented, you should // see that output. // + // 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: 'unsafe', // console without access to redacted info - // errorTaming: 'unsafe', // Disclose `error.stack` to ava + 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 }); const test = wrapTest(rawTest); 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) + t.log('t.log1:', exampleProblem('t.log1')); + console.log('console.log2:', exampleProblem('console.log2')); - ses-ava throw console output + t.withConsole(() => + console.log('console.log3:', exampleProblem('console.log3')), + ); - Error thrown in test: - - TypeError { - message: 'msg (a string)', - } - - ─ - - 1 test failed -``` -*/ + // Uncomment to see something how this test case fails + // throw exampleProblem('throw4'); +}); diff --git a/packages/ses/index.js b/packages/ses/index.js index 06f4ab107d..54cb4e2966 100644 --- a/packages/ses/index.js +++ b/packages/ses/index.js @@ -15,3 +15,4 @@ import './src/lockdown-shim.js'; import './src/compartment-shim.js'; import './src/assert-shim.js'; +import './src/console-shim.js'; diff --git a/packages/ses/src/console-shim.js b/packages/ses/src/console-shim.js new file mode 100644 index 0000000000..2f83d99685 --- /dev/null +++ b/packages/ses/src/console-shim.js @@ -0,0 +1,50 @@ +import { symbolFor, globalThis } from './commons.js'; +import { defineCausalConsoleFromLogger } from './error/console.js'; +import { loggedErrorHandler } from './error/assert.js'; + +// TODO possible additional exports. Some are privileged. +// export { loggedErrorHandler }; +// export { +// makeCausalConsole, +// consoleLevelMethods, +// consoleOtherMethods, +// makeLoggingConsoleKit, +// filterConsole, +// pumpLogToConsole, +// } from './src/error/console.js'; +// export { assertLogs, throwsAndLogs } from './src/error/throws-and-logs.js'; + +/** + * Makes a Console like the + * [SES causal `console`](https://github.com/endojs/endo/blob/master/packages/ses/src/error/README.md) + * but whose output is redirected to the supplied `logger` function. + */ +const makeCausalConsoleFromLoggerForSesAva = + defineCausalConsoleFromLogger(loggedErrorHandler); + +/** + *`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 = symbolFor( + 'MAKE_CAUSAL_CONSOLE_FROM_LOGGER_KEY_FOR_SES_AVA', +); + +globalThis[MAKE_CAUSAL_CONSOLE_FROM_LOGGER_KEY_FOR_SES_AVA] = + makeCausalConsoleFromLoggerForSesAva; diff --git a/packages/ses/src/error/README.md b/packages/ses/src/error/README.md index 9f39224e5f..35fecdd564 100644 --- a/packages/ses/src/error/README.md +++ b/packages/ses/src/error/README.md @@ -6,7 +6,15 @@ Summary * SES tames the global `console` and grants it the ability to reveal error annotations and stacks to the actual console. * Both `assert` and `console` are powerful globals that SES does not implicitly carry into child compartments. When creating a child compartment, add `assert` to the compartment’s globals. Either add `console` too, or add a wrapper that annotates the console with a topic. * SES hides annotations and stack traces by default. To reveal them, SES uses mechanisms like `process.on("uncaughtException")` in Node.js to catch the error and log it back to the `console` tamed by `lockdown`. - * In the scope of the Agoric software ecosystem, this architecture will allow us to eventually introduce a more powerful distributed `console` that can meaningfully capture stack traces for a distributed debugger, based on the design of [Causeway](https://github.com/Agoric/agoric-sdk/issues/1318#issuecomment-662127549). + +We refer to the enhanced `console`, installed by default by the ses shim, as the *causal console*, because the annotations it reveals are often used to show causality information. For example, with the [`TRACK_TURNS=enabled`](https://github.com/Agoric/agoric-sdk/blob/master/docs/env.md#track_turns) and [`DEBUG=track-turns`](https://github.com/Agoric/agoric-sdk/blob/master/docs/env.md#debug) environment options set +```sh +# in bash syntax +export DEBUG=track-turns +export TRACK_TURNS=enabled +``` +the @endo/eventual-send package will use annotations to show where previous `E` operations (either eventual sends or `E.when`) in previous turns *locally in the same vat* caused the turn with the current error. This is sometimes called "deep asynchronous stacks". + * In the scope of the Agoric software ecosystem, this architecture will allow us to eventually introduce a more powerful distributed causal `console` that can meaningfully capture stack traces for a distributed debugger, based on the design of [Causeway](https://github.com/Agoric/agoric-sdk/issues/1318#issuecomment-662127549). ## Goals, non-goals, and partial goals diff --git a/packages/ses/src/error/console.js b/packages/ses/src/error/console.js index 950bdd5c31..72411f21dc 100644 --- a/packages/ses/src/error/console.js +++ b/packages/ses/src/error/console.js @@ -46,8 +46,17 @@ import './internal-types.js'; /** @typedef {keyof VirtualConsole | 'profile' | 'profileEnd'} ConsoleProps */ -/** @type {readonly [ConsoleProps, LogSeverity | undefined][]} */ -const consoleLevelMethods = freeze([ +/** + * Those console methods whose actual parameters are `(fmt?, ...args)` + * even if their TypeScript types claim otherwise. + * + * Each is paired with what we consider to be their log severity level. + * This is the same as the log severity of these on other + * platform console implementations when they all agree. + * + * @type {readonly [ConsoleProps, LogSeverity | undefined][]} + */ +export const consoleLevelMethods = freeze([ ['debug', 'debug'], // (fmt?, ...args) verbose level on Chrome ['log', 'log'], // (fmt?, ...args) info level on Chrome ['info', 'info'], // (fmt?, ...args) @@ -55,13 +64,22 @@ const consoleLevelMethods = freeze([ ['error', 'error'], // (fmt?, ...args) ['trace', 'log'], // (fmt?, ...args) - ['dirxml', 'log'], // (fmt?, ...args) - ['group', 'log'], // (fmt?, ...args) - ['groupCollapsed', 'log'], // (fmt?, ...args) + ['dirxml', 'log'], // (fmt?, ...args) but TS typed (...data) + ['group', 'log'], // (fmt?, ...args) but TS typed (...label) + ['groupCollapsed', 'log'], // (fmt?, ...args) but TS typed (...label) ]); -/** @type {readonly [ConsoleProps, LogSeverity | undefined][]} */ -const consoleOtherMethods = freeze([ +/** + * Those console methods other than those already enumerated by + * `consoleLevelMethods`. + * + * Each is paired with what we consider to be their log severity level. + * This is the same as the log severity of these on other + * platform console implementations when they all agree. + * + * @type {readonly [ConsoleProps, LogSeverity | undefined][]} + */ +export const consoleOtherMethods = freeze([ ['assert', 'error'], // (value, fmt?, ...args) ['timeLog', 'log'], // (label?, ...args) no fmt string @@ -85,7 +103,7 @@ const consoleOtherMethods = freeze([ ]); /** @type {readonly [ConsoleProps, LogSeverity | undefined][]} */ -export const consoleWhitelist = freeze([ +const consoleWhitelist = freeze([ ...consoleLevelMethods, ...consoleOtherMethods, ]); @@ -117,10 +135,10 @@ export const consoleWhitelist = freeze([ * ]); */ -// ///////////////////////////////////////////////////////////////////////////// +// //////////////////////////// Logging Console //////////////////////////////// /** @type {MakeLoggingConsoleKit} */ -const makeLoggingConsoleKit = ( +export const makeLoggingConsoleKit = ( loggedErrorHandler, { shouldResetForDebugging = false } = {}, ) => { @@ -161,9 +179,23 @@ const makeLoggingConsoleKit = ( return freeze({ loggingConsole: typedLoggingConsole, takeLog }); }; freeze(makeLoggingConsoleKit); -export { makeLoggingConsoleKit }; -// ///////////////////////////////////////////////////////////////////////////// +/** + * Makes the same calls on a `baseConsole` that were made on a + * `loggingConsole` to produce this `log`. It this way, a logging console + * can be used as a buffer to delay the application of these calls to a + * `baseConsole`. + * + * @param {LogRecord[]} log + * @param {VirtualConsole} baseConsole + */ +export const pumpLogToConsole = (log, baseConsole) => { + for (const [name, ...args] of log) { + // eslint-disable-next-line @endo/no-polymorphic-call + baseConsole[name](...args); + } +}; +// //////////////////////////// Causal Console ///////////////////////////////// /** @type {ErrorInfo} */ const ErrorInfo = { @@ -175,7 +207,7 @@ const ErrorInfo = { freeze(ErrorInfo); /** @type {MakeCausalConsole} */ -const makeCausalConsole = (baseConsole, loggedErrorHandler) => { +export const makeCausalConsole = (baseConsole, loggedErrorHandler) => { if (!baseConsole) { return undefined; } @@ -362,12 +394,51 @@ const makeCausalConsole = (baseConsole, loggedErrorHandler) => { return /** @type {VirtualConsole} */ (freeze(causalConsole)); }; freeze(makeCausalConsole); -export { makeCausalConsole }; -// ///////////////////////////////////////////////////////////////////////////// +/** + * @typedef {(...args: unknown[]) => void} Logger + */ + +/** + * @param {LoggedErrorHandler} loggedErrorHandler + */ +export const defineCausalConsoleFromLogger = loggedErrorHandler => { + /** + * 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 {VirtualConsole} + */ + const makeCausalConsoleFromLogger = 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); + const causalConsole = makeCausalConsole( + /** @type {VirtualConsole} */ (baseConsole), + loggedErrorHandler, + ); + return /** @type {VirtualConsole} */ (causalConsole); + }; + return freeze(makeCausalConsoleFromLogger); +}; +freeze(defineCausalConsoleFromLogger); + +// ///////////////////////// Filter Console //////////////////////////////////// /** @type {FilterConsole} */ -const filterConsole = (baseConsole, filter, _topic = undefined) => { +export const filterConsole = (baseConsole, filter, _topic = undefined) => { // TODO do something with optional topic string const whitelist = arrayFilter( consoleWhitelist, @@ -391,4 +462,3 @@ const filterConsole = (baseConsole, filter, _topic = undefined) => { return /** @type {VirtualConsole} */ (freeze(filteringConsole)); }; freeze(filterConsole); -export { filterConsole };