diff --git a/a3p-integration/proposals/n:upgrade-next/priceFeedUpdate.test.js b/a3p-integration/proposals/n:upgrade-next/priceFeedUpdate.test.js index 5cbacd019ad..d0bdaa1b055 100644 --- a/a3p-integration/proposals/n:upgrade-next/priceFeedUpdate.test.js +++ b/a3p-integration/proposals/n:upgrade-next/priceFeedUpdate.test.js @@ -14,10 +14,12 @@ import { getVaultPrices, getVatDetails, openVault, - pushPrices, - registerOraclesForBrand, USER1ADDR, } from '@agoric/synthetic-chain'; +import { + getPriceFeedRoundId, + verifyPushedPrice, +} from './test-lib/price-feed.js'; import { BID_OFFER_ID } from './agd-tools.js'; @@ -37,12 +39,17 @@ const checkPriceFeedVatsUpdated = async t => { await checkForOracle(t, 'stATOM'); }; -console.log('adding oracle for each brand'); -const oraclesByBrand = generateOracleMap('f-priceFeeds', ['ATOM', 'stATOM']); -await registerOraclesForBrand('ATOM', oraclesByBrand); -await registerOraclesForBrand('stATOM', oraclesByBrand); +/* + * The Oracle for ATOM and stATOM brands are being registered in the offer made at file: + * a3p-integration/proposals/n:upgrade-next/verifyPushedPrice.js + * which is being executed during the use phase of upgrade-next proposal + */ +const oraclesByBrand = generateOracleMap('n-upgrade', ['ATOM', 'stATOM']); -let roundId = 1; +const latestAtomRoundId = await getPriceFeedRoundId('ATOM'); +const latestStAtomRoundId = await getPriceFeedRoundId('stATOM'); +let atomRoundId = latestAtomRoundId + 1; +let stAtomRoundId = latestStAtomRoundId + 1; const tryPushPrices = async t => { // There are no old prices for the other currencies. @@ -52,9 +59,10 @@ const tryPushPrices = async t => { // t.is(stAtomOutPre, '+12010000'); t.log('pushing new prices'); - await pushPrices(13.4, 'ATOM', oraclesByBrand, roundId); - await pushPrices(13.7, 'stATOM', oraclesByBrand, roundId); - roundId += 1; + await verifyPushedPrice(13.4, 'ATOM', oraclesByBrand, atomRoundId); + await verifyPushedPrice(13.7, 'stATOM', oraclesByBrand, stAtomRoundId); + atomRoundId += 1; + stAtomRoundId += 1; t.log('awaiting new quotes'); const atomOut = await getPriceQuote('ATOM'); @@ -89,7 +97,7 @@ const openMarginalVault = async t => { }; const triggerAuction = async t => { - await pushPrices(5.2, 'ATOM', oraclesByBrand, roundId); + await verifyPushedPrice(5.2, 'ATOM', oraclesByBrand, atomRoundId); const atomOut = await getPriceQuote('ATOM'); t.is(atomOut, '+5200000'); diff --git a/a3p-integration/proposals/n:upgrade-next/test-lib/price-feed.js b/a3p-integration/proposals/n:upgrade-next/test-lib/price-feed.js new file mode 100644 index 00000000000..c0e2acd311d --- /dev/null +++ b/a3p-integration/proposals/n:upgrade-next/test-lib/price-feed.js @@ -0,0 +1,62 @@ +/* eslint-env node */ + +import { + agoric, + getContractInfo, + pushPrices, + getPriceQuote, +} from '@agoric/synthetic-chain'; +import { retryUntilCondition } from './sync-tools.js'; + +export const scale6 = x => BigInt(x * 1_000_000); + +/** + * + * @param {number} price + * @param {string} brand + * @param {Map} oraclesByBrand + * @param {number} roundId + * @returns {Promise} + */ +export const verifyPushedPrice = async ( + price, + brand, + oraclesByBrand, + roundId, +) => { + const pushPriceRetryOpts = { + maxRetries: 5, // arbitrary + retryIntervalMs: 5000, // in ms + }; + + await pushPrices(price, brand, oraclesByBrand, roundId); + console.log(`Pushing price ${price} for ${brand}`); + + await retryUntilCondition( + () => getPriceQuote(brand), + res => res === `+${scale6(price).toString()}`, + 'price not pushed yet', + { + log: console.log, + setTimeout: global.setTimeout, + ...pushPriceRetryOpts, + }, + ); + console.log(`Price ${price} pushed for ${brand}`); +}; + +/** + * + * @param {string} brand + * @returns {Promise} + */ +export const getPriceFeedRoundId = async brand => { + const latestRoundPath = `published.priceFeed.${brand}-USD_price_feed.latestRound`; + const latestRound = await getContractInfo(latestRoundPath, { + agoric, + prefix: '', + }); + + console.log('latestRound: ', latestRound); + return Number(latestRound.roundId); +}; diff --git a/a3p-integration/proposals/n:upgrade-next/test-lib/sync-tools.js b/a3p-integration/proposals/n:upgrade-next/test-lib/sync-tools.js new file mode 100644 index 00000000000..4a0e727c465 --- /dev/null +++ b/a3p-integration/proposals/n:upgrade-next/test-lib/sync-tools.js @@ -0,0 +1,72 @@ +/* eslint-env node */ + +/** + * @file These tools mostly duplicate code that will be added in other PRs + * and eventually migrated to synthetic-chain. Sorry for the duplication. + */ + +/** + * @typedef {object} RetryOptions + * @property {number} [maxRetries] + * @property {number} [retryIntervalMs] + * @property {(...arg0: string[]) => void} log + * @property {(object) => void} [setTimeout] + * @property {string} [errorMessage=Error] + */ + +const ambientSetTimeout = global.setTimeout; + +/** + * From https://github.com/Agoric/agoric-sdk/blob/442f07c8f0af03281b52b90e90c27131eef6f331/multichain-testing/tools/sleep.ts#L10 + * + * @param {number} ms + * @param {*} sleepOptions + */ +const sleep = (ms, { log = () => {}, setTimeout = ambientSetTimeout }) => + new Promise(resolve => { + log(`Sleeping for ${ms}ms...`); + setTimeout(resolve, ms); + }); + +/** + * From https://github.com/Agoric/agoric-sdk/blob/442f07c8f0af03281b52b90e90c27131eef6f331/multichain-testing/tools/sleep.ts#L24 + * + * @param {() => Promise} operation + * @param {(result: any) => boolean} condition + * @param {string} message + * @param {RetryOptions} options + */ +export const retryUntilCondition = async ( + operation, + condition, + message, + { maxRetries = 6, retryIntervalMs = 3500, log, setTimeout }, +) => { + console.log({ maxRetries, retryIntervalMs, message }); + let retries = 0; + + await null; + while (retries < maxRetries) { + try { + const result = await operation(); + log('RESULT', result); + if (condition(result)) { + return result; + } + } catch (error) { + if (error instanceof Error) { + log(`Error: ${error.message}`); + } else { + log(`Unknown error: ${String(error)}`); + } + } + + retries += 1; + console.log( + `Retry ${retries}/${maxRetries} - Waiting for ${retryIntervalMs}ms for ${message}...`, + ); + await sleep(retryIntervalMs, { log, setTimeout }); + } + + throw Error(`${message} condition failed after ${maxRetries} retries.`); +}; diff --git a/a3p-integration/proposals/n:upgrade-next/use.sh b/a3p-integration/proposals/n:upgrade-next/use.sh index c68eaeafecc..fa6c4e42f65 100644 --- a/a3p-integration/proposals/n:upgrade-next/use.sh +++ b/a3p-integration/proposals/n:upgrade-next/use.sh @@ -5,3 +5,6 @@ set -uxeo pipefail node ./addGov4 ./acceptInvites.js + +./verifyPushedPrice.js 'ATOM' 12.01 +./verifyPushedPrice.js 'stATOM' 12.01 diff --git a/a3p-integration/proposals/n:upgrade-next/verifyPushedPrice.js b/a3p-integration/proposals/n:upgrade-next/verifyPushedPrice.js new file mode 100644 index 00000000000..98449c316a5 --- /dev/null +++ b/a3p-integration/proposals/n:upgrade-next/verifyPushedPrice.js @@ -0,0 +1,21 @@ +#!/usr/bin/env node + +import { + registerOraclesForBrand, + generateOracleMap, +} from '@agoric/synthetic-chain'; +import { argv } from 'node:process'; +import { verifyPushedPrice } from './test-lib/price-feed.js'; + +const brand = argv[2]; +const price = Number(argv[3]); + +const BASE_ID = 'n-upgrade'; +const ROUND_ID = 1; + +const oraclesByBrand = generateOracleMap(BASE_ID, [brand]); +await registerOraclesForBrand(brand, oraclesByBrand); +console.log(`Registering Oracle for ${brand}`); + +await verifyPushedPrice(price, brand, oraclesByBrand, ROUND_ID); +console.log(`Price pushed for ${brand}`); diff --git a/a3p-integration/proposals/z:acceptance/vaults.test.js b/a3p-integration/proposals/z:acceptance/vaults.test.js index 5545a9381be..73f6c9433a2 100644 --- a/a3p-integration/proposals/z:acceptance/vaults.test.js +++ b/a3p-integration/proposals/z:acceptance/vaults.test.js @@ -8,53 +8,15 @@ import { adjustVault, closeVault, getISTBalance, - getPriceQuote, - pushPrices, getContractInfo, ATOM_DENOM, USER1ADDR, waitForBlock, - registerOraclesForBrand, - generateOracleMap, } from '@agoric/synthetic-chain'; import { getBalances, agopsVaults } from './test-lib/utils.js'; -import { retryUntilCondition } from './test-lib/sync-tools.js'; export const scale6 = x => BigInt(x * 1_000_000); -// There may be a new vaultFactory that doesn't have prices yet, so we publish -// prices now -test.before(async t => { - const pushPriceRetryOpts = { - maxRetries: 5, // arbitrary - retryIntervalMs: 5000, // in ms - }; - t.context = { - roundId: 1, - retryOpts: { - pushPriceRetryOpts, - }, - }; - const oraclesByBrand = generateOracleMap('z-acc', ['ATOM']); - await registerOraclesForBrand('ATOM', oraclesByBrand); - - const price = 15.2; - // @ts-expect-error t.context is fine - await pushPrices(price, 'ATOM', oraclesByBrand, t.context.roundId); - - await retryUntilCondition( - () => getPriceQuote('ATOM'), - res => res === `+${scale6(price).toString()}`, - 'price not pushed yet', - { - log: t.log, - setTimeout: global.setTimeout, - // @ts-expect-error t.context is fine - ...t.context.pushPriceRetryOpts, - }, - ); -}); - test.serial('attempt to open vaults under the minimum amount', async t => { const activeVaultsBefore = await agopsVaults(USER1ADDR); await bankSend(USER1ADDR, `20000000${ATOM_DENOM}`); diff --git a/packages/cosmic-swingset/src/launch-chain.js b/packages/cosmic-swingset/src/launch-chain.js index c8b113d5528..c2211d66a4c 100644 --- a/packages/cosmic-swingset/src/launch-chain.js +++ b/packages/cosmic-swingset/src/launch-chain.js @@ -527,6 +527,8 @@ export async function launch({ inboundNum, sender, count: messages.length, + messages, + ack, }); if (!mb.deliverInbound(sender, messages, ack)) { return; @@ -539,6 +541,7 @@ export async function launch({ type: 'cosmic-swingset-bridge-inbound', inboundNum, source, + body, }); if (!bridgeInbound) throw Fail`bridgeInbound undefined`; // console.log(`doBridgeInbound`); @@ -547,7 +550,7 @@ export async function launch({ bridgeInbound(source, body); } - async function installBundle(bundleJson) { + async function installBundle(bundleJson, inboundNum) { let bundle; try { bundle = JSON.parse(bundleJson); @@ -564,6 +567,13 @@ export async function launch({ const { endoZipBase64Sha512 } = bundle; + controller.writeSlogObject({ + type: 'cosmic-swingset-install-bundle', + inboundNum, + endoZipBase64Sha512, + error, + }); + if (installationPublisher === undefined) { return; } @@ -645,7 +655,7 @@ export async function launch({ } case ActionType.INSTALL_BUNDLE: { - p = installBundle(action.bundle); + p = installBundle(action.bundle, inboundNum); break; } @@ -714,6 +724,12 @@ export async function launch({ // Then, update the timer device with the new external time, which might // push work onto the kernel run-queue (if any timers were ready to wake). const addedToQueue = timer.poll(blockTime); + controller.writeSlogObject({ + type: 'cosmic-swingset-timer-poll', + blockHeight, + blockTime, + added: addedToQueue, + }); console.debug( `polled; blockTime:${blockTime}, h:${blockHeight}; ADDED =`, addedToQueue, diff --git a/packages/telemetry/package.json b/packages/telemetry/package.json index 4ca8fa5f285..cd0cb0585c0 100644 --- a/packages/telemetry/package.json +++ b/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", diff --git a/packages/telemetry/src/context-aware-slog-file.js b/packages/telemetry/src/context-aware-slog-file.js new file mode 100644 index 00000000000..003680fc2bd --- /dev/null +++ b/packages/telemetry/src/context-aware-slog-file.js @@ -0,0 +1,42 @@ +/* eslint-env node */ + +import { makeFsStreamWriter } from '@agoric/internal/src/node/fs-stream.js'; +import { makeContextualSlogProcessor } from './context-aware-slog.js'; +import { serializeSlogObj } from './serialize-slog-obj.js'; + +/** + * @param {import('./index.js').MakeSlogSenderOptions} options + */ +export const makeSlogSender = async options => { + const { CHAIN_ID, CONTEXTUAL_SLOGFILE } = options.env || {}; + if (!CONTEXTUAL_SLOGFILE) + return console.warn( + 'Ignoring invocation of slogger "context-aware-slog-file" without the presence of "CONTEXTUAL_SLOGFILE"', + ); + + const stream = await makeFsStreamWriter(CONTEXTUAL_SLOGFILE); + + if (!stream) + return console.error( + `Couldn't create a write stream on file "${CONTEXTUAL_SLOGFILE}"`, + ); + + const contextualSlogProcessor = makeContextualSlogProcessor({ + 'chain-id': CHAIN_ID, + }); + + /** + * @param {import('./context-aware-slog.js').Slog} slog + */ + const slogSender = slog => { + const contextualizedSlog = contextualSlogProcessor(slog); + + // eslint-disable-next-line prefer-template + stream.write(serializeSlogObj(contextualizedSlog) + '\n').catch(() => {}); + }; + + return Object.assign(slogSender, { + forceFlush: () => stream.flush(), + shutdown: () => stream.close(), + }); +}; diff --git a/packages/telemetry/src/context-aware-slog.js b/packages/telemetry/src/context-aware-slog.js new file mode 100644 index 00000000000..33c2739efc5 --- /dev/null +++ b/packages/telemetry/src/context-aware-slog.js @@ -0,0 +1,383 @@ +/* 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.bundleHash': Slog['endoZipBase64Sha512']; + * '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; + * remainingBeans?: bigint; + * replay?: boolean; + * runNum?: number; + * sender?: string; + * source?: string; + * endoZipBase64Sha512?: 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', + }, + COMMIT: { + FINISH: 'cosmic-swingset-commit-finish', + START: 'cosmic-swingset-commit-start', + }, + 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', + }, + }, + COSMIC_SWINGSET_TRIGGERS: { + BRIDGE_INBOUND: 'cosmic-swingset-bridge-inbound', + DELIVER_INBOUND: 'cosmic-swingset-deliver-inbound', + TIMER_POLL: 'cosmic-swingset-timer-poll', + INSTALL_BUNDLE: 'cosmic-swingset-install-bundle', + }, + CRANK: { + FINISH: 'crank-finish', + 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} [T={}] + * @param {T} [staticContext] + * @param {Partial<{ persistContext: (context: Context) => void; restoreContext: () => Context | null; }>} [persistenceUtils] + */ +export const makeContextualSlogProcessor = ( + staticContext, + persistenceUtils = {}, +) => { + /** @type Array */ + 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; 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, + }; + break; + } + case SLOG_TYPES.COSMIC_SWINGSET.END_BLOCK.START: + 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_TRIGGERS.BRIDGE_INBOUND: + case SLOG_TYPES.COSMIC_SWINGSET_TRIGGERS.DELIVER_INBOUND: { + const [blockHeight, txHash, msgIdx] = ( + finalBody.inboundNum || '' + ).split('-'); + const [, triggerType] = + /cosmic-swingset-([^-]+)-inbound/.exec(body.type) || []; + + triggerContext = { + 'run.num': undefined, + '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), + }; + break; + } + case SLOG_TYPES.COSMIC_SWINGSET_TRIGGERS.INSTALL_BUNDLE: { + const [blockHeight, txHash, msgIdx] = ( + finalBody.inboundNum || '' + ).split('-'); + + const triggerType = 'install-bundle'; + + triggerContext = { + 'run.num': undefined, + 'run.id': `${triggerType}-${finalBody.inboundNum}`, + 'run.trigger.type': triggerType, + 'run.trigger.bundleHash': finalBody.endoZipBase64Sha512, + 'run.trigger.blockHeight': Number(blockHeight), + 'run.trigger.txHash': txHash, + 'run.trigger.msgIdx': Number(msgIdx), + }; + + break; + } + case SLOG_TYPES.COSMIC_SWINGSET_TRIGGERS.TIMER_POLL: { + const triggerType = 'timer-poll'; + + triggerContext = { + 'run.num': undefined, + 'run.id': `${triggerType}-${finalBody.inboundNum}`, + 'run.trigger.type': triggerType, + 'run.trigger.time': finalBody.blockTime, + 'run.trigger.blockHeight': finalBody.blockHeight, + }; + + break; + } + // eslint-disable-next-line no-restricted-syntax + case SLOG_TYPES.COSMIC_SWINGSET.RUN.START: { + if (!finalBody.runNum) { + assert(!triggerContext); + triggerContext = restoreContext(); // Restore persisted context if any + } else if (!triggerContext) { + 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': undefined, + 'run.id': `unknown-${finalBody.blockHeight}-${finalBody.runNum}`, + 'run.trigger.type': 'unknown', + 'run.trigger.blockHeight': finalBody.blockHeight, + }; + } + + 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: + case SLOG_TYPES.REPLAY.FINISH: { + replayContext = { replay: true, 'crank.vatID': finalBody.vatID }; + 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 = { + ...staticContext, + '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, + }; + + /** + * 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.BOOTSTRAP_BLOCK.START: { + triggerContext = { + 'run.num': undefined, + 'run.id': `bootstrap-${finalBody.blockTime}`, + 'run.trigger.type': 'bootstrap', + 'run.trigger.time': finalBody.blockTime, + }; + break; + } + case SLOG_TYPES.COSMIC_SWINGSET.AFTER_COMMIT_STATS: + 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: { + assert(!!triggerContext); + persistContext(finalBody.remainingBeans ? {} : triggerContext); + triggerContext = null; + break; + } + case SLOG_TYPES.CRANK.FINISH: { + crankContext = null; + break; + } + case SLOG_TYPES.REPLAY.FINISH: { + replayContext = null; + break; + } + default: + break; + } + + return { + attributes: /** @type {T & LogAttributes} */ (logAttributes), + body: finalBody, + timestamp, + }; + }; + + return slogProcessor; +}; diff --git a/packages/telemetry/src/otel-context-aware-slog.js b/packages/telemetry/src/otel-context-aware-slog.js new file mode 100644 index 00000000000..51891460eba --- /dev/null +++ b/packages/telemetry/src/otel-context-aware-slog.js @@ -0,0 +1,131 @@ +/* eslint-env node */ +import { logs, SeverityNumber } from '@opentelemetry/api-logs'; +import { OTLPLogExporter } from '@opentelemetry/exporter-logs-otlp-http'; +import { Resource } from '@opentelemetry/resources'; +import { + LoggerProvider, + SimpleLogRecordProcessor, +} from '@opentelemetry/sdk-logs'; +import { readFileSync, writeFileSync } from 'fs'; +import { makeContextualSlogProcessor } from './context-aware-slog.js'; +import { getResourceAttributes } from './index.js'; +import { serializeSlogObj } from './serialize-slog-obj.js'; + +const DEFAULT_CONTEXT_FILE = 'slog-context.json'; +const FILE_ENCODING = 'utf8'; + +/** + * @param {string} filePath + */ +export const getContextFilePersistenceUtils = filePath => { + console.warn(`Using file ${filePath} for slogger context`); + + return { + /** + * @param {import('./context-aware-slog.js').Context} context + */ + persistContext: context => { + try { + writeFileSync(filePath, serializeSlogObj(context), FILE_ENCODING); + } catch (err) { + console.error('Error writing context to file: ', err); + } + }, + + /** + * @returns {import('./context-aware-slog.js').Context | null} + */ + restoreContext: () => { + try { + return JSON.parse(readFileSync(filePath, FILE_ENCODING)); + } catch (parseErr) { + console.error('Error reading context from file: ', parseErr); + return null; + } + }, + }; +}; + +/** + * @param {import('./index.js').MakeSlogSenderOptions} options + */ +export const makeSlogSender = async options => { + const { CHAIN_ID, OTEL_EXPORTER_OTLP_ENDPOINT } = options.env || {}; + 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"', + ); + + const loggerProvider = new LoggerProvider({ + resource: new Resource(getResourceAttributes(options)), + }); + + const otelLogExporter = new OTLPLogExporter({ keepAlive: true }); + const logRecordProcessor = new SimpleLogRecordProcessor(otelLogExporter); + + loggerProvider.addLogRecordProcessor(logRecordProcessor); + + logs.setGlobalLoggerProvider(loggerProvider); + const logger = logs.getLogger('default'); + + const persistenceUtils = getContextFilePersistenceUtils( + process.env.SLOG_CONTEXT_FILE_PATH || + `${options.stateDir}/${DEFAULT_CONTEXT_FILE}`, + ); + + const contextualSlogProcessor = makeContextualSlogProcessor( + { 'chain-id': CHAIN_ID }, + persistenceUtils, + ); + + /** + * @param {import('./context-aware-slog.js').Slog} slog + */ + const slogSender = slog => { + const { timestamp, ...logRecord } = contextualSlogProcessor(slog); + + const [secondsStr, fractionStr] = String(timestamp).split('.'); + const seconds = parseInt(secondsStr, 10); + const nanoSeconds = parseInt( + (fractionStr || String(0)).padEnd(9, String(0)).slice(0, 9), + 10, + ); + + logger.emit({ + ...JSON.parse(serializeSlogObj(logRecord)), + severityNumber: SeverityNumber.INFO, + timestamp: [seconds, nanoSeconds], + }); + }; + + const shutdown = async () => { + await Promise.resolve(); + const errors = []; + + try { + await logRecordProcessor.shutdown(); + } catch (err) { + errors.push(err); + } + + try { + await otelLogExporter.forceFlush(); + } catch (err) { + errors.push(err); + } + + switch (errors.length) { + case 0: + return; + case 1: + throw errors[0]; + default: + throw AggregateError(errors); + } + }; + + return Object.assign(slogSender, { + forceFlush: () => otelLogExporter.forceFlush(), + shutdown, + }); +}; diff --git a/packages/telemetry/src/slog-to-otel.js b/packages/telemetry/src/slog-to-otel.js index d4b4abc4a44..87b36fd269d 100644 --- a/packages/telemetry/src/slog-to-otel.js +++ b/packages/telemetry/src/slog-to-otel.js @@ -915,7 +915,7 @@ export const makeSlogToOtelKit = (tracer, overrideAttrs = {}) => { break; } case 'cosmic-swingset-upgrade-finish': { - spans.pop(['slogAttrs.blockHeight', slogAttrs.blockHeight]); + spans.pop(['upgrade', slogAttrs.blockHeight]); dbTransactionManager.end(); break; } @@ -971,6 +971,16 @@ export const makeSlogToOtelKit = (tracer, overrideAttrs = {}) => { spans.pop('bridge-inbound'); break; } + case 'cosmic-swingset-timer-poll': { + spans.push(['timer-poll', slogAttrs.blockTime]); + spans.pop('timer-poll'); + break; + } + case 'cosmic-swingset-install-bundle': { + spans.push(['install-bundle', slogAttrs.endoZipBase64Sha512]); + spans.pop('install-bundle'); + break; + } case 'cosmic-swingset-end-block-start': { // Add `end-block` as an event onto the encompassing `block` span spans.top()?.addEvent('end-block-action', cleanAttrs(slogAttrs), now); diff --git a/yarn.lock b/yarn.lock index f2059f6e6bc..bb8a5ec3a88 100644 --- a/yarn.lock +++ b/yarn.lock @@ -3042,6 +3042,13 @@ dependencies: "@octokit/openapi-types" "^18.0.0" +"@opentelemetry/api-logs@0.53.0": + version "0.53.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/api-logs/-/api-logs-0.53.0.tgz#c478cbd8120ec2547b64edfa03a552cfe42170be" + integrity sha512-8HArjKx+RaAI8uEIgcORbZIPklyh1YLjPSBus8hjRmvLi6DeFzgOcdZ7KwPabKj8mXF8dX0hyfAyGfycz0DbFw== + dependencies: + "@opentelemetry/api" "^1.0.0" + "@opentelemetry/api@^1.0.0": version "1.4.1" resolved "https://registry.yarnpkg.com/@opentelemetry/api/-/api-1.4.1.tgz#ff22eb2e5d476fbc2450a196e40dd243cc20c28f" @@ -3052,6 +3059,13 @@ resolved "https://registry.yarnpkg.com/@opentelemetry/api/-/api-1.3.0.tgz#27c6f776ac3c1c616651e506a89f438a0ed6a055" integrity sha512-YveTnGNsFFixTKJz09Oi4zYkiLT5af3WpZDu4aIUM7xX+2bHAkOJayFTVQd6zB8kkWPpbua4Ha6Ql00grdLlJQ== +"@opentelemetry/core@1.26.0": + version "1.26.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/core/-/core-1.26.0.tgz#7d84265aaa850ed0ca5813f97d831155be42b328" + integrity sha512-1iKxXXE8415Cdv0yjG3G6hQnB5eVEsJce3QaawX8SjDn0mAS0ZM8fAbZZJD4ajvhC15cePvosSCut404KrIIvQ== + dependencies: + "@opentelemetry/semantic-conventions" "1.27.0" + "@opentelemetry/core@1.9.1": version "1.9.1" resolved "https://registry.yarnpkg.com/@opentelemetry/core/-/core-1.9.1.tgz#e343337e1a7bf30e9a6aef3ef659b9b76379762a" @@ -3066,6 +3080,17 @@ dependencies: "@opentelemetry/semantic-conventions" "1.15.2" +"@opentelemetry/exporter-logs-otlp-http@0.53.0": + version "0.53.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/exporter-logs-otlp-http/-/exporter-logs-otlp-http-0.53.0.tgz#1b4a152ea427ec4581532880fd0d620cc559cb11" + integrity sha512-cSRKgD/n8rb+Yd+Cif6EnHEL/VZg1o8lEcEwFji1lwene6BdH51Zh3feAD9p2TyVoBKrl6Q9Zm2WltSp2k9gWQ== + dependencies: + "@opentelemetry/api-logs" "0.53.0" + "@opentelemetry/core" "1.26.0" + "@opentelemetry/otlp-exporter-base" "0.53.0" + "@opentelemetry/otlp-transformer" "0.53.0" + "@opentelemetry/sdk-logs" "0.53.0" + "@opentelemetry/exporter-prometheus@~0.35.0": version "0.35.1" resolved "https://registry.yarnpkg.com/@opentelemetry/exporter-prometheus/-/exporter-prometheus-0.35.1.tgz#c2fd5fcd17dac8106b33e5d354d98c47ebaa8804" @@ -3093,6 +3118,14 @@ dependencies: "@opentelemetry/core" "1.9.1" +"@opentelemetry/otlp-exporter-base@0.53.0": + version "0.53.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/otlp-exporter-base/-/otlp-exporter-base-0.53.0.tgz#dfe51874b869c687c3cb463b70cddda7de282762" + integrity sha512-UCWPreGQEhD6FjBaeDuXhiMf6kkBODF0ZQzrk/tuQcaVDJ+dDQ/xhJp192H9yWnKxVpEjFrSSLnpqmX4VwX+eA== + dependencies: + "@opentelemetry/core" "1.26.0" + "@opentelemetry/otlp-transformer" "0.53.0" + "@opentelemetry/otlp-transformer@0.35.1": version "0.35.1" resolved "https://registry.yarnpkg.com/@opentelemetry/otlp-transformer/-/otlp-transformer-0.35.1.tgz#d4333b71324b83dbb1b0b3a4cfd769b3e214c6f9" @@ -3103,6 +3136,27 @@ "@opentelemetry/sdk-metrics" "1.9.1" "@opentelemetry/sdk-trace-base" "1.9.1" +"@opentelemetry/otlp-transformer@0.53.0": + version "0.53.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/otlp-transformer/-/otlp-transformer-0.53.0.tgz#55d435db5ed5cf56b99c010827294dd4921c45c2" + integrity sha512-rM0sDA9HD8dluwuBxLetUmoqGJKSAbWenwD65KY9iZhUxdBHRLrIdrABfNDP7aiTjcgK8XFyTn5fhDz7N+W6DA== + dependencies: + "@opentelemetry/api-logs" "0.53.0" + "@opentelemetry/core" "1.26.0" + "@opentelemetry/resources" "1.26.0" + "@opentelemetry/sdk-logs" "0.53.0" + "@opentelemetry/sdk-metrics" "1.26.0" + "@opentelemetry/sdk-trace-base" "1.26.0" + protobufjs "^7.3.0" + +"@opentelemetry/resources@1.26.0": + version "1.26.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/resources/-/resources-1.26.0.tgz#da4c7366018bd8add1f3aa9c91c6ac59fd503cef" + integrity sha512-CPNYchBE7MBecCSVy0HKpUISEeJOniWqcHaAHpmasZ3j9o6V3AyBzhRc90jdmemq0HOxDr6ylhUbDhBqqPpeNw== + dependencies: + "@opentelemetry/core" "1.26.0" + "@opentelemetry/semantic-conventions" "1.27.0" + "@opentelemetry/resources@1.9.1", "@opentelemetry/resources@~1.9.0": version "1.9.1" resolved "https://registry.yarnpkg.com/@opentelemetry/resources/-/resources-1.9.1.tgz#5ad3d80ba968a3a0e56498ce4bc82a6a01f2682f" @@ -3111,6 +3165,23 @@ "@opentelemetry/core" "1.9.1" "@opentelemetry/semantic-conventions" "1.9.1" +"@opentelemetry/sdk-logs@0.53.0": + version "0.53.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/sdk-logs/-/sdk-logs-0.53.0.tgz#ec8b69278c4e683c13c58ed4285a47c27f5799c6" + integrity sha512-dhSisnEgIj/vJZXZV6f6KcTnyLDx/VuQ6l3ejuZpMpPlh9S1qMHiZU9NMmOkVkwwHkMy3G6mEBwdP23vUZVr4g== + dependencies: + "@opentelemetry/api-logs" "0.53.0" + "@opentelemetry/core" "1.26.0" + "@opentelemetry/resources" "1.26.0" + +"@opentelemetry/sdk-metrics@1.26.0": + version "1.26.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/sdk-metrics/-/sdk-metrics-1.26.0.tgz#37bb0afb1d4447f50aab9cdd05db6f2d8b86103e" + integrity sha512-0SvDXmou/JjzSDOjUmetAAvcKQW6ZrvosU0rkbDGpXvvZN+pQF6JbK/Kd4hNdK4q/22yeruqvukXEJyySTzyTQ== + dependencies: + "@opentelemetry/core" "1.26.0" + "@opentelemetry/resources" "1.26.0" + "@opentelemetry/sdk-metrics@1.9.1", "@opentelemetry/sdk-metrics@~1.9.0": version "1.9.1" resolved "https://registry.yarnpkg.com/@opentelemetry/sdk-metrics/-/sdk-metrics-1.9.1.tgz#babc162a81df9884c16b1e67c2dd26ab478f3080" @@ -3120,6 +3191,15 @@ "@opentelemetry/resources" "1.9.1" lodash.merge "4.6.2" +"@opentelemetry/sdk-trace-base@1.26.0": + version "1.26.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/sdk-trace-base/-/sdk-trace-base-1.26.0.tgz#0c913bc6d2cfafd901de330e4540952269ae579c" + integrity sha512-olWQldtvbK4v22ymrKLbIcBi9L2SpMO84sCPY54IVsJhP9fRsxJT194C/AVaAuJzLE30EdhhM1VmvVYR7az+cw== + dependencies: + "@opentelemetry/core" "1.26.0" + "@opentelemetry/resources" "1.26.0" + "@opentelemetry/semantic-conventions" "1.27.0" + "@opentelemetry/sdk-trace-base@1.9.1", "@opentelemetry/sdk-trace-base@~1.9.0": version "1.9.1" resolved "https://registry.yarnpkg.com/@opentelemetry/sdk-trace-base/-/sdk-trace-base-1.9.1.tgz#c349491b432a7e0ae7316f0b48b2d454d79d2b84" @@ -3134,16 +3214,16 @@ resolved "https://registry.yarnpkg.com/@opentelemetry/semantic-conventions/-/semantic-conventions-1.15.2.tgz#3bafb5de3e20e841dff6cb3c66f4d6e9694c4241" integrity sha512-CjbOKwk2s+3xPIMcd5UNYQzsf+v94RczbdNix9/kQh38WiQkM90sUOi3if8eyHFgiBjBjhwXrA7W3ydiSQP9mw== +"@opentelemetry/semantic-conventions@1.27.0", "@opentelemetry/semantic-conventions@~1.27.0": + version "1.27.0" + resolved "https://registry.yarnpkg.com/@opentelemetry/semantic-conventions/-/semantic-conventions-1.27.0.tgz#1a857dcc95a5ab30122e04417148211e6f945e6c" + integrity sha512-sAay1RrB+ONOem0OZanAR1ZI/k7yDpnOQSQmTMuGImUQb2y8EbSaCJ94FQluM74xoU03vlb2d2U90hZluL6nQg== + "@opentelemetry/semantic-conventions@1.9.1": version "1.9.1" resolved "https://registry.yarnpkg.com/@opentelemetry/semantic-conventions/-/semantic-conventions-1.9.1.tgz#ad3367684a57879392513479e0a436cb2ac46dad" integrity sha512-oPQdbFDmZvjXk5ZDoBGXG8B4tSB/qW5vQunJWQMFUBp7Xe8O1ByPANueJ+Jzg58esEBegyyxZ7LRmfJr7kFcFg== -"@opentelemetry/semantic-conventions@~1.27.0": - version "1.27.0" - resolved "https://registry.yarnpkg.com/@opentelemetry/semantic-conventions/-/semantic-conventions-1.27.0.tgz#1a857dcc95a5ab30122e04417148211e6f945e6c" - integrity sha512-sAay1RrB+ONOem0OZanAR1ZI/k7yDpnOQSQmTMuGImUQb2y8EbSaCJ94FQluM74xoU03vlb2d2U90hZluL6nQg== - "@parcel/watcher@2.0.4": version "2.0.4" resolved "https://registry.yarnpkg.com/@parcel/watcher/-/watcher-2.0.4.tgz#f300fef4cc38008ff4b8c29d92588eced3ce014b" @@ -10052,7 +10132,7 @@ proto-list@~1.2.1: resolved "https://registry.yarnpkg.com/proto-list/-/proto-list-1.2.4.tgz#212d5bfe1318306a420f6402b8e26ff39647a849" integrity sha1-IS1b/hMYMGpCD2QCuOJv85ZHqEk= -protobufjs@^6.8.8, protobufjs@^7.2.4, protobufjs@^7.2.6: +protobufjs@^6.8.8, protobufjs@^7.2.4, protobufjs@^7.2.6, protobufjs@^7.3.0: version "7.4.0" resolved "https://registry.yarnpkg.com/protobufjs/-/protobufjs-7.4.0.tgz#7efe324ce9b3b61c82aae5de810d287bc08a248a" integrity sha512-mRUWCc3KUU4w1jU8sGxICXH/gNS94DvI1gxqDvBzhj1JpcsimQkYiOJfwsPUykUI5ZaspFbSgmBLER8IrQ3tqw==