diff --git a/packages/beacon-node/src/chain/emitter.ts b/packages/beacon-node/src/chain/emitter.ts index 8a3cd9b45810..9900f8d00c44 100644 --- a/packages/beacon-node/src/chain/emitter.ts +++ b/packages/beacon-node/src/chain/emitter.ts @@ -3,7 +3,7 @@ import {StrictEventEmitter} from "strict-event-emitter-types"; import {routes} from "@lodestar/api"; import {CheckpointWithHex} from "@lodestar/fork-choice"; import {IBeaconStateView} from "@lodestar/state-transition"; -import {DataColumnSidecar, RootHex, deneb, phase0} from "@lodestar/types"; +import {DataColumnSidecar, RootHex, Slot, deneb, phase0} from "@lodestar/types"; import {PeerIdStr} from "../util/peerId.js"; import {BlockInputSource, IBlockInput} from "./blocks/blockInput/types.js"; import {PayloadEnvelopeInput} from "./blocks/payloadEnvelopeInput/payloadEnvelopeInput.js"; @@ -94,7 +94,8 @@ export type ChainEventData = { peer: PeerIdStr; source: BlockInputSource; }; - [ChainEvent.unknownEnvelopeBlockRoot]: {rootHex: RootHex; peer?: PeerIdStr; source: BlockInputSource}; + // slot is the message slot, not necessarily the envelope's slot, but useful as a logging/prune hint + [ChainEvent.unknownEnvelopeBlockRoot]: {rootHex: RootHex; slot: Slot; peer?: PeerIdStr; source: BlockInputSource}; }; export type IChainEvents = ApiEvents & { diff --git a/packages/beacon-node/src/metrics/metrics/lodestar.ts b/packages/beacon-node/src/metrics/metrics/lodestar.ts index ab5e246f1bf5..745223553f59 100644 --- a/packages/beacon-node/src/metrics/metrics/lodestar.ts +++ b/packages/beacon-node/src/metrics/metrics/lodestar.ts @@ -610,6 +610,11 @@ export function createLodestarMetrics( help: "The origination source of one of the BlockInputSync triggers", labelNames: ["source"], }), + payloadSource: register.counter<{source: BlockInputSource}>({ + name: "lodestar_payload_input_sync_source_total", + help: "Count of payload (execution payload envelope) sync triggers, labeled by their source", + labelNames: ["source"], + }), pendingBlocks: register.gauge({ name: "lodestar_sync_unknown_block_pending_blocks_size", help: "Current size of UnknownBlockSync pending blocks cache", diff --git a/packages/beacon-node/src/network/processor/index.ts b/packages/beacon-node/src/network/processor/index.ts index 3dd9213b8044..357bb967e48e 100644 --- a/packages/beacon-node/src/network/processor/index.ts +++ b/packages/beacon-node/src/network/processor/index.ts @@ -299,7 +299,7 @@ export class NetworkProcessor { return; } this.unknownEnvelopesBySlot.getOrDefault(slot).add(root); - this.chain.emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, {rootHex: root, peer, source}); + this.chain.emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, {rootHex: root, slot, peer, source}); } private onPendingGossipsubMessage = (message: PendingGossipsubMessage): void => { diff --git a/packages/beacon-node/src/sync/types.ts b/packages/beacon-node/src/sync/types.ts index b79a8e40e91a..030a21aa6ecf 100644 --- a/packages/beacon-node/src/sync/types.ts +++ b/packages/beacon-node/src/sync/types.ts @@ -19,7 +19,14 @@ export enum PendingBlockType { */ INCOMPLETE_BLOCK_INPUT = "IncompleteBlockInput", - UNKNOWN_DATA = "unknown_data", + /** + * Payload analog of UNKNOWN_BLOCK_ROOT: we have a beacon block root but not its execution payload envelope. + */ + UNKNOWN_PAYLOAD_BLOCK_ROOT = "unknown_payload_block_root", + /** + * Payload analog of INCOMPLETE_BLOCK_INPUT: we have a partial payload input that did not complete in time. + */ + INCOMPLETE_PAYLOAD_ENVELOPE = "incomplete_payload_envelope", } export enum PendingBlockInputStatus { @@ -70,6 +77,8 @@ export type PendingPayloadInput = { export type PendingPayloadRootHex = { status: PendingPayloadInputStatus.pending | PendingPayloadInputStatus.fetching; rootHex: RootHex; + // message slot hint, may be missing when resolving a parent payload + slot?: Slot; timeAddedSec: number; timeSyncedSec?: number; peerIdStrings: Set; @@ -125,5 +134,5 @@ export function getPayloadSyncCacheItemSlot(payload: PayloadSyncCacheItem): Slot return payload.envelope.message.payload.slotNumber; } - return "unknown"; + return payload.slot ?? "unknown"; } diff --git a/packages/beacon-node/src/sync/unknownBlock.ts b/packages/beacon-node/src/sync/unknownBlock.ts index c108a9bdcf26..7e9856ef5171 100644 --- a/packages/beacon-node/src/sync/unknownBlock.ts +++ b/packages/beacon-node/src/sync/unknownBlock.ts @@ -3,7 +3,7 @@ import {ChainForkConfig} from "@lodestar/config"; import {ForkSeq} from "@lodestar/params"; import {RequestError, RequestErrorCode} from "@lodestar/reqresp"; import {computeTimeAtSlot} from "@lodestar/state-transition"; -import {RootHex, gloas} from "@lodestar/types"; +import {RootHex, Slot, gloas} from "@lodestar/types"; import {Logger, fromHex, prettyPrintIndices, pruneSetToMax, sleep, toRootHex} from "@lodestar/utils"; import {isBlockInputBlobs, isBlockInputColumns} from "../chain/blocks/blockInput/blockInput.js"; import {BlockInputSource, IBlockInput} from "../chain/blocks/blockInput/types.js"; @@ -215,10 +215,10 @@ export class BlockInputSync { private onUnknownEnvelopeBlockRoot = (data: ChainEventData[ChainEvent.unknownEnvelopeBlockRoot]): void => { try { - this.addByPayloadRootHex(data.rootHex, data.peer); + this.addByPayloadRootHex(data.rootHex, data.peer, data.slot); this.triggerUnknownBlockSearch(); - this.metrics?.blockInputSync.requests.inc({type: PendingBlockType.UNKNOWN_DATA}); - this.metrics?.blockInputSync.source.inc({source: data.source}); + this.metrics?.blockInputSync.requests.inc({type: PendingBlockType.UNKNOWN_PAYLOAD_BLOCK_ROOT}); + this.metrics?.blockInputSync.payloadSource.inc({source: data.source}); } catch (e) { this.logger.debug("Error handling unknownEnvelopeBlockRoot event", {}, e as Error); } @@ -228,8 +228,8 @@ export class BlockInputSync { try { this.addByPayloadInput(data.payloadInput, data.peer); this.triggerUnknownBlockSearch(); - this.metrics?.blockInputSync.requests.inc({type: PendingBlockType.UNKNOWN_DATA}); - this.metrics?.blockInputSync.source.inc({source: data.source}); + this.metrics?.blockInputSync.requests.inc({type: PendingBlockType.INCOMPLETE_PAYLOAD_ENVELOPE}); + this.metrics?.blockInputSync.payloadSource.inc({source: data.source}); } catch (e) { this.logger.debug("Error handling incompletePayloadEnvelope event", {}, e as Error); } @@ -331,7 +331,10 @@ export class BlockInputSync { }; this.pendingBlocks.set(blockInput.blockRootHex, pendingBlock); - this.logger.verbose("Added blockInput to BlockInputSync.pendingBlocks", pendingBlock.blockInput.getLogMeta()); + this.logger.verbose("Added blockInput to BlockInputSync.pendingBlocks", { + ...pendingBlock.blockInput.getLogMeta(), + delaySec: this.chain.clock.secFromSlot(blockInput.slot), + }); } if (peerIdStr) { @@ -346,13 +349,14 @@ export class BlockInputSync { } }; - private addByPayloadRootHex = (rootHex: RootHex, peerIdStr?: PeerIdStr): boolean => { + private addByPayloadRootHex = (rootHex: RootHex, peerIdStr?: PeerIdStr, slot?: Slot): boolean => { let pendingPayload = this.pendingPayloads.get(rootHex); let added = false; if (!pendingPayload) { pendingPayload = { status: PendingPayloadInputStatus.pending, rootHex, + slot, peerIdStrings: new Set(), timeAddedSec: Date.now() / 1000, }; @@ -360,6 +364,8 @@ export class BlockInputSync { added = true; this.logger.verbose("Added new payload rootHex to BlockInputSync.pendingPayloads", { + slot: slot ?? "unknown", + delaySec: slot != null ? this.chain.clock.secFromSlot(slot) : "unknown", root: rootHex, peerIdStr: peerIdStr ?? "unknown peer", }); @@ -392,6 +398,13 @@ export class BlockInputSync { } this.pendingPayloads.set(payloadInput.blockRootHex, pendingPayload); + + this.logger.verbose("Added payloadInput to BlockInputSync.pendingPayloads", { + slot: payloadInput.slot, + root: payloadInput.blockRootHex, + delaySec: this.chain.clock.secFromSlot(payloadInput.slot), + }); + const prunedItemCount = pruneSetToMax(this.pendingPayloads, this.maxPendingBlocks); if (prunedItemCount > 0) { this.logger.verbose(`Pruned ${prunedItemCount} items from BlockInputSync.pendingPayloads`); @@ -654,10 +667,12 @@ export class BlockInputSync { } const rootHex = getBlockInputSyncCacheItemRootHex(block); + const blockSlot = getBlockInputSyncCacheItemSlot(block); const logCtx = { - slot: getBlockInputSyncCacheItemSlot(block), + slot: blockSlot, root: rootHex, pendingBlocks: this.pendingBlocks.size, + ...(typeof blockSlot === "number" && {delaySec: this.chain.clock.secFromSlot(blockSlot)}), }; this.logger.verbose("BlockInputSync.downloadBlock()", logCtx); @@ -679,6 +694,7 @@ export class BlockInputSync { const logCtx2 = { ...logCtx, slot: blockSlot, + delaySec, parentInForkChoice, }; this.logger.verbose("Downloaded unknown block", logCtx2); @@ -748,6 +764,12 @@ export class BlockInputSync { // this prevents unbundling attack // see https://lighthouse-blog.sigmaprime.io/mev-unbundling-rpc.html const {slot: blockSlot, proposerIndex} = pendingBlock.blockInput.getBlock().message; + const logCtx = { + slot: blockSlot, + root: pendingBlock.blockInput.blockRootHex, + delaySec: this.chain.clock.secFromSlot(blockSlot), + }; + this.logger.verbose("Processing downloaded block", logCtx); const fork = this.config.getForkName(blockSlot); const proposerBoostWindowMs = this.config.getAttestationDueMs(fork); if ( @@ -783,6 +805,7 @@ export class BlockInputSync { else this.metrics?.blockInputSync.processedBlocksSuccess.inc(); if (!res.err) { + this.logger.verbose("Processed block from unknown sync", logCtx); // no need to update status to "processed", delete anyway this.pendingBlocks.delete(pendingBlock.blockInput.blockRootHex); // Re-enter the scheduler so descendants blocked on either parent blocks or parent payloads @@ -925,10 +948,12 @@ export class BlockInputSync { return; } + const payloadSlot = getPayloadSyncCacheItemSlot(payload); const logCtx = { - slot: getPayloadSyncCacheItemSlot(payload), + slot: payloadSlot, root: rootHex, pendingPayloads: this.pendingPayloads.size, + ...(typeof payloadSlot === "number" && {delaySec: this.chain.clock.secFromSlot(payloadSlot)}), }; this.logger.verbose("BlockInputSync.downloadPayload()", logCtx); @@ -956,7 +981,11 @@ export class BlockInputSync { private async processPayload(pendingPayload: PendingPayloadInput): Promise { const rootHex = pendingPayload.payloadInput.blockRootHex; - const logCtx = {slot: pendingPayload.payloadInput.slot, root: rootHex}; + const logCtx = { + slot: pendingPayload.payloadInput.slot, + root: rootHex, + delaySec: this.chain.clock.secFromSlot(pendingPayload.payloadInput.slot), + }; if (pendingPayload.status !== PendingPayloadInputStatus.downloaded) { this.logger.debug("Skipping payload processing before payload input is downloaded", { @@ -983,6 +1012,7 @@ export class BlockInputSync { } pendingPayload.status = PendingPayloadInputStatus.processing; + this.logger.debug("Processing downloaded payload", logCtx); const res = await wrapError(this.chain.processExecutionPayload(pendingPayload.payloadInput)); if (!res.err) { @@ -1125,6 +1155,7 @@ export class BlockInputSync { rootHex, peerId, peerClient, + ...(typeof slot === "number" && {delaySec: this.chain.clock.secFromSlot(slot)}), hasPayload: pendingPayload.payloadInput.hasPayloadEnvelope(), hasAllData: pendingPayload.payloadInput.hasAllData(), }); @@ -1296,7 +1327,7 @@ export class BlockInputSync { this.metrics?.blockInputSync.fetchBegin.observe(this.chain.clock.secFromSlot(slot, fetchStartSec)); } - const logCtx = {slot, rootHex, peerId, peerClient}; + const logCtx = {slot, rootHex, peerId, peerClient, delaySec: this.chain.clock.secFromSlot(slot)}; this.logger.verbose("BlockInputSync.fetchBlockInput: successful download", logCtx); this.metrics?.blockInputSync.downloadByRoot.success.inc(); const warnings = downloadResult.warnings; diff --git a/packages/beacon-node/test/e2e/sync/unknownBlockSync.test.ts b/packages/beacon-node/test/e2e/sync/unknownBlockSync.test.ts index 7a0479dd0afa..02c36ae4ba51 100644 --- a/packages/beacon-node/test/e2e/sync/unknownBlockSync.test.ts +++ b/packages/beacon-node/test/e2e/sync/unknownBlockSync.test.ts @@ -235,6 +235,7 @@ describe("sync / unknown block sync thru gloas", () => { case ChainEvent.unknownEnvelopeBlockRoot: bn2.chain.emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: headRootHex, + slot: headSlot, peer: sourcePeerId, source: BlockInputSource.gossip, }); diff --git a/packages/beacon-node/test/unit/sync/unknownBlock.test.ts b/packages/beacon-node/test/unit/sync/unknownBlock.test.ts index 71b686043a8b..e661ebbd236a 100644 --- a/packages/beacon-node/test/unit/sync/unknownBlock.test.ts +++ b/packages/beacon-node/test/unit/sync/unknownBlock.test.ts @@ -761,6 +761,7 @@ describe("UnknownBlockSync", () => { emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: blockRootHex, + slot: 0, peer, source: BlockInputSource.gossip, }); @@ -834,6 +835,7 @@ describe("UnknownBlockSync", () => { emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: blockRootHex, + slot: 0, peer: peerA, source: BlockInputSource.gossip, }); @@ -923,6 +925,7 @@ describe("UnknownBlockSync", () => { emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: blockRootHex, + slot: 0, peer, source: BlockInputSource.gossip, }); @@ -1021,8 +1024,11 @@ describe("UnknownBlockSync", () => { peers: [{peerId: peer}], })); - emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { + // tsgo overload-resolution miss when emit is reached through a closure that captures emitter + // first; cast re-anchors the StrictEventEmitter overload for ChainEvent keys (see #9491). + (emitter as ChainEventEmitter).emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: blockRootHex, + slot: 0, peer, source: BlockInputSource.gossip, }); @@ -1061,13 +1067,9 @@ describe("UnknownBlockSync", () => { ) .mockResolvedValueOnce(undefined); - let emitter!: ChainEventEmitter; - const processBlock = vi.fn().mockImplementation(async () => { - knownRoots.add(blockRootHex); - emitter.emit(routes.events.EventType.block, {slot: 1, block: blockRootHex, executionOptimistic: false}); - }); + const processBlock = vi.fn(); - ({emitter} = setupPayloadSyncTest({ + const {emitter} = setupPayloadSyncTest({ chainOverrides: { processBlock, processExecutionPayload, @@ -1115,10 +1117,18 @@ describe("UnknownBlockSync", () => { sendBeaconBlocksByRoot, }, peers: [{peerId: peer}], - })); + }); - emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { + processBlock.mockImplementation(async () => { + knownRoots.add(blockRootHex); + emitter.emit(routes.events.EventType.block, {slot: 1, block: blockRootHex, executionOptimistic: false}); + }); + + // tsgo overload-resolution miss when emit is reached through a closure that captures emitter + // first; cast re-anchors the StrictEventEmitter overload for ChainEvent keys. + (emitter as ChainEventEmitter).emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: blockRootHex, + slot: 0, peer, source: BlockInputSource.gossip, }); @@ -1175,6 +1185,7 @@ describe("UnknownBlockSync", () => { emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: blockRootHex, + slot: 0, peer, source: BlockInputSource.gossip, }); @@ -1224,6 +1235,7 @@ describe("UnknownBlockSync", () => { emitter.emit(ChainEvent.unknownEnvelopeBlockRoot, { rootHex: blockRootHex, + slot: 0, peer, source: BlockInputSource.gossip, });