feat(cosmic-swingset): make agd start stdout/stderr logs more consistent

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

@@ -4,15 +4,54 @@ import {
   getEnvironmentOption,
 } from '@endo/env-options';
 import anylogger from 'anylogger';
+import util from 'util';
 
-// Turn on debugging output with DEBUG=agoric
+//#region Golang zerolog-like output affordances
+let logFormat = 'plain';
+export const setLogFormat = format => {
+  logFormat = format;
+};
 
-const DEBUG_LIST = getEnvironmentOptionsList('DEBUG');
+let shortDateTimeFormatter;
+const plainTime = d => {
+  if (!shortDateTimeFormatter) {
+    shortDateTimeFormatter = new Intl.DateTimeFormat(undefined, {
+      timeStyle: 'short',
+    });
+  }
+  const shortTime = shortDateTimeFormatter.format(d).replace(/(\d) /, '$1');
+  return shortTime;
+};
+
+const levelToPlainLevel = {
+  error: 'ERR',
+  warn: 'WRN',
+  info: 'INF',
+  log: 'LOG',
+  debug: 'DBG',
+};
+
+/**
+ * @param {Date} d
+ * @returns {string}
+ */
+const jsonTime = d => {
+  const pad2 = n => (n < 10 ? `0${n}` : `${n}`);
+  const isoDate = `${d.getFullYear()}-${pad2(d.getMonth() + 1)}-${pad2(d.getDate())}`;
+  const isoTime = `${pad2(d.getHours())}:${pad2(d.getMinutes())}:${pad2(d.getSeconds())}`;
+  const tzo = d.getTimezoneOffset();
+  const isoTz = `${tzo < 0 ? '+' : '-'}${pad2(Math.floor(Math.abs(tzo) / 60))}:${pad2(Math.abs(tzo) % 60)}`;
+  return `${isoDate}T${isoTime}${isoTz}`;
+};
+
+//#endregion
 
 const isVatLogNameColon = nameColon =>
   ['SwingSet:ls:', 'SwingSet:vat:'].some(sel => nameColon.startsWith(sel));
 
 // Turn on debugging output with DEBUG=agoric or DEBUG=agoric:${level}
+const DEBUG_LIST = getEnvironmentOptionsList('DEBUG');
+
 let selectedLevel =
   DEBUG_LIST.length || getEnvironmentOption('DEBUG', 'unset') === 'unset'
     ? 'log'
@@ -54,10 +93,25 @@ anylogger.ext = logger => {
       // Enable the printing with a prefix.
       const doLog = l[level];
       if (doLog) {
+        const plainLevel = levelToPlainLevel[level];
         l[level] = (...args) => {
           // Add a timestamp.
-          const now = new Date().toISOString();
-          doLog(`${now} ${prefix}:`, ...args);
+          const now = new Date();
+          switch (logFormat) {
+            case 'plain': {
+              doLog(`${plainTime(now)} ${plainLevel} ${prefix}:`, ...args);
+              break;
+            }
+
+            case 'json':
+            default: {
+              const message = [`${prefix}:`, ...args]
+                .map(a => (typeof a === 'string' ? a : util.inspect(a)))
+                .join(' ');
+              doLog(JSON.stringify({ level, time: jsonTime(now), message }));
+              break;
+            }
+          }
         };
       } else {
         l[level] = () => {};

packages/cosmic-swingset/src/chain-main.js

@@ -38,6 +38,7 @@ import {
   makeArchiveSnapshot,
   makeArchiveTranscript,
 } from '@agoric/swing-store';
+import anylogger from 'anylogger';
 import {
   makeBufferedStorage,
   makeReadCachingStorage,
@@ -55,6 +56,10 @@ import {
   validateImporterOptions,
 } from './import-kernel-db.js';
 
+import { setLogFormat } from './anylogger-agd.js';
+
+const console = anylogger('chain-main');
+
 const ignore = () => {};
 
 // eslint-disable-next-line no-unused-vars
@@ -184,6 +189,8 @@ export default async function main(
     'home',
     `${homedir}/.ag-chain-cosmos`,
   );
+  const logFormat = processValue.getFlag('log_format', 'plain');
+  setLogFormat(logFormat);
   const stateDBDir = `${cosmosHome}/data/agoric`;
   fs.mkdirSync(stateDBDir, { recursive: true });
 
@@ -455,6 +462,7 @@ export default async function main(
 
     const slogSender = await makeSlogSender({
       stateDir: stateDBDir,
+      console: anylogger('slog-sender'),
       env,
       serviceName: TELEMETRY_SERVICE_NAME,
     });

packages/cosmic-swingset/src/entrypoint.js

@@ -11,7 +11,7 @@ import os from 'os';
 import path from 'path';
 import process from 'process';
 
-import './anylogger-agoric.js';
+import './anylogger-agd.js';
 import anylogger from 'anylogger';
 import main from './chain-main.js';
 

packages/solo/src/entrypoint.js

@@ -13,7 +13,7 @@ import process from 'process';
 import path from 'path';
 
 // Configure logs.
-import '@agoric/cosmic-swingset/src/anylogger-agoric.js';
+import '@agoric/cosmic-swingset/src/anylogger-agd.js';
 import solo from './main.js';
 
 const baseprog = path.basename(process.argv[1]);

packages/solo/src/pipe-entrypoint.js

@@ -7,7 +7,7 @@ import { makeError } from '@endo/errors';
 import { makePromiseKit } from '@endo/promise-kit';
 import { parse, stringify } from '@endo/marshal';
 
-import '@agoric/cosmic-swingset/src/anylogger-agoric.js';
+import '@agoric/cosmic-swingset/src/anylogger-agd.js';
 import { connectToFakeChain } from '@agoric/cosmic-swingset/src/sim-chain.js';
 import { makeShutdown } from '@agoric/internal/src/node/shutdown.js';
 

packages/telemetry/src/context-aware-slog-file.js

@@ -1,4 +1,5 @@
 /* eslint-env node */
+/* global globalThis */
 
 import { makeFsStreamWriter } from '@agoric/internal/src/node/fs-stream.js';
 import { makeContextualSlogProcessor } from './context-aware-slog.js';
@@ -9,6 +10,7 @@ import { serializeSlogObj } from './serialize-slog-obj.js';
  */
 export const makeSlogSender = async options => {
   const { CHAIN_ID, CONTEXTUAL_SLOGFILE } = options.env || {};
+  const { console = globalThis.console } = options;
   if (!CONTEXTUAL_SLOGFILE)
     return console.warn(
       'Ignoring invocation of slogger "context-aware-slog-file" without the presence of "CONTEXTUAL_SLOGFILE"',

packages/telemetry/src/index.js

@@ -20,6 +20,7 @@ export * from './make-slog-sender.js';
  * @typedef {MakeSlogSenderCommonOptions & Record<string, unknown>} MakeSlogSenderOptions
  * @typedef {object} MakeSlogSenderCommonOptions
  * @property {Record<string, string | undefined>} [env]
+ * @property {Pick<Console, 'debug' | 'log' | 'info' | 'warn' | 'error'>} [console]
  * @property {string} [stateDir]
  * @property {string} [serviceName]
  */
@@ -28,11 +29,16 @@ export * from './make-slog-sender.js';
  * @param {SlogSender} [slogSender]
  * @param {object} [options]
  * @param {Record<string, string | undefined>} [options.env]
- * @param {(...args: any[]) => void} [options.log]
+ * @param {MakeSlogSenderCommonOptions['console']} [options.console]
+ * @param {(...args) => void} [options.log]
  */
 export const tryFlushSlogSender = async (
   slogSender,
-  { env = {}, log } = {},
+  {
+    env = {},
+    console = globalThis.console,
+    log = (...args) => console.warn(...args),
+  } = {},
 ) => {
   await Promise.resolve(slogSender?.forceFlush?.()).catch(err => {
     log?.('Failed to flush slog sender', err);
@@ -81,7 +87,7 @@ export const getResourceAttributes = ({
 
 /**
  * @typedef {object} Powers
- * @property {{ warn: Console['warn'] }} console
+ * @property {MakeSlogSenderCommonOptions['console']} console
  * @property {NodeJS.ProcessEnv} env
  * @property {import('@opentelemetry/sdk-metrics').View[]} views
  * @property {string} [serviceName]

packages/telemetry/src/make-slog-sender.js

@@ -1,3 +1,4 @@
+/* global globalThis */
 import path from 'path';
 import tmp from 'tmp';
 import { PromiseAllOrErrors } from '@agoric/internal';
@@ -22,7 +23,12 @@ const filterTruthy = arr => /** @type {any[]} */ (arr.filter(Boolean));
  * @type {import('./index.js').MakeSlogSender}
  */
 export const makeSlogSender = async (opts = {}) => {
-  const { env = {}, stateDir: stateDirOption, ...otherOpts } = opts;
+  const {
+    env = {},
+    console = globalThis.console,
+    stateDir: stateDirOption,
+    ...otherOpts
+  } = opts;
   const {
     SLOGSENDER = DEFAULT_SLOGSENDER_MODULE,
     SLOGSENDER_AGENT = DEFAULT_SLOGSENDER_AGENT,

packages/telemetry/src/otel-and-flight-recorder.js

@@ -1,3 +1,4 @@
+/* global globalThis */
 import { NonNullish } from '@agoric/internal';
 import { makeSlogSender as makeSlogSenderFromEnv } from './make-slog-sender.js';
 
@@ -6,6 +7,7 @@ import { makeSlogSender as makeSlogSenderFromEnv } from './make-slog-sender.js';
  */
 export const makeSlogSender = async opts => {
   const { SLOGFILE: _1, SLOGSENDER: _2, ...otherEnv } = opts.env || {};
+  const { console = globalThis.console } = opts || {};
 
   console.warn(
     'Deprecated slog sender, please use SLOGSENDER=@agoric/telemetry/src/flight-recorder.js,@agoric/telemetry/src/otel-trace.js',

packages/telemetry/src/otel-context-aware-slog.js

@@ -1,4 +1,5 @@
 /* eslint-env node */
+/* global globalThis */
 import { logs, SeverityNumber } from '@opentelemetry/api-logs';
 import { OTLPLogExporter } from '@opentelemetry/exporter-logs-otlp-http';
 import { Resource } from '@opentelemetry/resources';
@@ -16,8 +17,13 @@ const FILE_ENCODING = 'utf8';
 
 /**
  * @param {string} filePath
+ * @param {object} [powers]
+ * @param {import('./index.js').MakeSlogSenderCommonOptions['console']} [powers.console]
  */
-export const getContextFilePersistenceUtils = filePath => {
+export const getContextFilePersistenceUtils = (
+  filePath,
+  { console = globalThis.console } = {},
+) => {
   console.warn(`Using file ${filePath} for slogger context`);
 
   return {
@@ -51,6 +57,7 @@ export const getContextFilePersistenceUtils = filePath => {
  */
 export const makeSlogSender = async options => {
   const { CHAIN_ID, OTEL_EXPORTER_OTLP_ENDPOINT } = options.env || {};
+  const { console = globalThis.console } = options;
   if (!(OTEL_EXPORTER_OTLP_ENDPOINT && options.stateDir))
     return console.error(
       'Ignoring invocation of slogger "context-aware-slog" without the presence of "OTEL_EXPORTER_OTLP_ENDPOINT" and "stateDir"',
@@ -71,6 +78,7 @@ export const makeSlogSender = async options => {
   const persistenceUtils = getContextFilePersistenceUtils(
     process.env.SLOG_CONTEXT_FILE_PATH ||
       `${options.stateDir}/${DEFAULT_CONTEXT_FILE}`,
+    { console: options.console },
   );
 
   const contextualSlogProcessor = makeContextualSlogProcessor(

packages/telemetry/src/otel-trace.js

@@ -1,4 +1,4 @@
-/* globals process */
+/* globals process globalThis */
 import {
   BasicTracerProvider,
   BatchSpanProcessor,
@@ -16,11 +16,10 @@ export const SPAN_MAX_QUEUE_SIZE = 100_000;
 export const SPAN_EXPORT_DELAY_MS = 1_000;
 
 /**
- * @param {object} opts
- * @param {Record<string, string>} opts.env
+ * @param {import('./index.js').MakeSlogSenderCommonOptions} opts
  */
 export const makeOtelTracingProvider = opts => {
-  const { env = process.env } = opts || {};
+  const { env = process.env, console = globalThis.console } = opts || {};
 
   const { OTEL_EXPORTER_OTLP_ENDPOINT, OTEL_EXPORTER_OTLP_TRACES_ENDPOINT } =
     env;
@@ -45,14 +44,17 @@ export const makeOtelTracingProvider = opts => {
   return provider;
 };
 
+/**
+ * @param {import('./index.js').MakeSlogSenderOptions & { version?: string }} opts
+ */
 export const makeSlogSender = async opts => {
   const tracingProvider =
     makeOtelTracingProvider(opts) || new BasicTracerProvider();
 
   tracingProvider.register();
   const tracer = tracingProvider.getTracer('slog-trace', opts.version);
 
-  const { slogSender, finish } = makeSlogToOtelKit(tracer);
+  const { slogSender, finish } = makeSlogToOtelKit(tracer, undefined, opts);
 
   // Cleanly shutdown if possible.
   const { registerShutdown } = makeShutdown();

packages/telemetry/src/slog-to-otel.js

@@ -1,3 +1,4 @@
+/* global globalThis */
 import otel, { SpanStatusCode } from '@opentelemetry/api';
 
 import { Fail, q } from '@endo/errors';
@@ -78,8 +79,10 @@ export const floatSecondsToHiRes = sFloat => {
 /**
  * @param {import('@opentelemetry/api').Tracer} tracer
  * @param {Record<string, any>} [overrideAttrs]
+ * @param {import('./index.js').MakeSlogSenderOptions} [powers]
  */
-export const makeSlogToOtelKit = (tracer, overrideAttrs = {}) => {
+export const makeSlogToOtelKit = (tracer, overrideAttrs = {}, powers = {}) => {
+  const { console = globalThis.console } = powers;
   let now;
   let nowFloat;
   /** @type {Record<string, any>} */

packages/telemetry/test/import.test.js

@@ -8,10 +8,17 @@ const sleep = timeoutMs =>
 
 test('get telemetry providers', async t => {
   const logged = [];
+  const mockMethod =
+    level =>
+    (...args) => {
+      logged.push([level, ...args]);
+    };
   const mockConsole = {
-    warn: (...args) => {
-      logged.push(args);
-    },
+    debug: mockMethod('debug'),
+    log: mockMethod('log'),
+    info: mockMethod('info'),
+    warn: mockMethod('warn'),
+    error: mockMethod('error'),
   };
   const providers = getTelemetryProviders({ console: mockConsole, env: {} });
   t.is(providers.metricsProvider, undefined);
@@ -31,6 +38,6 @@ test('get telemetry providers', async t => {
   t.deepEqual(logged, []);
   await sleep(250);
   t.deepEqual(logged, [
-    ['Prometheus scrape endpoint: http://0.0.0.0:9393/metrics'],
+    ['warn', 'Prometheus scrape endpoint: http://0.0.0.0:9393/metrics'],
   ]);
 });