Context building slog sender

packages/telemetry/package.json

@@ -29,9 +29,12 @@
     "@endo/marshal": "^1.6.1",
     "@endo/stream": "^1.2.7",
     "@opentelemetry/api": "~1.3.0",
+    "@opentelemetry/api-logs": "0.53.0",
     "@opentelemetry/exporter-prometheus": "~0.35.0",
+    "@opentelemetry/exporter-logs-otlp-http": "0.53.0",
     "@opentelemetry/exporter-trace-otlp-http": "~0.35.0",
     "@opentelemetry/resources": "~1.9.0",
+    "@opentelemetry/sdk-logs": "0.53.0",
     "@opentelemetry/sdk-metrics": "~1.9.0",
     "@opentelemetry/sdk-trace-base": "~1.9.0",
     "@opentelemetry/semantic-conventions": "~1.27.0",

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

@@ -0,0 +1,348 @@
+/* eslint-env node */
+
+/**
+ * @typedef {Partial<{
+ *    'block.height': Slog['blockHeight'];
+ *    'block.time': Slog['blockTime'];
+ *    'crank.deliveryNum': Slog['deliveryNum'];
+ *    'crank.num': Slog['crankNum'];
+ *    'crank.type': Slog['crankType'];
+ *    'crank.vatID': Slog['vatID'];
+ *    init: boolean;
+ *    replay: boolean;
+ *    'run.id': string;
+ *    'run.num': string | null;
+ *    'run.trigger.blockHeight': Slog['blockHeight'];
+ *    'run.trigger.msgIdx': number;
+ *    'run.trigger.sender': Slog['sender'];
+ *    'run.trigger.source': Slog['source'];
+ *    'run.trigger.time': Slog['blockTime'];
+ *    'run.trigger.txHash': string;
+ *    'run.trigger.type': string;
+ *  }>
+ * } Context
+ *
+ * @typedef {{
+ *  'crank.syscallNum'?: Slog['syscallNum'];
+ *  'process.uptime': Slog['monotime'];
+ * } & Context} LogAttributes
+ *
+ * @typedef {{
+ *  blockHeight?: number;
+ *  blockTime?: number;
+ *  crankNum?: bigint;
+ *  crankType?: string;
+ *  deliveryNum?: bigint;
+ *  inboundNum?: string;
+ *  monotime: number;
+ *  replay?: boolean;
+ *  runNum?: number;
+ *  sender?: string;
+ *  source?: string;
+ *  syscallNum?: number;
+ *  time: number;
+ *  type: string;
+ *  vatID?: string;
+ * }} Slog
+ */
+
+const SLOG_TYPES = {
+  CLIST: 'clist',
+  CONSOLE: 'console',
+  COSMIC_SWINGSET: {
+    AFTER_COMMIT_STATS: 'cosmic-swingset-after-commit-stats',
+    BEGIN_BLOCK: 'cosmic-swingset-begin-block',
+    BOOTSTRAP_BLOCK: {
+      FINISH: 'cosmic-swingset-bootstrap-block-finish',
+      START: 'cosmic-swingset-bootstrap-block-start',
+    },
+    BRIDGE_INBOUND: 'cosmic-swingset-bridge-inbound',
+    COMMIT: {
+      FINISH: 'cosmic-swingset-commit-finish',
+      START: 'cosmic-swingset-commit-start',
+    },
+    DELIVER_INBOUND: 'cosmic-swingset-deliver-inbound',
+    END_BLOCK: {
+      FINISH: 'cosmic-swingset-end-block-finish',
+      START: 'cosmic-swingset-end-block-start',
+    },
+    // eslint-disable-next-line no-restricted-syntax
+    RUN: {
+      FINISH: 'cosmic-swingset-run-finish',
+      START: 'cosmic-swingset-run-start',
+    },
+  },
+  CRANK: {
+    RESULT: 'crank-result',
+    START: 'crank-start',
+  },
+  DELIVER: 'deliver',
+  DELIVER_RESULT: 'deliver-result',
+  KERNEL: {
+    INIT: {
+      FINISH: 'kernel-init-finish',
+      START: 'kernel-init-start',
+    },
+  },
+  REPLAY: {
+    FINISH: 'finish-replay',
+    START: 'start-replay',
+  },
+  SYSCALL: 'syscall',
+  SYSCALL_RESULT: 'syscall-result',
+};
+
+/**
+ * @template {Record<string, any>} [T={}]
+ * @param {T} [staticContext]
+ * @param {Partial<{ persistContext: (context: Context) => void; restoreContext: () => Context | null; }>} [persistenceUtils]
+ */
+export const makeContextualSlogProcessor = (
+  staticContext,
+  persistenceUtils = {},
+) => {
+  /** @type Array<Context | null> */
+  let [
+    blockContext,
+    crankContext,
+    initContext,
+    lastPersistedTriggerContext,
+    replayContext,
+    triggerContext,
+  ] = [null, null, null, null, null, null];
+
+  /**
+   * @param {Context} context
+   */
+  const persistContext = context => {
+    lastPersistedTriggerContext = context;
+    return persistenceUtils?.persistContext?.(context);
+  };
+
+  const restoreContext = () => {
+    if (!lastPersistedTriggerContext)
+      lastPersistedTriggerContext =
+        persistenceUtils?.restoreContext?.() || null;
+    return lastPersistedTriggerContext;
+  };
+
+  /**
+   * @param {Slog} slog
+   * @returns {{ attributes: T & LogAttributes, body: Partial<Slog>; timestamp: Slog['time'] }}
+   */
+  const slogProcessor = ({ monotime, time: timestamp, ...body }) => {
+    const finalBody = { ...body };
+
+    /** @type {{'crank.syscallNum'?: Slog['syscallNum']}} */
+    const eventLogAttributes = {};
+
+    /**
+     * Add any before report operations here
+     * like setting context data
+     */
+    switch (body.type) {
+      case SLOG_TYPES.KERNEL.INIT.START: {
+        initContext = { init: true };
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.BEGIN_BLOCK: {
+        blockContext = {
+          'block.height': finalBody.blockHeight,
+          'block.time': finalBody.blockTime,
+        };
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.BOOTSTRAP_BLOCK.START: {
+        blockContext = {
+          'block.height': finalBody.blockHeight || 0,
+          'block.time': finalBody.blockTime,
+        };
+        triggerContext = {
+          'run.num': null,
+          'run.id': `bootstrap-${finalBody.blockTime}`,
+          'run.trigger.type': 'bootstrap',
+          'run.trigger.time': finalBody.blockTime,
+        };
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.START: {
+        assert(!!blockContext);
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.FINISH:
+      case SLOG_TYPES.COSMIC_SWINGSET.BOOTSTRAP_BLOCK.FINISH:
+      case SLOG_TYPES.COSMIC_SWINGSET.COMMIT.START:
+      case SLOG_TYPES.COSMIC_SWINGSET.COMMIT.FINISH:
+      case SLOG_TYPES.COSMIC_SWINGSET.AFTER_COMMIT_STATS: {
+        assert(!!blockContext && !triggerContext);
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.BRIDGE_INBOUND:
+      case SLOG_TYPES.COSMIC_SWINGSET.DELIVER_INBOUND: {
+        const [blockHeight, txHash, msgIdx] = (
+          finalBody.inboundNum || ''
+        ).split('-');
+        const [, triggerType] =
+          /cosmic-swingset-([^-]+)-inbound/.exec(body.type) || [];
+
+        triggerContext = {
+          'run.num': null,
+          'run.id': `${triggerType}-${finalBody.inboundNum}`,
+          'run.trigger.type': triggerType,
+          'run.trigger.source': finalBody.source,
+          'run.trigger.sender': finalBody.sender,
+          'run.trigger.blockHeight': Number(blockHeight),
+          'run.trigger.txHash': txHash,
+          'run.trigger.msgIdx': Number(msgIdx),
+        };
+        persistContext(triggerContext);
+        break;
+      }
+      // eslint-disable-next-line no-restricted-syntax
+      case SLOG_TYPES.COSMIC_SWINGSET.RUN.START: {
+        if (!triggerContext && finalBody.runNum !== 0) {
+          assert(!!blockContext);
+          // TODO: add explicit slog events of both timer poll and install bundle
+          // https://github.com/Agoric/agoric-sdk/issues/10332
+          triggerContext = {
+            'run.num': null,
+            'run.id': `unknown-${finalBody.blockHeight}-${finalBody.runNum}`,
+            'run.trigger.type': 'unknown',
+            'run.trigger.time': blockContext['block.time'],
+            'run.trigger.blockHeight': finalBody.blockHeight,
+          };
+          persistContext(triggerContext);
+        }
+
+        if (!triggerContext) triggerContext = {};
+        triggerContext['run.num'] = `${finalBody.runNum}`;
+
+        break;
+      }
+      case SLOG_TYPES.CRANK.START: {
+        crankContext = {
+          'crank.num': finalBody.crankNum,
+          'crank.type': finalBody.crankType,
+        };
+        break;
+      }
+      case SLOG_TYPES.CLIST: {
+        assert(!!crankContext);
+        crankContext['crank.vatID'] = finalBody.vatID;
+        break;
+      }
+      case SLOG_TYPES.REPLAY.START: {
+        replayContext = { replay: true };
+        break;
+      }
+      case SLOG_TYPES.DELIVER: {
+        if (replayContext) {
+          assert(finalBody.replay);
+          replayContext = {
+            ...replayContext,
+            'crank.vatID': finalBody.vatID,
+            'crank.deliveryNum': finalBody.deliveryNum,
+          };
+        } else {
+          assert(!!crankContext && !finalBody.replay);
+          crankContext = {
+            ...crankContext,
+            'crank.vatID': finalBody.vatID,
+            'crank.deliveryNum': finalBody.deliveryNum,
+          };
+        }
+
+        delete finalBody.deliveryNum;
+        delete finalBody.replay;
+
+        break;
+      }
+      case SLOG_TYPES.DELIVER_RESULT: {
+        delete finalBody.deliveryNum;
+        delete finalBody.replay;
+
+        break;
+      }
+      case SLOG_TYPES.SYSCALL:
+      case SLOG_TYPES.SYSCALL_RESULT: {
+        eventLogAttributes['crank.syscallNum'] = finalBody.syscallNum;
+
+        delete finalBody.deliveryNum;
+        delete finalBody.replay;
+        delete finalBody.syscallNum;
+
+        break;
+      }
+      case SLOG_TYPES.CONSOLE: {
+        delete finalBody.crankNum;
+        delete finalBody.deliveryNum;
+
+        break;
+      }
+      default:
+        // All other log types are logged as is (using existing contexts) without
+        // any change to the slogs or any contributions to the contexts. This also
+        // means that any unexpected slog type will pass through. To fix that, add
+        // all remaining cases of expected slog types above with a simple break
+        // statement and log a warning here
+        break;
+    }
+
+    const logAttributes = {
+      'process.uptime': monotime,
+      ...initContext, // Optional prelude
+      ...blockContext, // Block is the first level of execution nesting
+      ...triggerContext, // run and trigger info is nested next
+      ...crankContext, // Finally cranks are the last level of nesting
+      ...replayContext, // Replay is a substitute for crank context during vat page in
+      ...eventLogAttributes,
+      ...staticContext,
+    };
+
+    /**
+     * Add any after report operations here
+     * like resetting context data
+     */
+    switch (body.type) {
+      case SLOG_TYPES.KERNEL.INIT.FINISH: {
+        initContext = null;
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.START: {
+        triggerContext = restoreContext();
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.AFTER_COMMIT_STATS: {
+        blockContext = null;
+        break;
+      }
+      case SLOG_TYPES.COSMIC_SWINGSET.BOOTSTRAP_BLOCK.FINISH: {
+        blockContext = null;
+        break;
+      }
+      // eslint-disable-next-line no-restricted-syntax
+      case SLOG_TYPES.COSMIC_SWINGSET.RUN.FINISH: {
+        triggerContext = null;
+        break;
+      }
+      case SLOG_TYPES.CRANK.RESULT: {
+        crankContext = null;
+        break;
+      }
+      case SLOG_TYPES.REPLAY.FINISH: {
+        replayContext = null;
+        break;
+      }
+      default:
+        break;
+    }
+
+    return {
+      attributes: /** @type {T & LogAttributes} */ (logAttributes),
+      body: finalBody,
+      timestamp,
+    };
+  };
+
+  return slogProcessor;
+};