improve logging for debugging

packages/beacon-node/src/network/events.ts

@@ -27,7 +27,12 @@ export enum NetworkEvent {
 }
 
 export type NetworkEventData = {
-  [NetworkEvent.peerConnected]: {peer: PeerIdStr; status: phase0.Status; dataColumns: ColumnIndex[]};
+  [NetworkEvent.peerConnected]: {
+    peer: PeerIdStr;
+    status: phase0.Status;
+    dataColumns: ColumnIndex[];
+    clientAgent: string;
+  };
   [NetworkEvent.peerDisconnected]: {peer: PeerIdStr};
   [NetworkEvent.reqRespRequest]: {request: RequestTypedContainer; peer: PeerId};
   [NetworkEvent.unknownBlockParent]: {blockInput: BlockInput; peer: PeerIdStr};

packages/beacon-node/src/network/interface.ts

@@ -58,6 +58,7 @@ export interface INetwork extends INetworkCorePublic {
 
   getConnectedPeers(): PeerIdStr[];
   getConnectedPeerCustody(peerId: PeerIdStr): number[];
+  getConnectedPeerClientAgent(peerId: PeerIdStr): string;
   getConnectedPeerCount(): number;
   isSubscribedToGossipCoreTopics(): boolean;
   reportPeer(peer: PeerIdStr, action: PeerAction, actionName: string): void;

packages/beacon-node/src/network/network.ts

@@ -107,6 +107,7 @@ export class Network implements INetwork {
 
   private subscribedToCoreTopics = false;
   private connectedPeers = new Map<PeerIdStr, ColumnIndex[]>();
+  private connectedPeerClients = new Map<PeerIdStr, string>();
   private regossipBlsChangesPromise: Promise<void> | null = null;
 
   constructor(modules: NetworkModules) {
@@ -278,6 +279,14 @@ export class Network implements INetwork {
 
     return columns;
   }
+  getConnectedPeerClientAgent(peerId: PeerIdStr): string {
+    const clientAgent = this.connectedPeerClients.get(peerId);
+    if (clientAgent === undefined) {
+      throw Error("clientAgent not in connectedPeerClients");
+    }
+
+    return clientAgent;
+  }
   getConnectedPeerCount(): number {
     return this.connectedPeers.size;
   }
@@ -686,6 +695,7 @@ export class Network implements INetwork {
   private onPeerConnected = (data: NetworkEventData[NetworkEvent.peerConnected]): void => {
     this.logger.warn("onPeerConnected", {peer: data.peer, dataColumns: data.dataColumns.join(",")});
     this.connectedPeers.set(data.peer, data.dataColumns);
+    this.connectedPeerClients.set(data.peer, data.clientAgent);
   };
 
   private onPeerDisconnected = (data: NetworkEventData[NetworkEvent.peerDisconnected]): void => {

packages/beacon-node/src/network/peers/peerManager.ts

@@ -325,8 +325,11 @@ export class PeerManager {
     // Store metadata always in case the peer updates attnets but not the sequence number
     // Trust that the peer always sends the latest metadata (From Lighthouse)
     const peerData = this.connectedPeers.get(peer.toString());
-    this.logger.warn("onMetadata", {peer: peer.toString(), peerData: peerData !== undefined});
-    console.log("onMetadata", metadata);
+    this.logger.warn("onMetadata", {
+      peer: peer.toString(),
+      peerData: peerData !== undefined,
+      csc: (metadata as Partial<peerdas.Metadata>).csc,
+    });
     if (peerData) {
       const oldMetadata = peerData.metadata;
       peerData.metadata = {
@@ -407,10 +410,9 @@ export class PeerManager {
     }
     if (getConnection(this.libp2p, peer.toString())) {
       const nodeId = peerData?.nodeId ?? computeNodeId(peer);
-      console.log("onStatus", peerData?.metadata);
       const custodySubnetCount = peerData?.metadata?.csc;
 
-      const peerCustodySubnetCount = custodySubnetCount ?? 4;
+      const peerCustodySubnetCount = custodySubnetCount ?? this.config.CUSTODY_REQUIREMENT;
       const peerCustodySubnets = getDataColumnSubnets(nodeId, peerCustodySubnetCount);
 
       const matchingSubnetsNum = this.sampleSubnets.reduce(
@@ -419,6 +421,7 @@ export class PeerManager {
       );
       const hasAllColumns = matchingSubnetsNum === this.sampleSubnets.length;
       const hasMinCustodyMatchingColumns = matchingSubnetsNum >= this.config.CUSTODY_REQUIREMENT;
+      const clientAgent = peerData?.agentClient ?? ClientKind.Unknown;
 
       this.logger.warn(`onStatus ${custodySubnetCount == undefined ? "undefined custody count assuming 4" : ""}`, {
         nodeId: toHexString(nodeId),
@@ -428,6 +431,7 @@ export class PeerManager {
         hasAllColumns,
         peerCustodySubnets: peerCustodySubnets.join(","),
         mySampleSubnets: this.sampleSubnets.join(","),
+        clientAgent,
       });
 
       if (this.opts.onlyConnectToBiggerDataNodes && !hasAllColumns) {
@@ -448,7 +452,12 @@ export class PeerManager {
 
       // coule be optimized by directly using the previously calculated subnet
       const dataColumns = getDataColumns(nodeId, peerCustodySubnetCount);
-      this.networkEventBus.emit(NetworkEvent.peerConnected, {peer: peer.toString(), status, dataColumns});
+      this.networkEventBus.emit(NetworkEvent.peerConnected, {
+        peer: peer.toString(),
+        status,
+        dataColumns,
+        clientAgent: `${clientAgent}-csc:${peerCustodySubnets.length}`,
+      });
     }
   }
 

packages/beacon-node/src/network/reqresp/beaconBlocksMaybeBlobsByRange.ts

@@ -3,6 +3,7 @@ import {ChainForkConfig} from "@lodestar/config";
 import {deneb, Epoch, phase0, SignedBeaconBlock, Slot, peerdas, ssz} from "@lodestar/types";
 import {ForkSeq, NUMBER_OF_COLUMNS, ForkName} from "@lodestar/params";
 import {computeEpochAtSlot} from "@lodestar/state-transition";
+import {Logger} from "@lodestar/utils";
 
 import {
   BlobsSource,
@@ -28,7 +29,9 @@ export async function beaconBlocksMaybeBlobsByRange(
   peerId: PeerIdStr,
   request: phase0.BeaconBlocksByRangeRequest,
   currentEpoch: Epoch,
-  partialDownload: PartialDownload
+  partialDownload: PartialDownload,
+  peerClient: string,
+  logger?: Logger
 ): Promise<{blocks: BlockInput[]; pendingDataColumns: null | number[]}> {
   // Code below assumes the request is in the same epoch
   // Range sync satisfies this condition, but double check here for sanity
@@ -108,9 +111,12 @@ export async function beaconBlocksMaybeBlobsByRange(
           : network.sendBeaconBlocksByRange(peerId, request),
         columns.length === 0 ? [] : network.sendDataColumnSidecarsByRange(peerId, dataColumnRequest),
       ]);
-      console.log({
-        beaconBlocksRequest: ssz.phase0.BeaconBlocksByRangeRequest.toJson(request),
-        dataColumnRequest: ssz.peerdas.DataColumnSidecarsByRangeRequest.toJson(dataColumnRequest),
+      logger?.debug("ByRange requests", {
+        beaconBlocksRequest: JSON.stringify(ssz.phase0.BeaconBlocksByRangeRequest.toJson(request)),
+        dataColumnRequest: JSON.stringify(ssz.peerdas.DataColumnSidecarsByRangeRequest.toJson(dataColumnRequest)),
+        peerColumns: peerColumns.join(","),
+        peerId,
+        peerClient,
       });
 
       const blocks = matchBlockWithDataColumns(
@@ -124,7 +130,9 @@ export async function beaconBlocksMaybeBlobsByRange(
         endSlot,
         BlockSource.byRange,
         DataColumnsSource.byRange,
-        partialDownload
+        partialDownload,
+        peerClient,
+        logger
       );
 
       return {blocks, pendingDataColumns: pendingDataColumns.length > 0 ? pendingDataColumns : null};
@@ -222,7 +230,9 @@ export function matchBlockWithDataColumns(
   endSlot: Slot,
   blockSource: BlockSource,
   dataColumnsSource: DataColumnsSource,
-  prevPartialDownload: null | PartialDownload
+  prevPartialDownload: null | PartialDownload,
+  peerClient: string,
+  logger?: Logger
 ): BlockInput[] {
   const blockInputs: BlockInput[] = [];
   let dataColumnSideCarIndex = 0;
@@ -256,12 +266,15 @@ export function matchBlockWithDataColumns(
       }
 
       const blobKzgCommitmentsLen = (block.data.message.body as deneb.BeaconBlockBody).blobKzgCommitments.length;
-      console.log("matchBlockWithDataColumns", {
+      logger?.debug("processing matchBlockWithDataColumns", {
         blobKzgCommitmentsLen,
         dataColumnSidecars: dataColumnSidecars.length,
         shouldHaveAllData,
-        neededColumns,
-        requestedColumns,
+        neededColumns: neededColumns.join(","),
+        requestedColumns: requestedColumns.join(","),
+        slot: block.data.message.slot,
+        dataColumnsSlots: dataColumnSidecars.map((dcm) => dcm.signedBlockHeader.message.slot).join(","),
+        peerClient,
       });
       if (blobKzgCommitmentsLen === 0) {
         if (dataColumnSidecars.length > 0) {
@@ -285,18 +298,23 @@ export function matchBlockWithDataColumns(
           true
         );
 
-        console.log("matchBlockWithDataColumns", {dataColumnIndexes, requestedColumnsPresent});
+        logger?.debug("matchBlockWithDataColumns2", {
+          dataColumnIndexes: dataColumnIndexes.join(","),
+          requestedColumnsPresent,
+          slot: block.data.message.slot,
+          peerClient,
+        });
 
         if (dataColumnSidecars.length !== requestedColumns.length || !requestedColumnsPresent) {
-          console.log(
-            "matchBlockWithDataColumns",
+          logger?.debug(
             `Missing or mismatching dataColumnSidecars from peerId=${peerId} for blockSlot=${block.data.message.slot} with numColumns=${sampledColumns.length} dataColumnSidecars=${dataColumnSidecars.length} requestedColumnsPresent=${requestedColumnsPresent} received dataColumnIndexes=${dataColumnIndexes.join(",")} requested=${requestedColumns.join(",")}`,
             {
               allBlocks: allBlocks.length,
               allDataColumnSidecars: allDataColumnSidecars.length,
               peerId,
               nodeId: toHexString(computeNodeId(peerId)),
               blobKzgCommitmentsLen,
+              peerClient,
             }
           );
           throw Error(
@@ -361,6 +379,9 @@ export function matchBlockWithDataColumns(
         .join(",")}`
     );
   }
-  console.log("matchedBlockWithDataColumns", blockInputs);
+  logger?.debug("matched BlockWithDataColumns", {
+    peerClient,
+    blockInputs: blockInputs.map((bInpt) => `${bInpt.block.message.slot}=${bInpt.type}`).join(" "),
+  });
   return blockInputs;
 }

packages/beacon-node/src/network/reqresp/beaconBlocksMaybeBlobsByRoot.ts

@@ -2,6 +2,7 @@ import {fromHexString, toHexString} from "@chainsafe/ssz";
 import {ChainForkConfig} from "@lodestar/config";
 import {phase0, deneb, peerdas, ssz} from "@lodestar/types";
 import {ForkName, ForkSeq, NUMBER_OF_COLUMNS} from "@lodestar/params";
+import {Logger} from "@lodestar/utils";
 import {
   BlockInput,
   BlockInputType,
@@ -25,14 +26,16 @@ export async function beaconBlocksMaybeBlobsByRoot(
   network: INetwork,
   peerId: PeerIdStr,
   request: phase0.BeaconBlocksByRootRequest,
-  partialDownload: null | PartialDownload
+  partialDownload: null | PartialDownload,
+  peerClient: string,
+  logger?: Logger
 ): Promise<{blocks: BlockInput[]; pendingDataColumns: null | number[]}> {
   console.log("beaconBlocksMaybeBlobsByRoot", request);
   const allBlocks = partialDownload
     ? partialDownload.blocks.map((blockInput) => ({data: blockInput.block, bytes: blockInput.blockBytes!}))
     : await network.sendBeaconBlocksByRoot(peerId, request);
 
-  console.log("beaconBlocksMaybeBlobsByRoot response", {allBlocks: allBlocks.length});
+  logger?.debug("beaconBlocksMaybeBlobsByRoot response", {allBlocks: allBlocks.length, peerClient});
 
   const preDataBlocks = [];
   const blobsDataBlocks = [];
@@ -69,7 +72,7 @@ export async function beaconBlocksMaybeBlobsByRoot(
     } else if (fork === ForkName.deneb) {
       blobsDataBlocks.push(block);
       const blobKzgCommitmentsLen = (block.data.message.body as deneb.BeaconBlockBody).blobKzgCommitments.length;
-      console.log("beaconBlocksMaybeBlobsByRoot", {blobKzgCommitmentsLen});
+      logger?.debug("beaconBlocksMaybeBlobsByRoot", {blobKzgCommitmentsLen, peerClient});
       for (let index = 0; index < blobKzgCommitmentsLen; index++) {
         blobIdentifiers.push({blockRoot, index});
       }
@@ -119,7 +122,13 @@ export async function beaconBlocksMaybeBlobsByRoot(
     }, [] as number[]);
 
     let allDataColumnsSidecars: peerdas.DataColumnSidecar[];
-    console.log("allDataColumnsSidecars", partialDownload, dataColumnIdentifiers);
+    logger?.debug("allDataColumnsSidecars partialDownload", {
+      ...(partialDownload
+        ? {blocks: partialDownload.blocks.length, pendingDataColumns: partialDownload.pendingDataColumns.join(",")}
+        : {blocks: null, pendingDataColumns: null}),
+      dataColumnIdentifiers: dataColumnIdentifiers.map((did) => did.index).join(","),
+      peerClient,
+    });
     if (dataColumnIdentifiers.length > 0) {
       allDataColumnsSidecars = await network.sendDataColumnSidecarsByRoot(peerId, dataColumnIdentifiers);
     } else {
@@ -142,7 +151,9 @@ export async function beaconBlocksMaybeBlobsByRoot(
       Infinity,
       BlockSource.byRoot,
       DataColumnsSource.byRoot,
-      partialDownload
+      partialDownload,
+      peerClient,
+      logger
     );
     blockInputs = [...blockInputs, ...blockInputWithBlobs];
   }
@@ -158,7 +169,9 @@ export async function unavailableBeaconBlobsByRoot(
   network: INetwork,
   peerId: PeerIdStr,
   unavailableBlockInput: BlockInput | NullBlockInput,
-  metrics: Metrics | null
+  metrics: Metrics | null,
+  peerClient: string,
+  logger?: Logger
 ): Promise<BlockInput> {
   if (unavailableBlockInput.block !== null && unavailableBlockInput.type !== BlockInputType.dataPromise) {
     return unavailableBlockInput;
@@ -308,7 +321,9 @@ export async function unavailableBeaconBlobsByRoot(
         DataColumnsSource.byRoot,
         unavailableBlockInput.block !== null
           ? {blocks: [unavailableBlockInput], pendingDataColumns: neededColumns}
-          : null
+          : null,
+        peerClient,
+        logger
       );
 
       // don't forget to resolve availability as the block may be stuck in availability wait

packages/beacon-node/src/sync/range/chain.ts

@@ -40,7 +40,8 @@ export type SyncChainFns = {
   downloadBeaconBlocksByRange: (
     peer: PeerIdStr,
     request: phase0.BeaconBlocksByRangeRequest,
-    partialDownload: PartialDownload
+    partialDownload: PartialDownload,
+    peerClient: string
   ) => Promise<{blocks: BlockInput[]; pendingDataColumns: null | number[]}>;
   /** Report peer for negative actions. Decouples from the full network instance */
   reportPeer: (peer: PeerIdStr, action: PeerAction, actionName: string) => void;
@@ -113,7 +114,7 @@ export class SyncChain {
   /** Sorted map of batches undergoing some kind of processing. */
   private readonly batches = new Map<Epoch, Batch>();
   private readonly peerset = new Map<PeerIdStr, ChainTarget>();
-  private readonly peersetCustody = new Map<PeerIdStr, {custodyColumns: number[]}>();
+  private readonly peersetCustody = new Map<PeerIdStr, {custodyColumns: number[]; clientAgent: string}>();
 
   private readonly logger: Logger;
   private readonly config: ChainForkConfig;
@@ -195,9 +196,9 @@ export class SyncChain {
   /**
    * Add peer to the chain and request batches if active
    */
-  addPeer(peer: PeerIdStr, target: ChainTarget, custodyColumns: number[]): void {
+  addPeer(peer: PeerIdStr, target: ChainTarget, custodyColumns: number[], clientAgent: string): void {
     this.peerset.set(peer, target);
-    this.peersetCustody.set(peer, {custodyColumns});
+    this.peersetCustody.set(peer, {custodyColumns, clientAgent});
     this.computeTarget();
     this.triggerBatchDownloader();
   }
@@ -403,9 +404,10 @@ export class SyncChain {
   private async sendBatch(batch: Batch, peer: PeerIdStr): Promise<void> {
     try {
       const partialDownload = batch.startDownloading(peer);
+      const peerClient = this.peersetCustody.get(peer)?.clientAgent ?? "unknown";
 
       // wrapError ensures to never call both batch success() and batch error()
-      const res = await wrapError(this.downloadBeaconBlocksByRange(peer, batch.request, partialDownload));
+      const res = await wrapError(this.downloadBeaconBlocksByRange(peer, batch.request, partialDownload, peerClient));
 
       if (!res.err) {
         const blocks = batch.downloadingSuccess(res.result);

packages/beacon-node/src/sync/range/range.ts

@@ -204,15 +204,18 @@ export class RangeSync extends (EventEmitter as {new (): RangeSyncEmitter}) {
   private downloadBeaconBlocksByRange: SyncChainFns["downloadBeaconBlocksByRange"] = async (
     peerId,
     request,
-    partialDownload
+    partialDownload,
+    peerClient
   ) => {
     return beaconBlocksMaybeBlobsByRange(
       this.config,
       this.network,
       peerId,
       request,
       this.chain.clock.currentEpoch,
-      partialDownload
+      partialDownload,
+      peerClient,
+      this.logger
     );
   };
 
@@ -257,7 +260,12 @@ export class RangeSync extends (EventEmitter as {new (): RangeSyncEmitter}) {
       });
     }
 
-    syncChain.addPeer(peer, target, this.network.getConnectedPeerCustody(peer));
+    syncChain.addPeer(
+      peer,
+      target,
+      this.network.getConnectedPeerCustody(peer),
+      this.network.getConnectedPeerClientAgent(peer)
+    );
   }
 
   private update(localFinalizedEpoch: Epoch): void {