Single lookup improvements (#5488)

* Fix unexpected `UnrequestedBlobId` and `ExtraBlocksReturned` errors due to race conditions.

* Continue chain segment processing and skip any blocks that are already known, rather than returning an error.

* more de-dup checking

* ensure we don't reset `requested_ids` during rpc download

* better fix

* Merge branch 'unstable' of https://github.com/sigp/lighthouse into more-dup-lookup-fixes

* remove chain hash check

* Merge branch 'fix-block-lookup-race' of https://github.com/jimmygchen/lighthouse into sean-test-lookups

* remove block check

* add back tests

* Log and CI fixes

* undue extra check

* Merge branch 'sean-test-lookups' of https://github.com/realbigsean/lighthouse into sean-test-lookups

* log improvements

* Improve logging

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

@@ -152,6 +152,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
             if let Some(components) = child_components {
                 lookup.add_child_components(components);
             }
+            debug!(self.log, "Already searching for block"; "block_root" => ?block_root);
             return;
         }
 
@@ -162,6 +163,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
 
             // If the block was already downloaded, or is being downloaded in this moment, do not
             // request it.
+            debug!(self.log, "Already searching for block in a parent lookup request"; "block_root" => ?block_root);
             return;
         }
 
@@ -171,6 +173,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
             .any(|(hashes, _last_parent_request)| hashes.contains(&block_root))
         {
             // we are already processing this block, ignore it.
+            debug!(self.log, "Already processing block in a parent request"; "block_root" => ?block_root);
             return;
         }
 
@@ -221,15 +224,23 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
         }) {
             parent_lookup.add_peer(peer_id);
             // we are already searching for this block, ignore it
+            debug!(self.log, "Already searching for parent block";
+                "block_root" => ?block_root, "parent_root" => ?parent_root);
             return;
         }
 
         if self
             .processing_parent_lookups
-            .values()
-            .any(|(hashes, _peers)| hashes.contains(&block_root) || hashes.contains(&parent_root))
+            .iter()
+            .any(|(chain_hash, (hashes, _peers))| {
+                chain_hash == &block_root
+                    || hashes.contains(&block_root)
+                    || hashes.contains(&parent_root)
+            })
         {
             // we are already processing this block, ignore it.
+            debug!(self.log, "Already processing parent block";
+                "block_root" => ?block_root, "parent_root" => ?parent_root);
             return;
         }
         let parent_lookup = ParentLookup::new(
@@ -298,6 +309,12 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
         };
 
         let expected_block_root = lookup.block_root();
+        debug!(self.log,
+            "Peer returned block for single lookup";
+            "peer_id" => %peer_id ,
+            "id" => ?id,
+            "block_root" => ?expected_block_root,
+        );
 
         match self.single_lookup_response_inner::<R>(peer_id, response, seen_timestamp, cx, lookup)
         {
@@ -478,6 +495,13 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
             return;
         };
 
+        debug!(self.log,
+            "Peer returned block for parent lookup";
+            "peer_id" => %peer_id ,
+            "id" => ?id,
+            "block_root" => ?parent_lookup.current_parent_request.block_request_state.requested_block_root,
+        );
+
         match self.parent_lookup_response_inner::<R>(
             peer_id,
             response,
@@ -540,7 +564,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
             | ParentVerifyError::NoBlockReturned
             | ParentVerifyError::NotEnoughBlobsReturned
             | ParentVerifyError::ExtraBlocksReturned
-            | ParentVerifyError::UnrequestedBlobId
+            | ParentVerifyError::UnrequestedBlobId(_)
             | ParentVerifyError::ExtraBlobsReturned
             | ParentVerifyError::InvalidIndex(_) => {
                 let e = e.into();
@@ -728,6 +752,8 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
             "Block component processed for lookup";
             "response_type" => ?R::response_type(),
             "block_root" => ?root,
+            "result" => ?result,
+            "id" => target_id,
         );
 
         match result {
@@ -901,7 +927,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
                     debug!(self.log, "Parent block processing succeeded"; &parent_lookup, "block_root" => ?block_root)
                 }
                 AvailabilityProcessingStatus::MissingComponents(_, block_root) => {
-                    debug!(self.log, "Parent missing parts, triggering single block lookup "; &parent_lookup,"block_root" => ?block_root)
+                    debug!(self.log, "Parent missing parts, triggering single block lookup"; &parent_lookup,"block_root" => ?block_root)
                 }
             },
             BlockProcessingResult::Err(e) => {
@@ -1223,7 +1249,7 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
     ) -> Result<(), LookupRequestError> {
         match cx.beacon_processor_if_enabled() {
             Some(beacon_processor) => {
-                trace!(self.log, "Sending block for processing"; "block" => ?block_root, "process" => ?process_type);
+                debug!(self.log, "Sending block for processing"; "block" => ?block_root, "process" => ?process_type);
                 if let Err(e) = beacon_processor.send_rpc_beacon_block(
                     block_root,
                     block,