chore: fix BlockInputSync metrics and logs

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 & {

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",

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 => {

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<string>;
@@ -125,5 +134,5 @@ export function getPayloadSyncCacheItemSlot(payload: PayloadSyncCacheItem): Slot
     return payload.envelope.message.payload.slotNumber;
   }
 
-  return "unknown";
+  return payload.slot ?? "unknown";
 }

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,20 +349,23 @@ 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,
       };
       this.pendingPayloads.set(rootHex, pendingPayload);
       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<void> {
     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;

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,
           });

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,
       });