fix(xsnap): format objects nicely in console using SES assert.quote (#…

…3856)

fixes #3844

* test(xsnap): xsnap console formats complex objects nicely
* refactor(xsnap): factor bootSESWorker out of several tests

Co-authored-by: Mark S. Miller <erights@users.noreply.github.com>

packages/SwingSet/test/test-xsnap-store.js

@@ -167,15 +167,15 @@ test('XS + SES snapshots are deterministic', async t => {
   const h2 = await store.save(vat.snapshot);
   t.is(
     h2,
-    '93dd13f6c97a2a11f2d6fd88aa2a64f800ef6c4224b6417fbe28f593418cf225',
+    '3659d88bd99032afa15dbe5f938182dffa63abad2cfe53df2f81e8646af2d8b3',
     'after SES boot',
   );
 
   await vat.evaluate('globalThis.x = harden({a: 1})');
   const h3 = await store.save(vat.snapshot);
   t.is(
     h3,
-    'e8e4864ee6a9f4855c93e840028facc6ece988d83a6baafed2d0aafc37dfae76',
+    'b938034b72a3bfa68accb802554cd6bc1c08bbcb8fe80573dabec8584b4ddd9c',
     'after use of harden()',
   );
 });

packages/xsnap/lib/console-shim.js

@@ -1,17 +1,15 @@
-/* global globalThis */
-function tryPrint(...args) {
-  try {
-    // eslint-disable-next-line
-    print(...args.map(arg => typeof arg === 'symbol' ? arg.toString() : arg));
-  } catch (err) {
-    // eslint-disable-next-line
-    print('cannot print:', err.message);
-    args.forEach((a, i) => {
-      // eslint-disable-next-line
-      print(` ${i}:`, a.toString ? a.toString() : '<no .toString>', typeof a);
-    });
-  }
-}
+/* global globalThis, print */
+
+// We use setQuote() below to break the cycle
+// where SES requires console and console is
+// implemented using assert.quote from SES.
+let quote = _v => '[?]';
+
+const printAll = (...args) => {
+  // Though xsnap doesn't have a whole console, it does have print().
+  // eslint-disable-next-line no-restricted-globals
+  print(...args.map(v => (typeof v === 'string' ? v : quote(v))));
+};
 
 const noop = _ => {};
 
@@ -24,11 +22,11 @@ const noop = _ => {};
  * See https://github.com/Agoric/agoric-sdk/issues/2146
  */
 const console = {
-  debug: tryPrint,
-  log: tryPrint,
-  info: tryPrint,
-  warn: tryPrint,
-  error: tryPrint,
+  debug: printAll,
+  log: printAll,
+  info: printAll,
+  warn: printAll,
+  error: printAll,
 
   trace: noop,
   dirxml: noop,
@@ -52,4 +50,14 @@ const console = {
   timeStamp: noop,
 };
 
+let quoteSet = false;
+
+export function setQuote(f) {
+  if (quoteSet) {
+    throw TypeError('quote already set');
+  }
+  quote = f;
+  quoteSet = true;
+}
+
 globalThis.console = console;

packages/xsnap/lib/ses-boot-debug.js

@@ -1,5 +1,7 @@
-import './console-shim.js';
+import { setQuote } from './console-shim.js';
 import '@agoric/eventual-send/shim.js';
 import './lockdown-shim-debug.js';
 
+setQuote(assert.quote);
+
 harden(console);

packages/xsnap/lib/ses-boot.js

@@ -1,5 +1,7 @@
-import './console-shim.js';
+import { setQuote } from './console-shim.js';
 import '@agoric/eventual-send/shim.js';
 import './lockdown-shim.js';
 
+setQuote(assert.quote);
+
 harden(console);

packages/xsnap/test/test-boot-lockdown.js

@@ -13,6 +13,45 @@ import { options, loader } from './message-tools.js';
 const io = { spawn: proc.spawn, os: os.type() }; // WARNING: ambient
 const ld = loader(import.meta.url, fs.promises.readFile);
 
+/**
+ * @param {string} name
+ * @param {string} script to execute
+ * @param {boolean=} savePrinted
+ */
+async function bootWorker(name, script, savePrinted = false) {
+  const opts = options(io);
+  const worker = xsnap({ ...opts, name });
+
+  const preface = savePrinted
+    ? `
+    globalThis.printed = [];
+    const rawPrint = print;
+    globalThis.print = (...args) => {
+      rawPrint(...args);
+      printed.push(args);
+    }
+  `
+    : 'null';
+  await worker.evaluate(preface);
+
+  await worker.evaluate(script);
+  await worker.evaluate(`
+    const encoder = new TextEncoder();
+    const send = msg => issueCommand(encoder.encode(JSON.stringify(msg)).buffer);
+    globalThis.send = send;
+  `);
+  return { worker, opts };
+}
+
+/**
+ * @param {string} name
+ * @param {boolean=} savePrinted
+ */
+async function bootSESWorker(name, savePrinted = false) {
+  const bootScript = await ld.asset('../dist/bundle-ses-boot.umd.js');
+  return bootWorker(name, bootScript, savePrinted);
+}
+
 test('bootstrap to SES lockdown', async t => {
   const bootScript = await ld.asset('../dist/bundle-ses-boot.umd.js');
   const opts = options(io);
@@ -33,10 +72,7 @@ test('bootstrap to SES lockdown', async t => {
 });
 
 test('child compartment cannot access start powers', async t => {
-  const bootScript = await ld.asset('../dist/bundle-ses-boot.umd.js');
-  const opts = options(io);
-  const vat = xsnap(opts);
-  await vat.evaluate(bootScript);
+  const { worker: vat, opts } = await bootSESWorker(t.title);
 
   const script = await ld.asset('escapeCompartment.js');
   await vat.evaluate(script);
@@ -56,10 +92,7 @@ test('child compartment cannot access start powers', async t => {
 });
 
 test('SES deep stacks work on xsnap', async t => {
-  const bootScript = await ld.asset('../dist/bundle-ses-boot.umd.js');
-  const opts = options(io);
-  const vat = xsnap(opts);
-  await vat.evaluate(bootScript);
+  const { worker: vat, opts } = await bootSESWorker(t.title);
   await vat.evaluate(`
     const encoder = new TextEncoder();
     const send = msg => issueCommand(encoder.encode(JSON.stringify(msg)).buffer);
@@ -76,10 +109,7 @@ test('SES deep stacks work on xsnap', async t => {
 });
 
 test('TextDecoder under xsnap handles TypedArray and subarrays', async t => {
-  const bootScript = await ld.asset('../dist/bundle-ses-boot.umd.js');
-  const opts = options(io);
-  const vat = xsnap(opts);
-  await vat.evaluate(bootScript);
+  const { worker: vat, opts } = await bootSESWorker(t.title);
   await vat.evaluate(`
     const decoder = new TextDecoder();
     const encoder = new TextEncoder();
@@ -99,10 +129,7 @@ test('TextDecoder under xsnap handles TypedArray and subarrays', async t => {
 
 test('console - symbols', async t => {
   // our console-shim.js handles Symbol specially
-  const bootScript = await ld.asset('../dist/bundle-ses-boot.umd.js');
-  const opts = options(io);
-  const vat = xsnap(opts);
-  await vat.evaluate(bootScript);
+  const { worker: vat, opts } = await bootSESWorker(t.title);
   t.deepEqual([], opts.messages);
   await vat.evaluate(`
     const encoder = new TextEncoder();
@@ -115,3 +142,86 @@ test('console - symbols', async t => {
   await vat.close();
   t.deepEqual(['"ok"'], opts.messages);
 });
+
+test('console - objects should include detail', async t => {
+  function runInWorker() {
+    // This was getting logged as [object Object]
+    const richStructure = {
+      prop1: ['elem1a', 'elem1b'],
+      prop2: ['elem2a', 'elem2b'],
+    };
+
+    // Let's check the rest of these while we're at it.
+    const primitive = [
+      undefined,
+      null,
+      true,
+      false,
+      123,
+      'abc',
+      123n,
+      Symbol('x'),
+    ];
+    const compound = [
+      richStructure,
+      new ArrayBuffer(10),
+      new Promise(_r => null),
+      new Error('oops!'),
+    ];
+    const { details: X } = assert;
+
+    try {
+      assert.fail(X`assertion text ${richStructure}`);
+    } catch (e) {
+      console.error(e);
+    }
+    console.log('primitive:', ...primitive);
+    console.log('compound:', ...compound);
+  }
+
+  // start a worker with the SES shim plus a global that captures args to print()
+  const { worker, opts } = await bootSESWorker(t.title, true);
+
+  await worker.evaluate(`(${runInWorker})()`);
+
+  // send all args to print(), which come from console methods
+  // filter stack traces so that we're insensitive to line number changes
+  await worker.evaluate(`
+    const skipLineNumbers = s => !s.startsWith('Error: ');
+    send(printed.map(args => args.map(a => a.toString()).filter(skipLineNumbers)))
+  `);
+  t.deepEqual(
+    opts.messages.map(s => JSON.parse(s)),
+    [
+      [
+        ['(Error#1)'],
+        [
+          'Error#1:',
+          'assertion text',
+          '{"prop1":["elem1a","elem1b"],"prop2":["elem2a","elem2b"]}',
+        ],
+        [],
+        [
+          'primitive:',
+          '"[undefined]"',
+          'null',
+          'true',
+          'false',
+          '123',
+          'abc',
+          '"[123n]"',
+          '"[Symbol(x)]"',
+        ],
+        [
+          'compound:',
+          '{"prop1":["elem1a","elem1b"],"prop2":["elem2a","elem2b"]}',
+          '"[ArrayBuffer]"',
+          '"[Promise]"',
+          '(Error#2)',
+        ],
+        ['Error#2:', 'oops!'],
+        [],
+      ],
+    ],
+  );
+});