diff --git a/packages/eventual-send/test/test-deep-send.js b/packages/eventual-send/test/test-deep-send.js index 4ab8ac39b9..3d4c652476 100644 --- a/packages/eventual-send/test/test-deep-send.js +++ b/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)); diff --git a/packages/eventual-send/test/test-deep-stacks.js b/packages/eventual-send/test/test-deep-stacks.js index b596e8491c..40ad769bed 100644 --- a/packages/eventual-send/test/test-deep-stacks.js +++ b/packages/eventual-send/test/test-deep-stacks.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. @@ -6,13 +6,21 @@ 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)); 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..937cb141d8 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, 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,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,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,9 +201,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 +213,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 +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, 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..604b9c75d4 100644 --- a/packages/ses-ava/test/test-raw-ava-reject.js +++ b/packages/ses-ava/test/test-raw-ava-reject.js @@ -1,57 +1,42 @@ +// This file is not really useful as an +// automated test. Rather, its purpose is just to run it to see what +// its console log looks like. + 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', // Host console lacks 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.logA:', exampleProblem('t.logA')); + console.log('console.logB:', exampleProblem('console.logB')); + return Promise.resolve(null) .then(v => v) .then(v => v) .then(_ => { - assert.typeof(88, 'string', assert.details`msg ${'NOTICE ME'}`); + t.log('t.logC:', exampleProblem('t.logC')); + console.log('console.logD:', exampleProblem('console.logD')); + + // Uncomment to see something how this test case fails + // throw exampleProblem('throwE'); }); - */ }); - -/* -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..1449a96294 100644 --- a/packages/ses-ava/test/test-raw-ava-throw.js +++ b/packages/ses-ava/test/test-raw-ava-throw.js @@ -1,52 +1,34 @@ +// This file is not really useful as an +// automated test. Rather, its purpose is just to run it to see what +// its console log looks like. + 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', // Host console lacks 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.logA:', exampleProblem('t.logA')); + console.log('console.logB:', exampleProblem('console.logB')); - 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('throwC'); +}); diff --git a/packages/ses-ava/test/test-ses-ava-reject.js b/packages/ses-ava/test/test-ses-ava-reject.js index 005f96d980..c7dee9b126 100644 --- a/packages/ses-ava/test/test-ses-ava-reject.js +++ b/packages/ses-ava/test/test-ses-ava-reject.js @@ -1,57 +1,45 @@ +// This file is not really useful as an +// automated test. Rather, its purpose is just to run it to see what +// its console log looks like. + 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', // Host console lacks 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 reject console output', t => { t.assert(true); - // Uncomment this to see something like the text in the extended comment below - /* + t.log('t.logA:', exampleProblem('t.logA')); + console.log('console.logB:', exampleProblem('console.logB')); + return Promise.resolve(null) .then(v => v) .then(v => v) .then(_ => { - assert.typeof(88, 'string', assert.details`msg ${'NOTICE ME'}`); + t.log('t.logC:', exampleProblem('t.logC')); + console.log('console.logD:', exampleProblem('console.logD')); + + // Uncomment to see something how this test case fails + // throw exampleProblem('throwE'); }); - */ }); - -/* -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..0aa7a8c709 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 @@ +// This file is not really useful as an +// automated test. Rather, its purpose is just to run it to see what +// its console log looks like. + 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', // Host console lacks 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.logA:', exampleProblem('t.logA')); + console.log('console.logB:', exampleProblem('console.logB')); - ses-ava throw console output - - Error thrown in test: - - TypeError { - message: 'msg (a string)', - } - - ─ - - 1 test failed -``` -*/ + // Uncomment to see something how this test case fails + // throw exampleProblem('throwC'); +}); 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/commons.js b/packages/ses/src/commons.js index 2ef01d7425..427330f8ea 100644 --- a/packages/ses/src/commons.js +++ b/packages/ses/src/commons.js @@ -159,6 +159,9 @@ export const arrayIncludes = uncurryThis(arrayPrototype.includes); export const arrayJoin = uncurryThis(arrayPrototype.join); /** @type {(thisArg: readonly T[], callbackfn: (value: T, index: number, array: T[]) => U, cbThisArg?: any) => U[]} */ export const arrayMap = /** @type {any} */ (uncurryThis(arrayPrototype.map)); +export const arrayFlatMap = /** @type {any} */ ( + uncurryThis(arrayPrototype.flatMap) +); export const arrayPop = uncurryThis(arrayPrototype.pop); /** @type {(thisArg: T[], ...items: T[]) => number} */ export const arrayPush = uncurryThis(arrayPrototype.push); diff --git a/packages/ses/src/console-shim.js b/packages/ses/src/console-shim.js new file mode 100644 index 0000000000..a35c4bf96c --- /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` + * 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 = 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..8ad8853805 100644 --- a/packages/ses/src/error/console.js +++ b/packages/ses/src/error/console.js @@ -8,13 +8,17 @@ import { WeakSet, arrayFilter, + arrayFlatMap, arrayMap, + arrayPop, arrayPush, defineProperty, freeze, fromEntries, isError, stringEndsWith, + stringIncludes, + stringSplit, weaksetAdd, weaksetHas, } from '../commons.js'; @@ -46,8 +50,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 +68,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 +107,7 @@ const consoleOtherMethods = freeze([ ]); /** @type {readonly [ConsoleProps, LogSeverity | undefined][]} */ -export const consoleWhitelist = freeze([ +const consoleWhitelist = freeze([ ...consoleLevelMethods, ...consoleOtherMethods, ]); @@ -117,10 +139,10 @@ export const consoleWhitelist = freeze([ * ]); */ -// ///////////////////////////////////////////////////////////////////////////// +// //////////////////////////// Logging Console //////////////////////////////// /** @type {MakeLoggingConsoleKit} */ -const makeLoggingConsoleKit = ( +export const makeLoggingConsoleKit = ( loggedErrorHandler, { shouldResetForDebugging = false } = {}, ) => { @@ -161,9 +183,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`. In 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 +211,7 @@ const ErrorInfo = { freeze(ErrorInfo); /** @type {MakeCausalConsole} */ -const makeCausalConsole = (baseConsole, loggedErrorHandler) => { +export const makeCausalConsole = (baseConsole, loggedErrorHandler) => { if (!baseConsole) { return undefined; } @@ -362,12 +398,106 @@ const makeCausalConsole = (baseConsole, loggedErrorHandler) => { return /** @type {VirtualConsole} */ (freeze(causalConsole)); }; freeze(makeCausalConsole); -export { makeCausalConsole }; -// ///////////////////////////////////////////////////////////////////////////// +/** + * @typedef {(...args: unknown[]) => void} Logger + */ + +/** + * This is a rather horrible kludge to indent the output to a logger in + * the case where some arguments are strings containing newlines. Part of + * the problem is that console-like loggers, including the one in ava, + * join the string arguments of the log message with a space. + * Because of this, there's an extra space at the beginning of each of + * the split lines. So this kludge compensated by putting an extra empty + * string at the beginning, so that the logger will add the same extra + * joiner. + * TODO: Fix this horrible kludge, and indent in a sane manner. + * + * @param {string} str + * @param {string} sep + * @param {string[]} indents + * @returns {string[]} + */ +const indentAfterAllSeps = (str, sep, indents) => { + const [firstLine, ...restLines] = stringSplit(str, sep); + const indentedRest = arrayFlatMap(restLines, line => [sep, ...indents, line]); + return ['', firstLine, ...indentedRest]; +}; + +/** + * @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 indents = []; + const logWithIndent = (...args) => { + if (indents.length > 0) { + args = arrayFlatMap(args, arg => + typeof arg === 'string' && stringIncludes(arg, '\n') + ? indentAfterAllSeps(arg, '\n', indents) + : [arg], + ); + args = [...indents, ...args]; + } + return tlogger(...args); + }; + const makeNamed = (name, fn) => + ({ [name]: (...args) => fn(...args) })[name]; + + const baseConsole = fromEntries([ + ...arrayMap(consoleLevelMethods, ([name]) => [ + name, + makeNamed(name, logWithIndent), + ]), + ...arrayMap(consoleOtherMethods, ([name]) => [ + name, + makeNamed(name, (...args) => logWithIndent(name, ...args)), + ]), + ]); + // https://console.spec.whatwg.org/#grouping + for (const name of ['group', 'groupCollapsed']) { + if (baseConsole[name]) { + baseConsole[name] = makeNamed(name, (...args) => { + if (args.length >= 1) { + // Prefix the logged data with "group" or "groupCollapsed". + logWithIndent(...args); + } + // A single space is enough; + // the host console will separate them with additional spaces. + arrayPush(indents, ' '); + }); + } + } + if (baseConsole.groupEnd) { + baseConsole.groupEnd = makeNamed('groupEnd', (...args) => { + arrayPop(indents); + }); + } + 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 +521,3 @@ const filterConsole = (baseConsole, filter, _topic = undefined) => { return /** @type {VirtualConsole} */ (freeze(filteringConsole)); }; freeze(filterConsole); -export { filterConsole };