Add more info about why lookup is in AwaitingDownload (#5838)

* Add more info about why lookup is in AwaitingDownload

* Review comments

* Merge branch 'unstable' into awaiting-download-context

* Merge branch 'unstable' of https://github.com/sigp/lighthouse into awaiting-download-context

* cargo fmt

beacon_node/network/src/sync/block_lookups/single_block_lookup.rs

@@ -211,7 +211,12 @@ impl<T: BeaconChainTypes> SingleBlockLookup<T> {
                     request.get_state_mut().on_completed_request()?
                 }
                 // Sync will receive a future event to make progress on the request, do nothing now
-                LookupRequestResult::Pending => return Ok(()),
+                LookupRequestResult::Pending(reason) => {
+                    request
+                        .get_state_mut()
+                        .update_awaiting_download_status(reason);
+                    return Ok(());
+                }
             }
 
         // Otherwise, attempt to progress awaiting processing
@@ -304,7 +309,7 @@ pub struct DownloadResult<T: Clone> {
 
 #[derive(PartialEq, Eq, IntoStaticStr)]
 pub enum State<T: Clone> {
-    AwaitingDownload,
+    AwaitingDownload(&'static str),
     Downloading(ReqId),
     AwaitingProcess(DownloadResult<T>),
     /// Request is processing, sent by lookup sync
@@ -328,7 +333,7 @@ pub struct SingleLookupRequestState<T: Clone> {
 impl<T: Clone> SingleLookupRequestState<T> {
     pub fn new() -> Self {
         Self {
-            state: State::AwaitingDownload,
+            state: State::AwaitingDownload("not started"),
             failed_processing: 0,
             failed_downloading: 0,
         }
@@ -336,7 +341,7 @@ impl<T: Clone> SingleLookupRequestState<T> {
 
     pub fn is_awaiting_download(&self) -> bool {
         match self.state {
-            State::AwaitingDownload => true,
+            State::AwaitingDownload { .. } => true,
             State::Downloading { .. }
             | State::AwaitingProcess { .. }
             | State::Processing { .. }
@@ -346,7 +351,7 @@ impl<T: Clone> SingleLookupRequestState<T> {
 
     pub fn is_processed(&self) -> bool {
         match self.state {
-            State::AwaitingDownload
+            State::AwaitingDownload { .. }
             | State::Downloading { .. }
             | State::AwaitingProcess { .. }
             | State::Processing { .. } => false,
@@ -374,7 +379,7 @@ impl<T: Clone> SingleLookupRequestState<T> {
 
     pub fn peek_downloaded_data(&self) -> Option<&T> {
         match &self.state {
-            State::AwaitingDownload => None,
+            State::AwaitingDownload { .. } => None,
             State::Downloading { .. } => None,
             State::AwaitingProcess(result) => Some(&result.value),
             State::Processing(result) => Some(&result.value),
@@ -385,7 +390,7 @@ impl<T: Clone> SingleLookupRequestState<T> {
     /// Switch to `AwaitingProcessing` if the request is in `AwaitingDownload` state, otherwise
     /// ignore.
     pub fn insert_verified_response(&mut self, result: DownloadResult<T>) -> bool {
-        if let State::AwaitingDownload = &self.state {
+        if let State::AwaitingDownload { .. } = &self.state {
             self.state = State::AwaitingProcess(result);
             true
         } else {
@@ -393,10 +398,18 @@ impl<T: Clone> SingleLookupRequestState<T> {
         }
     }
 
+    /// Append metadata on why this request is in AwaitingDownload status. Very helpful to debug
+    /// stuck lookups. Not fallible as it's purely informational.
+    pub fn update_awaiting_download_status(&mut self, new_status: &'static str) {
+        if let State::AwaitingDownload(status) = &mut self.state {
+            *status = new_status
+        }
+    }
+
     /// Switch to `Downloading` if the request is in `AwaitingDownload` state, otherwise returns None.
     pub fn on_download_start(&mut self, req_id: ReqId) -> Result<(), LookupRequestError> {
         match &self.state {
-            State::AwaitingDownload => {
+            State::AwaitingDownload { .. } => {
                 self.state = State::Downloading(req_id);
                 Ok(())
             }
@@ -418,7 +431,7 @@ impl<T: Clone> SingleLookupRequestState<T> {
                     });
                 }
                 self.failed_downloading = self.failed_downloading.saturating_add(1);
-                self.state = State::AwaitingDownload;
+                self.state = State::AwaitingDownload("not started");
                 Ok(())
             }
             other => Err(LookupRequestError::BadState(format!(
@@ -482,7 +495,7 @@ impl<T: Clone> SingleLookupRequestState<T> {
             State::Processing(result) => {
                 let peer_id = result.peer_id;
                 self.failed_processing = self.failed_processing.saturating_add(1);
-                self.state = State::AwaitingDownload;
+                self.state = State::AwaitingDownload("not started");
                 Ok(peer_id)
             }
             other => Err(LookupRequestError::BadState(format!(
@@ -506,7 +519,7 @@ impl<T: Clone> SingleLookupRequestState<T> {
     /// Mark a request as complete without any download or processing
     pub fn on_completed_request(&mut self) -> Result<(), LookupRequestError> {
         match &self.state {
-            State::AwaitingDownload => {
+            State::AwaitingDownload { .. } => {
                 self.state = State::Processed;
                 Ok(())
             }
@@ -538,7 +551,7 @@ impl<T: Clone> std::fmt::Display for State<T> {
 impl<T: Clone> std::fmt::Debug for State<T> {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
         match self {
-            Self::AwaitingDownload { .. } => write!(f, "AwaitingDownload"),
+            Self::AwaitingDownload(status) => write!(f, "AwaitingDownload({:?})", status),
             Self::Downloading(req_id) => write!(f, "Downloading({:?})", req_id),
             Self::AwaitingProcess(d) => write!(f, "AwaitingProcess({:?})", d.peer_id),
             Self::Processing(d) => write!(f, "Processing({:?})", d.peer_id),

beacon_node/network/src/sync/network_context.rs

@@ -105,7 +105,7 @@ pub enum LookupRequestResult {
     /// that makes progress on the request. For example: request is processing from a different
     /// source (i.e. block received from gossip) and sync MUST receive an event with that processing
     /// result.
-    Pending,
+    Pending(&'static str),
 }
 
 /// Wraps a Network channel to employ various RPC related network functionality for the Sync manager. This includes management of a global RPC request Id.
@@ -342,7 +342,9 @@ impl<T: BeaconChainTypes> SyncNetworkContext<T> {
             BlockProcessStatus::Unknown => {}
             // Block is known are currently processing, expect a future event with the result of
             // processing.
-            BlockProcessStatus::NotValidated { .. } => return Ok(LookupRequestResult::Pending),
+            BlockProcessStatus::NotValidated { .. } => {
+                return Ok(LookupRequestResult::Pending("block in processing cache"))
+            }
             // Block is fully validated. If it's not yet imported it's waiting for missing block
             // components. Consider this request completed and do nothing.
             BlockProcessStatus::ExecutionValidated { .. } => {
@@ -406,7 +408,7 @@ impl<T: BeaconChainTypes> SyncNetworkContext<T> {
             // latter handle the case where if the peer sent no blobs, penalize.
             // - if `downloaded_block_expected_blobs` is Some = block is downloading or processing.
             // - if `num_expected_blobs` returns Some = block is processed.
-            return Ok(LookupRequestResult::Pending);
+            return Ok(LookupRequestResult::Pending("waiting for block download"));
         };
 
         let imported_blob_indexes = self