fix: DEBUG harmony (#8136)

* fix: DEBUG harmony

* fix(agoric-cli); be sure to `await` `rmVerbose()`

* fixup! minor improvements

* fixup! DEBUG harmony

* fixup! DEBUG harmony

* fixup! minor todo done

* fixup! review syggestions

---------

Co-authored-by: Michael FIG <[email protected]>

docs/env.md

@@ -49,26 +49,31 @@ Affects: agoric (CLI), ag-chain-cosmos, ag-solo
 
 Purpose: to change the meaning of `console.log` and other console methods
 
-Description: uses `anylogger` to change whether the following methods (in order
-of increasing severity) are active for a given context:
+Description: uses `anylogger` to change whether the following methods are active
+for a given context, in order of increasing severity:
 
 1. `console.debug`
 2. `console.log`
 3. `console.info`
 4. `console.warn`
 5. `console.error`
 
-If not set, then default (`console.info` and above) logging is enabled.
+If `$DEBUG` is unset or non-empty, then default (`console.log` and above) logging is enabled.  (`console.debug` logging is disabled.)
+
+If `$DEBUG` is set to an empty string, then quiet (`console.info` and above) logging is enabled.
 (`console.log` and `console.debug` logging is disabled.)
 
-If set to an empty string, or running in `ag-chain-cosmos start` mode, don't
-print any logs.  This is part of "consensus mode."
+Otherwise, set to a comma-separated list of strings.
 
-If set to a value that contains the substring `agoric`, then print all console
-messages for the entire SDK.
+If one of those strings is
+- `agoric:${level}`, then don't print `agoric-sdk` console messages below `${level}`.
+- `agoric:none`, then silence all `agoric-sdk` console messages.
+- `agoric` (an alias for `agoric:debug`) print all `agoric-sdk` console messages.
+- `track-turns`, then log errors at the top of the event-loop that may otherwise be unreported. See also the TRACK_TURNS environment variable below.
+- `label-instances`, then log exo instances with a unique label per instance. HAZARD This causes an information leak in the messages of thrown errors, which are available even to code without access to the console. Use with care.
 
-Otherwise, set to a comma-separated list of prefixes, where each prefix is the
-context given to `makeConsole`.  For example:
+For each of those strings beginning with a prefix recognized as indicating what
+console messages to enable, pass it to `makeConsole`. For example:
 
 - `DEBUG=SwingSet:ls` enable all console messages for liveslots, regardless of vat.
 - `DEBUG=SwingSet:ls:v13` enable for liveslots in vat 13.
@@ -97,6 +102,10 @@ Description: When nonempty, create pretend prepopulated tokens like "moola" and
 
 Lifetime: until chain is mature enough not to need any pretend tokens
 
+## LOCKDOWN_*
+
+For the environment variables beginning with `LOCKDOWN_` , see [`lockdown` Options](https://github.com/endojs/endo/blob/master/packages/ses/docs/lockdown.md).
+
 ## OTEL_EXPORTER_PROMETHEUS_PORT
 
 Affects: cosmic-swingset
@@ -238,3 +247,8 @@ records individually. `config.defaultManagerType` has a higher priority so that
 tests which require a specific worker (e.g. which exercise XS heap snapshots,
 or metering) can override the env var, so they won't break under `yarn
 test:xs`.
+
+## TRACK_TURNS
+
+Log the deep causality stack behind logged errors if possible. See also the
+`DEBUG` setting `DEBUG=track-turns` above.

packages/agoric-cli/package.json

@@ -61,6 +61,7 @@
     "@endo/bundle-source": "^3.0.2",
     "@endo/captp": "^4.0.2",
     "@endo/compartment-mapper": "^1.1.0",
+    "@endo/env-options": "^1.1.0",
     "@endo/far": "^1.0.2",
     "@endo/init": "^1.0.2",
     "@endo/marshal": "^1.1.0",

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

@@ -1,31 +1,45 @@
-/* global process */
+import {
+  getEnvironmentOption,
+  getEnvironmentOptionsList,
+} from '@endo/env-options';
 import anylogger from 'anylogger';
 import chalk from 'chalk';
 
-// Turn on debugging output with DEBUG=agoric
-const { DEBUG } = process.env;
-let selectedLevel = 'info';
-if (DEBUG === undefined) {
-  selectedLevel = 'log';
-} else if (DEBUG.includes('agoric')) {
-  selectedLevel = 'debug';
+const DEBUG_LIST = getEnvironmentOptionsList('DEBUG');
+
+// Turn on debugging output with DEBUG=agoric or DEBUG=agoric:${level}
+let selectedLevel =
+  DEBUG_LIST.length || getEnvironmentOption('DEBUG', 'unset') === 'unset'
+    ? 'log'
+    : 'info';
+for (const level of DEBUG_LIST) {
+  const parts = level.split(':');
+  if (parts[0] !== 'agoric') {
+    continue;
+  }
+  if (parts.length > 1) {
+    selectedLevel = parts[1];
+  } else {
+    selectedLevel = 'debug';
+  }
 }
-const defaultLevel = anylogger.levels[selectedLevel];
+const selectedCode = anylogger.levels[selectedLevel];
+const globalCode = selectedCode === undefined ? -Infinity : selectedCode;
 
 const oldExt = anylogger.ext;
 anylogger.ext = (l, o) => {
   l = oldExt(l, o);
-  l.enabledFor = lvl => defaultLevel >= anylogger.levels[lvl];
+  l.enabledFor = lvl => globalCode >= anylogger.levels[lvl];
 
   const prefix = l.name.replace(/:/g, ': ');
   for (const [level, code] of Object.entries(anylogger.levels)) {
-    if (code > defaultLevel) {
-      // Disable printing.
-      l[level] = () => {};
-    } else {
+    if (globalCode >= code) {
       // Enable the printing with a prefix.
       const doLog = l[level] || (() => {});
       l[level] = (...args) => doLog(chalk.bold.blue(`${prefix}:`), ...args);
+    } else {
+      // Disable printing.
+      l[level] = () => {};
     }
   }
   return l;

packages/agoric-cli/src/cosmos.js

@@ -14,10 +14,10 @@ export default async function cosmosMain(progname, rawArgs, powers, opts) {
   const pspawnEnv = { ...process.env };
   if (popts.verbose > 1) {
     // Enable verbose logs.
-    pspawnEnv.DEBUG = 'agoric';
+    pspawnEnv.DEBUG = 'agoric:info';
   } else if (!popts.verbose) {
     // Disable more logs.
-    pspawnEnv.DEBUG = '';
+    pspawnEnv.DEBUG = 'agoric:none';
   }
 
   const pspawn = makePspawn({ env: pspawnEnv, log, spawn, chalk });

packages/agoric-cli/src/start.js

@@ -71,10 +71,10 @@ export default async function startMain(progname, rawArgs, powers, opts) {
   const pspawnEnv = { ...process.env };
   if (opts.verbose > 1) {
     // Loudly verbose logs (nondeterministic).
-    pspawnEnv.DEBUG = 'agoric,SwingSet:vat,SwingSet:ls';
+    pspawnEnv.DEBUG = 'agoric:debug,SwingSet:vat,SwingSet:ls';
   } else if (opts.verbose) {
     // Verbose vat logs (nondeterministic).
-    pspawnEnv.DEBUG = 'SwingSet:vat,SwingSet:ls';
+    pspawnEnv.DEBUG = 'agoric:info,SwingSet:vat,SwingSet:ls';
   }
 
   const pspawn = makePspawn({ env: pspawnEnv, spawn, log, chalk });
@@ -184,7 +184,7 @@ export default async function startMain(progname, rawArgs, powers, opts) {
 
     await null;
     if (popts.reset) {
-      rmVerbose(serverDir);
+      await rmVerbose(serverDir);
     }
 
     if (!opts.dockerTag) {
@@ -274,7 +274,7 @@ export default async function startMain(progname, rawArgs, powers, opts) {
 
     const serverDir = `${SERVERS_ROOT_DIR}/${profileName}-${portNum}`;
     if (popts.reset) {
-      rmVerbose(serverDir);
+      await rmVerbose(serverDir);
     }
 
     let chainSpawn;
@@ -481,7 +481,7 @@ export default async function startMain(progname, rawArgs, powers, opts) {
     }
 
     if (popts.reset) {
-      rmVerbose(serverDir);
+      await rmVerbose(serverDir);
     }
 
     let soloSpawn;
@@ -704,7 +704,7 @@ export default async function startMain(progname, rawArgs, powers, opts) {
     const serverDir = `${SERVERS_ROOT_DIR}/${profileName}-${port}`;
 
     if (popts.reset) {
-      rmVerbose(serverDir);
+      await rmVerbose(serverDir);
     }
 
     const setupRun = (...bonusArgs) =>
@@ -731,7 +731,7 @@ export default async function startMain(progname, rawArgs, powers, opts) {
 
     await null;
     if (popts.reset) {
-      rmVerbose(serverDir);
+      await rmVerbose(serverDir);
     }
 
     const setupRun = (...bonusArgs) =>

packages/agoric-cli/tools/getting-started.js

@@ -64,7 +64,7 @@ export const gettingStartedWorkflowTest = async (t, options = {}) => {
     // console.error('running agoric-cli', ...extraArgs, ...args);
     return pspawnStdout(agoricCmd[0], [...agoricCmd.slice(1), ...args], {
       stdio: ['ignore', 'pipe', 'inherit'],
-      env: { ...process.env, DEBUG: 'agoric' },
+      env: { ...process.env, DEBUG: 'agoric:debug' },
       detached: true,
       ...opts,
     });

packages/cosmic-swingset/package.json

@@ -33,6 +33,7 @@
     "@agoric/telemetry": "^0.6.2",
     "@agoric/vm-config": "^0.1.0",
     "@endo/bundle-source": "^3.0.2",
+    "@endo/env-options": "^1.1.0",
     "@endo/far": "^1.0.2",
     "@endo/import-bundle": "^1.0.2",
     "@endo/init": "^1.0.2",

packages/cosmic-swingset/src/anylogger-agoric.js

@@ -1,45 +1,55 @@
-/* global process */
+import {
+  getEnvironmentOptionsList,
+  getEnvironmentOption,
+} from '@endo/env-options';
 import anylogger from 'anylogger';
 
 // Turn on debugging output with DEBUG=agoric
 
-const { DEBUG: debugEnv = '' } = process.env;
-let debugging;
+const DEBUG_LIST = getEnvironmentOptionsList('DEBUG');
 
-const filterOutPrefixes = [];
-// Mute vat logging unless requested, for determinism.
-if (!debugEnv.includes('SwingSet:vat')) {
-  filterOutPrefixes.push('SwingSet:vat:');
-}
-// Mute liveSlots logging unless requested, for determinism.
-if (!debugEnv.includes('SwingSet:ls')) {
-  filterOutPrefixes.push('SwingSet:ls:');
-}
+const isVatLogNameColon = nameColon =>
+  ['SwingSet:ls:', 'SwingSet:vat:'].some(sel => nameColon.startsWith(sel));
 
-if (process.env.DEBUG === undefined) {
-  // DEBUG wasn't set, default to info level; quieter than normal.
-  debugging = 'info';
-} else if (debugEnv.includes('agoric')) {
-  // $DEBUG set and we're enabled; loudly verbose.
-  debugging = 'debug';
-} else {
-  // $DEBUG set but we're not enabled; slightly louder than normal.
-  debugging = 'log';
+// Turn on debugging output with DEBUG=agoric or DEBUG=agoric:${level}
+let selectedLevel =
+  DEBUG_LIST.length || getEnvironmentOption('DEBUG', 'unset') === 'unset'
+    ? 'log'
+    : 'info';
+for (const selector of DEBUG_LIST) {
+  const parts = selector.split(':');
+  if (parts[0] !== 'agoric') {
+    continue;
+  }
+  if (parts.length > 1) {
+    selectedLevel = parts[1];
+  } else {
+    selectedLevel = 'debug';
+  }
 }
-const defaultLevel = anylogger.levels[debugging];
+const selectedCode = anylogger.levels[selectedLevel];
+const globalCode = selectedCode === undefined ? -Infinity : selectedCode;
 
 const oldExt = anylogger.ext;
 anylogger.ext = (l, o) => {
   l = oldExt(l, o);
-  l.enabledFor = lvl => defaultLevel >= anylogger.levels[lvl];
+  l.enabledFor = lvl => globalCode >= anylogger.levels[lvl];
 
   const prefix = l.name.replace(/:/g, ': ');
-  const filteredOut = filterOutPrefixes.find(pfx => l.name.startsWith(pfx));
+
+  const nameColon = `${l.name}:`;
+  const logBelongsToVat = isVatLogNameColon(nameColon);
+
+  // If this is a vat log, then it is enabled by a selector in DEBUG_LIST.
+  const logMatchesSelector =
+    !logBelongsToVat ||
+    DEBUG_LIST.some(selector => {
+      const selectorColon = `${selector}:`;
+      return nameColon.startsWith(selectorColon);
+    });
+
   for (const [level, code] of Object.entries(anylogger.levels)) {
-    if (filteredOut || code > defaultLevel) {
-      // Disable printing.
-      l[level] = () => {};
-    } else {
+    if (logMatchesSelector && globalCode >= code) {
       // Enable the printing with a prefix.
       const doLog = l[level];
       if (doLog) {
@@ -51,6 +61,9 @@ anylogger.ext = (l, o) => {
       } else {
         l[level] = () => {};
       }
+    } else {
+      // Disable printing.
+      l[level] = () => {};
     }
   }
   return l;

packages/smart-wallet/test/test-addAsset.js

@@ -38,7 +38,7 @@ test.before(async t => {
   t.context = await makeDefaultTestContext(t, withBankManager);
 });
 
-const DEBUG = false;
+const LOG_NEWS_HEAD = false;
 const bigIntReplacer = (_key, val) =>
   typeof val === 'bigint' ? Number(val) : val;
 
@@ -68,7 +68,7 @@ test.serial('avoid O(wallets) storage writes for a new asset', async t => {
       const news = await E(current).subscribeAfter(publishCount);
       publishCount = news.publishCount;
       chainStorageWrites += 1;
-      if (DEBUG) {
+      if (LOG_NEWS_HEAD) {
         console.log(JSON.stringify(news.head, bigIntReplacer, 2));
       }
     }

packages/solo/src/start.js

@@ -371,10 +371,13 @@ const deployWallet = async ({ agWallet, deploys, hostport }) => {
 
   // Use the same verbosity as our caller did for us.
   let verbosity;
-  if (process.env.DEBUG === undefined) {
-    verbosity = [];
-  } else if (process.env.DEBUG.includes('agoric')) {
+  const DEBUG_LIST = (process.env.DEBUG || '').split(',');
+  if (
+    DEBUG_LIST.find(selector => ['agoric:debug', 'agoric'].includes(selector))
+  ) {
     verbosity = ['-vv'];
+  } else if (DEBUG_LIST.includes('agoric:info') || process.env.DEBUG === '') {
+    verbosity = [];
   } else {
     verbosity = ['-v'];
   }

packages/swingset-liveslots/package.json

@@ -20,6 +20,8 @@
     "@agoric/assert": "^0.6.0",
     "@agoric/internal": "^0.3.2",
     "@agoric/store": "^0.9.2",
+    "@endo/env-options": "^1.1.0",
+    "@endo/errors": "^1.0.2",
     "@endo/eventual-send": "^1.1.0",
     "@endo/exo": "^1.1.0",
     "@endo/far": "^1.0.2",