Merge pull request #4364 from Agoric/mfig-liveslots-consensus-mode

`liveSlots` consensus mode and better verbosity switches

.prettierignore

@@ -9,5 +9,8 @@ public
 /packages/xsnap/moddable
 /packages/xsnap/xsnap-native
 
+# copied from upstream
+/packages/xsnap/lib/object-inspect.js
+
 # XXX unsupported syntax; will be addressed in https://github.com/Agoric/agoric-sdk/issues/4329
 /packages/captp/src/ts-types.d.ts

packages/SwingSet/src/kernel/liveSlots.js

@@ -1283,7 +1283,7 @@ function build(
  * @param {boolean} enableDisavow
  * @param {boolean} enableVatstore
  * @param {*} gcTools { WeakRef, FinalizationRegistry, waitUntilQuiescent }
- * @param {Console} [liveSlotsConsole]
+ * @param {Pick<Console, 'debug' | 'log' | 'info' | 'warn' | 'error'>} [liveSlotsConsole]
  * @returns {*} { vatGlobals, inescapableGlobalProperties, dispatch, setBuildRootObject }
  *
  * setBuildRootObject should be called, once, with a function that will

packages/SwingSet/src/kernel/vatManager/manager-local.js

@@ -103,6 +103,25 @@ export function makeLocalVatManagerFactory(tools) {
       testLog: allVatPowers.testLog,
     });
 
+    const makeLogMaker = logger => {
+      const makeLog = level => {
+        const log = logger[level];
+        assert.typeof(log, 'function', X`logger[${level}] must be a function`);
+        return (...args) => {
+          // We have to dynamically wrap the consensus mode so that it can change
+          // during the lifetime of the supervisor (which when snapshotting, is
+          // restored to its current heap across restarts, not actually stopping
+          // until the vat is terminated).
+          if (consensusMode) {
+            return;
+          }
+
+          log(...args);
+        };
+      };
+      return makeLog;
+    };
+
     // we might or might not use this, depending upon whether the vat exports
     // 'buildRootObject' or a default 'setup' function
     const ls = makeLiveSlots(
@@ -114,15 +133,13 @@ export function makeLocalVatManagerFactory(tools) {
       enableDisavow,
       enableVatstore,
       gcTools,
-      liveSlotsConsole,
+      makeVatConsole(makeLogMaker(liveSlotsConsole)),
     );
 
     const endowments = harden({
       ...vatEndowments,
       ...ls.vatGlobals,
-      console: makeVatConsole(vatConsole, (logger, args) => {
-        consensusMode || logger(...args);
-      }),
+      console: makeVatConsole(makeLogMaker(vatConsole)),
       assert,
       TextEncoder,
       TextDecoder,

packages/SwingSet/src/kernel/vatManager/manager-subprocess-xsnap.js

@@ -61,6 +61,7 @@ export function makeXsSubprocessFactory({
       metered,
       compareSyscalls,
       useTranscript,
+      liveSlotsConsole,
       vatConsole,
     } = managerOptions;
     assert(
@@ -87,12 +88,16 @@ export function makeXsSubprocessFactory({
           insistVatSyscallObject(vso);
           return mk.syscallFromWorker(vso);
         }
+        case 'liveSlotsConsole':
         case 'console': {
           const [level, ...rest] = args;
-          if (typeof level === 'string' && level in vatConsole) {
-            vatConsole[level](...rest);
+          // Choose the right console.
+          const myConsole =
+            (type === 'liveSlotsConsole' && liveSlotsConsole) || vatConsole;
+          if (typeof level === 'string' && level in myConsole) {
+            myConsole[level](...rest);
           } else {
-            console.error('bad console level', level);
+            console.error(`bad ${type} level`, level);
           }
           return ['ok'];
         }

packages/SwingSet/src/kernel/vatManager/supervisor-helper.js

@@ -1,5 +1,5 @@
 // @ts-check
-import { assert, details as X } from '@agoric/assert';
+import { assert } from '@agoric/assert';
 import {
   insistVatSyscallObject,
   insistVatSyscallResult,
@@ -144,36 +144,21 @@ harden(makeSupervisorSyscall);
 export { makeSupervisorSyscall };
 
 /**
- * Create a vat console, or a no-op if consensusMode is true.
+ * Create a vat console from a log stream maker.
  *
  * TODO: consider other methods per SES VirtualConsole.
  * See https://github.com/Agoric/agoric-sdk/issues/2146
  *
- * @param {Record<'debug' | 'log' | 'info' | 'warn' | 'error', (...args: any[]) => void>} logger
- * the backing log method
- * @param {(logger: any, args: any[]) => void} [wrapper]
+ * @param {(level: string) => (...args: any[]) => void} makeLog
  */
-function makeVatConsole(logger, wrapper) {
-  assert.typeof(
-    wrapper,
-    'function',
-    X`Invalid VatConsole wrapper value ${wrapper}`,
-  );
-  const cons = Object.fromEntries(
-    ['debug', 'log', 'info', 'warn', 'error'].map(level => {
-      const backingLog = logger[level];
-
-      return [
-        level,
-        (...args) => {
-          // Wrap the actual backing log message, in case there is logic to impose.
-          wrapper(backingLog, args);
-        },
-      ];
-    }),
-  );
-
-  return harden(cons);
+function makeVatConsole(makeLog) {
+  return harden({
+    debug: makeLog('debug'),
+    log: makeLog('log'),
+    info: makeLog('info'),
+    warn: makeLog('warn'),
+    error: makeLog('error'),
+  });
 }
 
 harden(makeVatConsole);

packages/SwingSet/src/kernel/vatManager/supervisor-nodeworker.js

@@ -79,6 +79,27 @@ parentPort.on('message', ([type, ...margs]) => {
       gcAndFinalize: makeGcAndFinalize(engineGC),
       meterControl: makeDummyMeterControl(),
     });
+
+    const makeLogMaker = tag => {
+      const logger = anylogger(tag);
+      const makeLog = level => {
+        const log = logger[level];
+        assert.typeof(log, 'function', X`logger[${level}] must be a function`);
+        return (...args) => {
+          // We have to dynamically wrap the consensus mode so that it can change
+          // during the lifetime of the supervisor (which when snapshotting, is
+          // restored to its current heap across restarts, not actually stopping
+          // until the vat is terminated).
+          if (consensusMode) {
+            return;
+          }
+
+          log(...args);
+        };
+      };
+      return makeLog;
+    };
+
     const ls = makeLiveSlots(
       syscall,
       vatID,
@@ -88,16 +109,12 @@ parentPort.on('message', ([type, ...margs]) => {
       enableDisavow,
       enableVatstore,
       gcTools,
+      makeVatConsole(makeLogMaker(`SwingSet:ls:${vatID}`)),
     );
 
     const endowments = {
       ...ls.vatGlobals,
-      console: makeVatConsole(
-        anylogger(`SwingSet:vat:${vatID}`),
-        (logger, args) => {
-          consensusMode || logger(...args);
-        },
-      ),
+      console: makeVatConsole(makeLogMaker(`SwingSet:vat:${vatID}`)),
       assert,
     };
 

packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-node.js

@@ -1,3 +1,5 @@
+// @ts-check
+
 // this file is loaded at the start of a new subprocess
 import '@agoric/install-ses';
 
@@ -81,6 +83,7 @@ fromParent.on('data', ([type, ...margs]) => {
       sendUplink(['syscall', vatSyscallObject]);
     }
     // this 'syscall' throws or returns data
+    // @ts-expect-error the syscaller can return void when the second argument is false
     const syscall = makeSupervisorSyscall(syscallToManager, false);
     const vatID = 'demo-vatID';
     const vatPowers = {
@@ -95,6 +98,27 @@ fromParent.on('data', ([type, ...margs]) => {
       gcAndFinalize: makeGcAndFinalize(engineGC),
       meterControl: makeDummyMeterControl(),
     });
+
+    const makeLogMaker = tag => {
+      const logger = anylogger(tag);
+      const makeLog = level => {
+        const log = logger[level];
+        assert.typeof(log, 'function', X`logger[${level}] must be a function`);
+        return (...args) => {
+          // We have to dynamically wrap the consensus mode so that it can change
+          // during the lifetime of the supervisor (which when snapshotting, is
+          // restored to its current heap across restarts, not actually stopping
+          // until the vat is terminated).
+          if (consensusMode) {
+            return;
+          }
+
+          log(...args);
+        };
+      };
+      return makeLog;
+    };
+
     const ls = makeLiveSlots(
       syscall,
       vatID,
@@ -104,17 +128,13 @@ fromParent.on('data', ([type, ...margs]) => {
       enableDisavow,
       enableVatstore,
       gcTools,
+      makeVatConsole(makeLogMaker(`SwingSet:ls:${vatID}`)),
     );
 
     // Enable or disable the console accordingly.
     const endowments = {
       ...ls.vatGlobals,
-      console: makeVatConsole(
-        anylogger(`SwingSet:vat:${vatID}`),
-        (logger, args) => {
-          consensusMode || logger(...args);
-        },
-      ),
+      console: makeVatConsole(makeLogMaker(`SwingSet:vat:${vatID}`)),
       assert,
     };
 
@@ -125,7 +145,7 @@ fromParent.on('data', ([type, ...margs]) => {
         workerLog(`got vatNS:`, Object.keys(vatNS).join(','));
         sendUplink(['gotBundle']);
         ls.setBuildRootObject(vatNS.buildRootObject);
-        dispatch = makeSupervisorDispatch(ls.dispatch, waitUntilQuiescent);
+        dispatch = makeSupervisorDispatch(ls.dispatch);
         workerLog(`got dispatch:`, Object.keys(dispatch).join(','));
         sendUplink(['dispatchReady']);
       },

packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js

@@ -1,6 +1,6 @@
 /* global globalThis WeakRef FinalizationRegistry */
 // @ts-check
-import { assert, details as X, q } from '@agoric/assert';
+import { assert, details as X } from '@agoric/assert';
 import { importBundle } from '@agoric/import-bundle';
 import { makeMarshal } from '@agoric/marshal';
 import '../../types.js';
@@ -204,6 +204,9 @@ function makeWorker(port) {
     consensusMode,
     gcEveryCrank,
   ) {
+    // Enable or disable the consensus mode according to current settings.
+    currentConsensusMode = consensusMode;
+
     /** @type { (vso: VatSyscallObject) => VatSyscallResult } */
     function syscallToManager(vatSyscallObject) {
       workerLog('doSyscall', vatSyscallObject);
@@ -243,6 +246,42 @@ function makeWorker(port) {
       meterControl,
     });
 
+    /** @param {string} dst */
+    const makeLogMaker = dst => {
+      /** @param {string} level */
+      const makeLog = level => {
+        // Capture the `console.log`, etc.'s `printAll` function.
+        const printAll = console[level];
+        assert.typeof(printAll, 'function');
+        const portSendingPrinter = (...args) => {
+          port.send([dst, level, ...args]);
+        };
+        return (...args) => {
+          // We have to dynamically wrap the consensus mode so that it can change
+          // during the lifetime of the supervisor (which when snapshotting, is
+          // restored to its current heap across restarts, not actually stopping
+          // until the vat is terminated).
+          if (currentConsensusMode) {
+            return;
+          }
+
+          // Use the causal console, but output to the port.
+          //
+          // FIXME: This is a hack until the start compartment can create
+          // Console objects that log to a different destination than
+          // `globalThis.console`.
+          const { print: savePrinter } = globalThis;
+          try {
+            globalThis.print = portSendingPrinter;
+            printAll(...args);
+          } finally {
+            globalThis.print = savePrinter;
+          }
+        };
+      };
+      return makeLog;
+    };
+
     const ls = makeLiveSlots(
       syscall,
       vatID,
@@ -252,37 +291,12 @@ function makeWorker(port) {
       enableDisavow,
       enableVatstore,
       gcTools,
+      makeVatConsole(makeLogMaker('liveSlotsConsole')),
     );
 
-    const makeLog = level => {
-      return (...args) => {
-        // TODO: use more faithful stringification
-        const jsonSafeArgs = JSON.parse(`${q(args)}`);
-        port.send(['console', level, ...jsonSafeArgs]);
-      };
-    };
-    const forwardingLogger = {
-      debug: makeLog('debug'),
-      log: makeLog('log'),
-      info: makeLog('info'),
-      warn: makeLog('warn'),
-      error: makeLog('error'),
-    };
-
-    // Enable or disable the console accordingly.
-    currentConsensusMode = consensusMode;
     const endowments = {
       ...ls.vatGlobals,
-      console: makeVatConsole(
-        forwardingLogger,
-        // We have to dynamically wrap the consensus mode so that it can change
-        // during the lifetime of the supervisor (which when snapshotting, is
-        // restored to its current heap across restarts, not actually stopping
-        // until the vat is terminated).
-        (logger, args) => {
-          currentConsensusMode || logger(...args);
-        },
-      ),
+      console: makeVatConsole(makeLogMaker('console')),
       assert,
       // bootstrap provides HandledPromise
       HandledPromise: globalThis.HandledPromise,

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

@@ -164,15 +164,15 @@ test('XS + SES snapshots are long-term deterministic', async t => {
   const h2 = await store.save(vat.snapshot);
   t.is(
     h2,
-    '9e11a482f0d4bd25c988a4e102d24c0d239afe332981787a674f84149a63f0a0',
+    '994211d096e8b5b7a975074fe155bf4963e350abd7b67e24fbe444401d82613b',
     'after SES boot - sensitive to SES-shim, XS, and supervisor',
   );
 
   await vat.evaluate('globalThis.x = harden({a: 1})');
   const h3 = await store.save(vat.snapshot);
   t.is(
     h3,
-    '556ebf0c07a99517e86ddd2fc0b0fadb8c39731de1c14ceaca5741ca246f13d3',
+    '243821fd617ad4cd06a19ee08a2d1fb2957c9ab3de49624dc38acd16203d5e9e',
     'after use of harden() - sensitive to SES-shim, XS, and supervisor',
   );
 });

packages/agoric-cli/src/anylogger-agoric.js

@@ -3,11 +3,11 @@ import anylogger from 'anylogger';
 import chalk from 'chalk';
 
 // Turn on debugging output with DEBUG=agoric
-
+const { DEBUG } = process.env;
 let selectedLevel = 'info';
-if (process.env.DEBUG === undefined) {
+if (DEBUG === undefined) {
   selectedLevel = 'log';
-} else if (process.env.DEBUG.includes('agoric')) {
+} else if (DEBUG.includes('agoric')) {
   selectedLevel = 'debug';
 }
 const defaultLevel = anylogger.levels[selectedLevel];