Add execution blockNumber to the notifier log

docs/usage/beacon-management.md

@@ -69,18 +69,20 @@ In case execution-layer clients are available at different locations, use `--exe
 Immediately you should see confirmation that the node has started
 
 ```bash
-Nov-29 15:59:48.479[]                 info: Lodestar network=sepolia, version=v1.2.1/q9f/docs/14898d5, commit=14898d5beea341bc7d450dd494dcb9efbb9556fa
-Nov-29 15:59:48.518[]                 info: Connected to LevelDB database path=/home/user/.local/share/lodestar/sepolia/chain-db
-Nov-29 15:59:49.347[network]          info: PeerId 16Uiu2HAm9kKss7LSRU5Z6xYz7Rr5JzWVz8njqx7Ezyj4SSDcpT2Q, Multiaddrs /ip4/127.0.0.1/tcp/9000/p2p/16Uiu2HAm9kKss7LSRU5Z6xYz7Rr5JzWVz8njqx7Ezyj4SSDcpT2Q,/ip4/192.168.1.26/tcp/9000/p2p/16Uiu2HAm9kKss7LSRU5Z6xYz7Rr5JzWVz8njqx7Ezyj4SSDcpT2Q
-Nov-29 15:59:49.457[rest]             info: Started REST API server address=http://127.0.0.1:9596
-Nov-29 15:59:49.458[]                 warn: Low peer count peers=0
-Nov-29 15:59:49.459[]                 info: Searching peers - peers: 0 - slot: 1164899 (skipped 1164899) - head: 0 0xfb9b…de43 - finalized: 0x0000…0000:0
-Nov-29 15:59:54.001[]                 info: Searching peers - peers: 0 - slot: 1164899 (skipped 1164899) - head: 0 0xfb9b…de43 - finalized: 0x0000…0000:0
-Nov-29 16:00:06.003[]                 info: Searching peers - peers: 0 - slot: 1164900 (skipped 1164900) - head: 0 0xfb9b…de43 - finalized: 0x0000…0000:0
-Nov-29 16:00:18.003[]                 info: Searching peers - peers: 0 - slot: 1164901 (skipped 1164901) - head: 0 0xfb9b…de43 - finalized: 0x0000…0000:0
-Nov-29 16:00:30.002[]                 info: Syncing - 1.4 days left - 9.47 slots/s - slot: 1164902 (skipped 1164423) - head: 479 0x72b4…df6b - finalized: 0xfc3e…bbb0:13 - peers: 3
-Nov-29 16:00:42.001[]                 info: Syncing - 13 hours left - 25.3 slots/s - slot: 1164903 (skipped 1163304) - head: 1599 0x5692…f542 - finalized: 0xc72e…122e:48 - peers: 3
-Nov-29 16:00:54.001[]                 info: Syncing - 8.3 hours left - 38.7 slots/s - slot: 1164904 (skipped 1162153) - head: 2751 0xaac6…3aa6 - finalized: 0xbfeb…a990:83 - peers: 3
+pr-20 15:12:45.274[]                 info: Lodestar network=mainnet, version=v1.7.2, commit=
+Apr-20 15:12:45.327[]                 info: Connected to LevelDB database path=/data/mt1/chain-db
+Apr-20 15:12:57.747[]                 info: Initializing beacon from a valid db state slot=6264480, epoch=195765, stateRoot=0x8133cd4d0be59c3e94405f902fe0ad68ffaa5013b525dddb6285b91ad79716f6, isWithinWeakSubjectivityPeriod=true
+Apr-20 15:13:18.077[network]          info: PeerId 16Uiu2HAmDsGet67va6VCnaW2Tu1Ae2yujiDMnmURMMWNvssER7ZQ, Multiaddrs /ip4/127.0.0.1/tcp/9000/p2p/16Uiu2HAmDsGet67va6VCnaW2Tu1Ae2yujiDMnmURMMWNvssER7ZQ,/ip4/10.244.0.199/tcp/9000/p2p/16Uiu2HAmDsGet67va6VCnaW2Tu1Ae2yujiDMnmURMMWNvssER7ZQ
+Apr-20 15:13:18.270[rest]             info: Started REST API server address=http://127.0.0.1:9596
+Apr-20 15:13:18.271[]                 warn: Low peer count peers=0
+Apr-20 15:13:18.280[]                 info: Searching peers - peers: 0 - slot: 6264964 - head: (slot - 484) 0x7ee6…2a15 - exec-block: syncing(17088043 0x9442…) - finalized: 0xe359…4d7e:195763
+Apr-20 15:13:23.009[chain]            info: Validated transition configuration with execution client terminalTotalDifficulty=0xc70d808a128d7380000, terminalBlockHash=0x0000000000000000000000000000000000000000000000000000000000000000, terminalBlockNumber=0x0
+Apr-20 15:13:29.287[]                 info: Syncing - ? left - 0.00 slots/s - slot: 6264965 - head: (slot - 485) 0x7ee6…2a15 - exec-block: syncing(17088043 0x9442…) - finalized: 0xe359…4d7e:195763 - peers: 1
+Apr-20 15:14:41.003[]                 info: Syncing - 22 seconds left - 4.92 slots/s - slot: 6264971 - head: (slot - 108) 0xd15f…b605 - exec-block: valid(17088414 0x3dba…) - finalized: 0x70fd…5157:195775 - peers: 4
+Apr-20 15:14:53.001[]                 info: Syncing - 9 seconds left - 5.00 slots/s - slot: 6264972 - head: (slot - 45) 0x44e4…20a4 - exec-block: valid(17088475 0xca61…) - finalized: 0x9cbd…ba83:195776 - peers: 8
+Apr-20 15:15:01.443[network]          info: Subscribed gossip core topics
+Apr-20 15:15:01.446[sync]             info: Subscribed gossip core topics
+Apr-20 15:15:05.000[]                 info: Synced - slot: 6264973 - head: 0x90ea…c655 - exec-block: valid(17088521 0xca9b…) - finalized: 0x6981…682f:195778 - peers: 6
 ```
 
 <!-- prettier-ignore-start -->
@@ -117,3 +119,48 @@ In case you really trust `checkpointSyncUrl` then you may skip providing `wssChe
     Please use this option very carefully (and at your own risk), a malicious server URL can put you on the wrong chain with a danger of you losing your funds by social engineering.
 If possible, validate your `wssCheckpoint` from multiple places (e.g. different client distributions) or from other trusted sources. This will highly reduce the risk of starting off on a malicious chain.
 <!-- prettier-ignore-end -->
+
+### Guide to the sync logs
+
+Lodestar beacon sync log aims to provide information of utmost importance  about your node and yet be suucint at the same time. You may see the sync logs in the following format:
+
+`[Sync status] - [ Slot info ] - [Head info] - [Exec block info] - [Finalized info] - [Peers info]`
+
+See the following example of different kinds of sync log:
+```
+Apr-20 15:24:08.034[]                 info: Searching peers - peers: 0 - slot: 6265018 - head: 6264018 0xed93…7b0a - exec-block: syncing(17088476 0x9649…) - finalized: 0xbf30…7e7c:195777
+Apr-20 15:24:17.000[]                 info: Searching peers - peers: 0 - slot: 6265019 - head: 6264018 0xed93…7b0a - exec-block: syncing(17088476 0x9649…) - finalized: 0xbf30…7e7c:195777
+
+Apr-20 15:13:41.298[]                 info: Syncing - 2.5 minutes left - 2.78 slots/s - slot: 6264966 - head: 6262966 0x5cec…f5b8 - exec-block: valid(17088105 0x6f74…) - finalized: 0x5cc0…3874:195764 - peers: 1
+Apr-20 15:13:41.298[]                 info: Syncing - 2 minutes left - 2.78 slots/s - slot: 6264967 - head: 6263965 0x5cec…f5b8 - exec-block: valid(17088105 0x6f74…) - finalized: 0x5cc0…3874:195764 - peers: 1
+
+Apr-20 15:13:53.151[]                 info: Syncing - 1.6 minutes left - 3.82 slots/s - slot: 6264967 - head: (slot -360) 0xe0cf…9f3c - exec-block: valid(17088167 0x2d6a…) - finalized: 0x8f3f…2f81:195766 - peers: 5
+Apr-20 15:14:05.425[]                 info: Syncing - 1.1 minutes left - 4.33 slots/s - slot: 6264968 - head: (slot -297) 0x3655…1658 - exec-block: valid(17088231 0xdafd…) - finalized: 0x9475…425a:195769 - peers: 2
+Apr-20 15:14:53.001[]                 info: Syncing - 9 seconds left - 5.00 slots/s - slot: 6264972 - head: (slot -45) 0x44e4…20a4 - exec-block: valid(17088475 0xca61…) - finalized: 0x9cbd…ba83:195776 - peers: 8
+
+Apr-20 15:15:01.443[network]          info: Subscribed gossip core topics
+Apr-20 15:15:01.446[sync]             info: Subscribed gossip core topics
+Apr-20 15:15:05.000[]                 info: Synced - slot: 6264973 - head: 0x90ea…c655 - exec-block: valid(17088521 0xca9b…) - finalized: 0x6981…682f:195778 - peers: 6
+Apr-20 15:15:17.003[]                 info: Synced - slot: 6264974 - head: 0x4f7e…0e3a - exec-block: valid(17088522 0x08b1…) - finalized: 0x6981…682f:195778 - peers: 6
+
+Apr-20 15:15:41.001[]                 info: Synced - slot: 6264976 - head: (slot -1) 0x17c6…71a7 - exec-block: valid(17088524 0x5bc1…) - finalized: 0x6981…682f:195778 - peers: 8
+Apr-20 15:15:53.001[]                 info: Synced - slot: 6264977 - head: (slot -2) 0x17c6…71a7 - exec-block: valid(17088524 0x5bc1…) - finalized: 0x6981…682f:195778 - peers: 8
+
+Apr-20 15:16:05.000[]                 info: Synced - slot: 6264978 - head: 0xc9fd…28c5 - exec-block: valid(17088526 0xb5bf…) - finalized: 0x6981…682f:195778 - peers: 8
+Apr-20 15:16:17.017[]                 info: Synced - slot: 6264979 - head: 0xde91…d4cb - exec-block: valid(17088527 0xa488…) - finalized: 0x6981…682f:195778 - peers: 7
+
+```
+
+1. Sync status: Takes three values : `Synced` or `Syncing` (along with sync speed info) or `Searching` if node is is still looking for viable peers from where it can download blocks.
+
+2. Slot (clock) info: What is the current ongoing slot as per the chain genesis
+
+3. Head info: It specifies where the local chain head hash is. In case its far behind the Slot (clock) then it independntly shows the head slot else it show how far behind from the Slot it is if difference < 1000.
+
+4. Exec block info: It provides the execution information about the head whether its confirmed `valid` or EL is still `syncing` to it, as well as its number and a short hash to easy identification.
+
+5. Finalized info: What is the current local `finalized` checkpoint in the format of `[checkpoint root]:[checkpoint epoch]`, for e.g.: `0xd7ba…8386:189636`
+
+6. Peer info: Current total number of outbound or inbound peers, for e.g.: `peers: 27`
+
+For more insight into lodestar beacon functioning, you may setup lodestar metrics and use prepared grafana dashboards that you may find in the repo.

packages/api/src/beacon/routes/debug.ts

@@ -29,6 +29,7 @@ const stringType = new StringType();
 const protoNodeSszType = new ContainerType(
   {
     executionPayloadBlockHash: stringType,
+    executionPayloadNumber: ssz.UintNum64,
     executionStatus: stringType,
     slot: ssz.Slot,
     blockRoot: stringType,

packages/api/test/unit/beacon/testData/debug.ts

@@ -21,6 +21,7 @@ export const testData: GenericServerTestCases<Api> = {
       data: [
         {
           executionPayloadBlockHash: rootHex,
+          executionPayloadNumber: 1,
           executionStatus: "Valid",
           slot: 1,
           blockRoot: rootHex,

packages/beacon-node/src/api/impl/debug/index.ts

@@ -29,6 +29,8 @@ export function getDebugApi({
 
     async getProtoArrayNodes() {
       const nodes = chain.forkChoice.getAllNodes().map((node) => ({
+        // if node has executionPayloadNumber, it will overwrite the below default
+        executionPayloadNumber: 0,
         ...node,
         executionPayloadBlockHash: node.executionPayloadBlockHash ?? "",
         parent: String(node.parent),

packages/beacon-node/src/api/impl/validator/index.ts

@@ -181,7 +181,7 @@ export function getValidatorApi({
 
     if (protoBeaconBlock.executionStatus === ExecutionStatus.Syncing)
       throw new NodeIsSyncing(
-        `Block's execution payload not yet validated, executionPayloadBlockHash=${protoBeaconBlock.executionPayloadBlockHash}`
+        `Block's execution payload not yet validated, executionPayloadBlockHash=${protoBeaconBlock.executionPayloadBlockHash} number=${protoBeaconBlock.executionPayloadNumber}`
       );
   }
 

packages/beacon-node/src/chain/forkChoice/index.ts

@@ -81,6 +81,7 @@ export function initializeForkChoice(
         ...(isExecutionStateType(state) && isMergeTransitionComplete(state)
           ? {
               executionPayloadBlockHash: toHexString(state.latestExecutionPayloadHeader.blockHash),
+              executionPayloadNumber: state.latestExecutionPayloadHeader.blockNumber,
               executionStatus: blockHeader.slot === GENESIS_SLOT ? ExecutionStatus.Valid : ExecutionStatus.Syncing,
             }
           : {executionPayloadBlockHash: null, executionStatus: ExecutionStatus.PreMerge}),

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

@@ -1,8 +1,8 @@
 import {BeaconConfig} from "@lodestar/config";
 import {Epoch} from "@lodestar/types";
 import {CachedBeaconStateAllForks} from "@lodestar/state-transition";
-import {ProtoBlock} from "@lodestar/fork-choice";
-import {ErrorAborted, Logger, sleep, prettyBytes} from "@lodestar/utils";
+import {ProtoBlock, ExecutionStatus} from "@lodestar/fork-choice";
+import {ErrorAborted, Logger, sleep, prettyBytes, prettyBytesShort} from "@lodestar/utils";
 import {EPOCHS_PER_SYNC_COMMITTEE_PERIOD, SLOTS_PER_EPOCH} from "@lodestar/params";
 import {computeEpochAtSlot, isExecutionCachedStateType, isMergeTransitionComplete} from "@lodestar/state-transition";
 import {IBeaconChain} from "../chain/index.js";
@@ -59,12 +59,17 @@ export async function runNodeNotifier(modules: NodeNotifierModules): Promise<voi
       headSlotTimeSeries.addPoint(headSlot, Math.floor(Date.now() / 1000));
 
       const peersRow = `peers: ${connectedPeerCount}`;
-      const finalizedCheckpointRow = `finalized: ${prettyBytes(finalizedRoot)}:${finalizedEpoch}`;
-      const headRow = `head: ${headInfo.slot} ${prettyBytes(headInfo.blockRoot)}`;
+      const clockSlotRow = `slot: ${clockSlot}`;
 
       // Give info about empty slots if head < clock
       const skippedSlots = clockSlot - headInfo.slot;
-      const clockSlotRow = `slot: ${clockSlot}` + (skippedSlots > 0 ? ` (skipped ${skippedSlots})` : "");
+      // headDiffInfo to have space suffix if its a non empty string
+      const headDiffInfo =
+        skippedSlots > 1 ? (skippedSlots > 1000 ? `${headInfo.slot} ` : `(slot -${skippedSlots}) `) : "";
+      const headRow = `head: ${headDiffInfo}${prettyBytes(headInfo.blockRoot)}`;
+
+      const executionInfo = getHeadExecutionInfo(config, clockEpoch, headState, headInfo);
+      const finalizedCheckpointRow = `finalized: ${prettyBytes(finalizedRoot)}:${finalizedEpoch}`;
 
       // Log in TD progress in separate line to not clutter regular status update.
       // This line will only exist between BELLATRIX_FORK_EPOCH and TTD, a window of some days / weeks max.
@@ -81,8 +86,6 @@ export async function runNodeNotifier(modules: NodeNotifierModules): Promise<voi
         logger.info(`TTD in ${timeLeft} current TD ${tdProgress.td} / ${tdProgress.ttd}`);
       }
 
-      const executionInfo = getExecutionInfo(config, clockEpoch, headState, headInfo);
-
       let nodeState: string[];
       switch (sync.state) {
         case SyncState.SyncingFinalized:
@@ -146,7 +149,7 @@ function timeToNextHalfSlot(config: BeaconConfig, chain: IBeaconChain): number {
   return msToNextSlot > msPerSlot / 2 ? msToNextSlot - msPerSlot / 2 : msToNextSlot + msPerSlot / 2;
 }
 
-function getExecutionInfo(
+function getHeadExecutionInfo(
   config: BeaconConfig,
   clockEpoch: Epoch,
   headState: CachedBeaconStateAllForks,
@@ -160,9 +163,17 @@ function getExecutionInfo(
     // Add execution status to notifier only if head is on/post bellatrix
     if (isExecutionCachedStateType(headState)) {
       if (isMergeTransitionComplete(headState)) {
-        return [`execution: ${executionStatusStr}(${prettyBytes(headInfo.executionPayloadBlockHash ?? "empty")})`];
+        const executionPayloadHashInfo =
+          headInfo.executionStatus !== ExecutionStatus.PreMerge ? headInfo.executionPayloadBlockHash : "empty";
+        const executionPayloadNumberInfo =
+          headInfo.executionStatus !== ExecutionStatus.PreMerge ? headInfo.executionPayloadNumber : NaN;
+        return [
+          `exec-block: ${executionStatusStr}(${executionPayloadNumberInfo} ${prettyBytesShort(
+            executionPayloadHashInfo
+          )})`,
+        ];
       } else {
-        return [`execution: ${executionStatusStr}`];
+        return [`exec-block: ${executionStatusStr}`];
       }
     } else {
       return [];

packages/fork-choice/src/forkChoice/forkChoice.ts

@@ -450,6 +450,7 @@ export class ForkChoice implements IForkChoice {
       ...(isExecutionBlockBodyType(block.body) && isExecutionStateType(state) && isExecutionEnabled(state, block)
         ? {
             executionPayloadBlockHash: toHexString(block.body.executionPayload.blockHash),
+            executionPayloadNumber: block.body.executionPayload.blockNumber,
             executionStatus: this.getPostMergeExecStatus(executionStatus),
           }
         : {executionPayloadBlockHash: null, executionStatus: this.getPreMergeExecStatus(executionStatus)}),

packages/fork-choice/src/protoArray/interface.ts

@@ -1,4 +1,4 @@
-import {Epoch, Slot, RootHex} from "@lodestar/types";
+import {Epoch, Slot, RootHex, UintNum64} from "@lodestar/types";
 
 // RootHex is a root as a hex string
 // Used for lightweight and easy comparison
@@ -34,7 +34,11 @@ export type LVHExecResponse = LVHValidResponse | LVHInvalidResponse;
 export type MaybeValidExecutionStatus = Exclude<ExecutionStatus, ExecutionStatus.Invalid>;
 
 export type BlockExecution =
-  | {executionPayloadBlockHash: RootHex; executionStatus: Exclude<ExecutionStatus, ExecutionStatus.PreMerge>}
+  | {
+      executionPayloadBlockHash: RootHex;
+      executionPayloadNumber: UintNum64;
+      executionStatus: Exclude<ExecutionStatus, ExecutionStatus.PreMerge>;
+    }
   | {executionPayloadBlockHash: null; executionStatus: ExecutionStatus.PreMerge};
 /**
  * A block that is to be applied to the fork choice

packages/fork-choice/test/unit/protoArray/executionStatusUpdates.test.ts

@@ -82,7 +82,11 @@ function setupForkChoice(): ProtoArray {
     const executionData = (
       block.executionStatus === ExecutionStatus.PreMerge
         ? {executionPayloadBlockHash: null, executionStatus: ExecutionStatus.PreMerge}
-        : {executionPayloadBlockHash: block.root, executionStatus: block.executionStatus}
+        : {
+            executionPayloadBlockHash: block.root,
+            executionPayloadNumber: block.slot,
+            executionStatus: block.executionStatus,
+          }
     ) as BlockExecution;
     fc.onBlock(
       {

packages/utils/src/format.ts

@@ -8,3 +8,12 @@ export function prettyBytes(root: Uint8Array | string): string {
   const str = typeof root === "string" ? root : toHexString(root);
   return `${str.slice(0, 6)}…${str.slice(-4)}`;
 }
+
+/**
+ * Format bytes as `0x1234…`
+ * Paired with block numbers or slots, it can still act as a decent identify-able format
+ */
+export function prettyBytesShort(root: Uint8Array | string): string {
+  const str = typeof root === "string" ? root : toHexString(root);
+  return `${str.slice(0, 6)}…`;
+}