From 17d9a620cf5e583206207ef9186fbeabd7f36eb7 Mon Sep 17 00:00:00 2001
From: Paul Hauner <paul@paulhauner.com>
Date: Tue, 28 Feb 2023 02:20:53 +0000
Subject: [PATCH] Add more logs in the BN HTTP API during block production
 (#4025)

## Issue Addressed

NA

## Proposed Changes

Adds two new `DEBG` logs to the HTTP API:

1. As soon as we are requested to produce a block.
2. As soon as a signed block is received.

In #3858 we added some very helpful logs to the VC so we could see when things are happening with block proposals in the VC. After doing some more debugging, I found that I can tell when the VC is sending a block but I *can't* tell the time that the BN receives it (I can only get the time after the BN has started doing some work with the block). Knowing when the VC published and as soon as the BN receives is useful for determining the delays introduced by network latency (and some other things like JSON decoding, etc).

## Additional Info

NA
---
 beacon_node/http_api/src/lib.rs            | 10 +++++++++-
 beacon_node/http_api/src/publish_blocks.rs |  8 +++++++-
 2 files changed, 16 insertions(+), 2 deletions(-)

diff --git a/beacon_node/http_api/src/lib.rs b/beacon_node/http_api/src/lib.rs
index a0975a5c73c..7d9c8829f59 100644
--- a/beacon_node/http_api/src/lib.rs
+++ b/beacon_node/http_api/src/lib.rs
@@ -2380,11 +2380,19 @@ pub fn serve<T: BeaconChainTypes>(
         .and(not_while_syncing_filter.clone())
         .and(warp::query::<api_types::ValidatorBlocksQuery>())
         .and(chain_filter.clone())
+        .and(log_filter.clone())
         .and_then(
             |endpoint_version: EndpointVersion,
              slot: Slot,
              query: api_types::ValidatorBlocksQuery,
-             chain: Arc<BeaconChain<T>>| async move {
+             chain: Arc<BeaconChain<T>>,
+             log: Logger| async move {
+                debug!(
+                    log,
+                    "Block production request from HTTP API";
+                    "slot" => slot
+                );
+
                 let randao_reveal = query.randao_reveal.decompress().map_err(|e| {
                     warp_utils::reject::custom_bad_request(format!(
                         "randao reveal is not a valid BLS signature: {:?}",
diff --git a/beacon_node/http_api/src/publish_blocks.rs b/beacon_node/http_api/src/publish_blocks.rs
index 83ab8ceee61..b38e4166862 100644
--- a/beacon_node/http_api/src/publish_blocks.rs
+++ b/beacon_node/http_api/src/publish_blocks.rs
@@ -5,7 +5,7 @@ use beacon_chain::{
 };
 use lighthouse_network::{PubsubMessage, SignedBeaconBlockAndBlobsSidecar};
 use network::NetworkMessage;
-use slog::{error, info, warn, Logger};
+use slog::{debug, error, info, warn, Logger};
 use slot_clock::SlotClock;
 use std::sync::Arc;
 use tokio::sync::mpsc::UnboundedSender;
@@ -27,6 +27,12 @@ pub async fn publish_block<T: BeaconChainTypes>(
 ) -> Result<(), Rejection> {
     let seen_timestamp = timestamp_now();
 
+    debug!(
+        log,
+        "Signed block published to HTTP API";
+        "slot" => block.slot()
+    );
+
     // Send the block, regardless of whether or not it is valid. The API
     // specification is very clear that this is the desired behaviour.