Merge pull request #5270 from stacks-network/fix/5267

Fix/5267

Author: jcnelson

stackslib/src/net/download/nakamoto/download_state_machine.rs

@@ -384,7 +384,7 @@ impl NakamotoDownloadStateMachine {
             &new_wanted_tenures
         );
         self.wanted_tenures.append(&mut new_wanted_tenures);
-        debug!("extended wanted_tenures is now {:?}", &self.wanted_tenures);
+        test_debug!("extended wanted_tenures is now {:?}", &self.wanted_tenures);
 
         Ok(())
     }
@@ -983,9 +983,9 @@ impl NakamotoDownloadStateMachine {
             prev_schedule
         };
 
-        debug!("new schedule: {:?}", schedule);
-        debug!("new available: {:?}", &available);
-        debug!("new tenure_block_ids: {:?}", &tenure_block_ids);
+        test_debug!("new schedule: {:?}", schedule);
+        test_debug!("new available: {:?}", &available);
+        test_debug!("new tenure_block_ids: {:?}", &tenure_block_ids);
 
         self.tenure_download_schedule = schedule;
         self.tenure_block_ids = tenure_block_ids;
@@ -1023,7 +1023,7 @@ impl NakamotoDownloadStateMachine {
             .map(|wt| (wt.burn_height, &wt.tenure_id_consensus_hash))
             .collect();
 
-        debug!("Check availability {:?}", available);
+        test_debug!("Check availability {:?}", available);
         let mut highest_available = Vec::with_capacity(2);
         for (_, ch) in tenure_block_heights.iter().rev() {
             let available_count = available

stackslib/src/net/download/nakamoto/tenure_downloader.rs

@@ -66,16 +66,18 @@ use crate::util_lib::db::{DBConn, Error as DBError};
 /// start and end block.  This includes all tenures except for the two most recent ones.
 #[derive(Debug, Clone, PartialEq)]
 pub enum NakamotoTenureDownloadState {
-    /// Getting the tenure-start block (the given StacksBlockId is it's block ID).
-    GetTenureStartBlock(StacksBlockId),
+    /// Getting the tenure-start block (the given StacksBlockId is it's block ID), as well as the
+    /// millisecond epoch timestamp at which the request began
+    GetTenureStartBlock(StacksBlockId, u128),
     /// Getting the tenure-end block.
-    ///
-    /// The field here is the block ID of the tenure end block.
-    GetTenureEndBlock(StacksBlockId),
+    /// The fields here are the block ID of the tenure end block, as well as the millisecond epoch
+    /// timestamp at which the request begahn
+    GetTenureEndBlock(StacksBlockId, u128),
     /// Receiving tenure blocks.
-    /// The field here is the hash of the _last_ block in the tenure that must be downloaded.  This
-    /// is because a tenure is fetched in order from highest block to lowest block.
-    GetTenureBlocks(StacksBlockId),
+    /// The fields here are the hash of the _last_ block in the tenure that must be downloaded, as well
+    /// as the millisecond epoch timestamp at which the request began.  The first field is needed
+    /// because a tenure is fetched in order from highest block to lowest block.
+    GetTenureBlocks(StacksBlockId, u128),
     /// We have gotten all the blocks for this tenure
     Done,
 }
@@ -166,7 +168,10 @@ impl NakamotoTenureDownloader {
             start_signer_keys,
             end_signer_keys,
             idle: false,
-            state: NakamotoTenureDownloadState::GetTenureStartBlock(tenure_start_block_id.clone()),
+            state: NakamotoTenureDownloadState::GetTenureStartBlock(
+                tenure_start_block_id.clone(),
+                get_epoch_time_ms(),
+            ),
             tenure_start_block: None,
             tenure_end_block: None,
             tenure_blocks: None,
@@ -187,7 +192,7 @@ impl NakamotoTenureDownloader {
         &mut self,
         tenure_start_block: NakamotoBlock,
     ) -> Result<(), NetError> {
-        let NakamotoTenureDownloadState::GetTenureStartBlock(_) = &self.state else {
+        let NakamotoTenureDownloadState::GetTenureStartBlock(..) = &self.state else {
             // not the right state for this
             warn!("Invalid state for this method";
                   "state" => %self.state);
@@ -234,8 +239,10 @@ impl NakamotoTenureDownloader {
             self.try_accept_tenure_end_block(&tenure_end_block)?;
         } else {
             // need to get tenure_end_block.
-            self.state =
-                NakamotoTenureDownloadState::GetTenureEndBlock(self.tenure_end_block_id.clone());
+            self.state = NakamotoTenureDownloadState::GetTenureEndBlock(
+                self.tenure_end_block_id.clone(),
+                get_epoch_time_ms(),
+            );
         }
         Ok(())
     }
@@ -252,7 +259,7 @@ impl NakamotoTenureDownloader {
     ) -> Result<(), NetError> {
         if !matches!(
             &self.state,
-            NakamotoTenureDownloadState::GetTenureEndBlock(_)
+            NakamotoTenureDownloadState::GetTenureEndBlock(..)
         ) {
             warn!("Invalid state for this method";
                   "state" => %self.state);
@@ -326,6 +333,7 @@ impl NakamotoTenureDownloader {
         self.tenure_end_block = Some(tenure_end_block.clone());
         self.state = NakamotoTenureDownloadState::GetTenureBlocks(
             tenure_end_block.header.parent_block_id.clone(),
+            get_epoch_time_ms(),
         );
         Ok(())
     }
@@ -361,7 +369,9 @@ impl NakamotoTenureDownloader {
         &mut self,
         mut tenure_blocks: Vec<NakamotoBlock>,
     ) -> Result<Option<Vec<NakamotoBlock>>, NetError> {
-        let NakamotoTenureDownloadState::GetTenureBlocks(block_cursor) = &self.state else {
+        let NakamotoTenureDownloadState::GetTenureBlocks(block_cursor, start_request_time) =
+            &self.state
+        else {
             warn!("Invalid state for this method";
                   "state" => %self.state);
             return Err(NetError::InvalidState);
@@ -473,7 +483,8 @@ impl NakamotoTenureDownloader {
                 &earliest_block.block_id(),
                 &next_block_id
             );
-            self.state = NakamotoTenureDownloadState::GetTenureBlocks(next_block_id);
+            self.state =
+                NakamotoTenureDownloadState::GetTenureBlocks(next_block_id, *start_request_time);
             return Ok(None);
         }
 
@@ -498,16 +509,28 @@ impl NakamotoTenureDownloader {
         peerhost: PeerHost,
     ) -> Result<Option<StacksHttpRequest>, ()> {
         let request = match self.state {
-            NakamotoTenureDownloadState::GetTenureStartBlock(start_block_id) => {
-                debug!("Request tenure-start block {}", &start_block_id);
+            NakamotoTenureDownloadState::GetTenureStartBlock(
+                start_block_id,
+                start_request_time,
+            ) => {
+                debug!(
+                    "Request tenure-start block {} at {}",
+                    &start_block_id, start_request_time
+                );
                 StacksHttpRequest::new_get_nakamoto_block(peerhost, start_block_id.clone())
             }
-            NakamotoTenureDownloadState::GetTenureEndBlock(end_block_id) => {
-                debug!("Request tenure-end block {}", &end_block_id);
+            NakamotoTenureDownloadState::GetTenureEndBlock(end_block_id, start_request_time) => {
+                debug!(
+                    "Request tenure-end block {} at {}",
+                    &end_block_id, start_request_time
+                );
                 StacksHttpRequest::new_get_nakamoto_block(peerhost, end_block_id.clone())
             }
-            NakamotoTenureDownloadState::GetTenureBlocks(end_block_id) => {
-                debug!("Downloading tenure ending at {}", &end_block_id);
+            NakamotoTenureDownloadState::GetTenureBlocks(end_block_id, start_request_time) => {
+                debug!(
+                    "Downloading tenure ending at {} at {}",
+                    &end_block_id, start_request_time
+                );
                 StacksHttpRequest::new_get_nakamoto_tenure(peerhost, end_block_id.clone(), None)
             }
             NakamotoTenureDownloadState::Done => {
@@ -570,10 +593,11 @@ impl NakamotoTenureDownloader {
         response: StacksHttpResponse,
     ) -> Result<Option<Vec<NakamotoBlock>>, NetError> {
         let handle_result = match self.state {
-            NakamotoTenureDownloadState::GetTenureStartBlock(_block_id) => {
+            NakamotoTenureDownloadState::GetTenureStartBlock(block_id, start_request_time) => {
                 debug!(
-                    "Got download response for tenure-start block {}",
-                    &_block_id
+                    "Got download response for tenure-start block {} in {}ms",
+                    &block_id,
+                    get_epoch_time_ms().saturating_sub(start_request_time)
                 );
                 let block = response.decode_nakamoto_block().map_err(|e| {
                     warn!("Failed to decode response for a Nakamoto block: {:?}", &e);
@@ -582,19 +606,24 @@ impl NakamotoTenureDownloader {
                 self.try_accept_tenure_start_block(block)?;
                 Ok(None)
             }
-            NakamotoTenureDownloadState::GetTenureEndBlock(_block_id) => {
-                debug!("Got download response to tenure-end block {}", &_block_id);
+            NakamotoTenureDownloadState::GetTenureEndBlock(block_id, start_request_time) => {
+                debug!(
+                    "Got download response to tenure-end block {} in {}ms",
+                    &block_id,
+                    get_epoch_time_ms().saturating_sub(start_request_time)
+                );
                 let block = response.decode_nakamoto_block().map_err(|e| {
                     warn!("Failed to decode response for a Nakamoto block: {:?}", &e);
                     e
                 })?;
                 self.try_accept_tenure_end_block(&block)?;
                 Ok(None)
             }
-            NakamotoTenureDownloadState::GetTenureBlocks(_end_block_id) => {
+            NakamotoTenureDownloadState::GetTenureBlocks(end_block_id, start_request_time) => {
                 debug!(
-                    "Got download response for tenure blocks ending at {}",
-                    &_end_block_id
+                    "Got download response for tenure blocks ending at {} in {}ms",
+                    &end_block_id,
+                    get_epoch_time_ms().saturating_sub(start_request_time)
                 );
                 let blocks = response.decode_nakamoto_tenure().map_err(|e| {
                     warn!("Failed to decode response for a Nakamoto tenure: {:?}", &e);

stackslib/src/net/download/nakamoto/tenure_downloader_set.rs

@@ -230,13 +230,11 @@ impl NakamotoTenureDownloaderSet {
             if !downloader.idle {
                 continue;
             }
-            if downloader.naddr != naddr {
-                continue;
-            }
             debug!(
                 "Assign peer {} to work on downloader for {} in state {}",
                 &naddr, &downloader.tenure_id_consensus_hash, &downloader.state
             );
+            downloader.naddr = naddr.clone();
             self.peers.insert(naddr, i);
             return true;
         }
@@ -308,8 +306,8 @@ impl NakamotoTenureDownloaderSet {
             };
             if &downloader.tenure_id_consensus_hash == tenure_id {
                 debug!(
-                    "Have downloader for tenure {} already (idle={}, state={})",
-                    tenure_id, downloader.idle, &downloader.state
+                    "Have downloader for tenure {} already (idle={}, state={}, naddr={})",
+                    tenure_id, downloader.idle, &downloader.state, &downloader.naddr
                 );
                 return true;
             }
@@ -328,7 +326,7 @@ impl NakamotoTenureDownloaderSet {
         count: usize,
         current_reward_cycles: &BTreeMap<u64, CurrentRewardSet>,
     ) {
-        debug!("make_tenure_downloaders";
+        test_debug!("make_tenure_downloaders";
                "schedule" => ?schedule,
                "available" => ?available,
                "tenure_block_ids" => ?tenure_block_ids,
@@ -463,7 +461,10 @@ impl NakamotoTenureDownloaderSet {
                 continue;
             };
             if downloader.is_done() {
-                debug!("Downloader for {} is done", &naddr);
+                debug!(
+                    "Downloader for {} on tenure {} is finished",
+                    &naddr, &downloader.tenure_id_consensus_hash
+                );
                 finished.push(naddr.clone());
                 finished_tenures.push(downloader.tenure_id_consensus_hash.clone());
                 continue;
@@ -534,6 +535,10 @@ impl NakamotoTenureDownloaderSet {
             );
             new_blocks.insert(downloader.tenure_id_consensus_hash.clone(), blocks);
             if downloader.is_done() {
+                debug!(
+                    "Downloader for {} on tenure {} is finished",
+                    &naddr, &downloader.tenure_id_consensus_hash
+                );
                 finished.push(naddr.clone());
                 finished_tenures.push(downloader.tenure_id_consensus_hash.clone());
                 continue;

stackslib/src/net/tests/download/nakamoto.rs

@@ -50,6 +50,17 @@ use crate::net::{Error as NetError, Hash160, NeighborAddress, SortitionDB};
 use crate::stacks_common::types::Address;
 use crate::util_lib::db::Error as DBError;
 
+impl NakamotoTenureDownloadState {
+    pub fn request_time(&self) -> Option<u128> {
+        match self {
+            Self::GetTenureStartBlock(_, ts) => Some(*ts),
+            Self::GetTenureEndBlock(_, ts) => Some(*ts),
+            Self::GetTenureBlocks(_, ts) => Some(*ts),
+            Self::Done => None,
+        }
+    }
+}
+
 impl NakamotoDownloadStateMachine {
     /// Find the list of wanted tenures for the given reward cycle.  The reward cycle must
     /// be complete already.  Used for testing.
@@ -240,7 +251,10 @@ fn test_nakamoto_tenure_downloader() {
     // must be first block
     assert_eq!(
         td.state,
-        NakamotoTenureDownloadState::GetTenureStartBlock(tenure_start_block.header.block_id())
+        NakamotoTenureDownloadState::GetTenureStartBlock(
+            tenure_start_block.header.block_id(),
+            td.state.request_time().unwrap()
+        )
     );
     assert!(td
         .try_accept_tenure_start_block(blocks.last().unwrap().clone())
@@ -254,7 +268,7 @@ fn test_nakamoto_tenure_downloader() {
         .try_accept_tenure_start_block(blocks.first().unwrap().clone())
         .is_ok());
 
-    let NakamotoTenureDownloadState::GetTenureEndBlock(block_id) = td.state else {
+    let NakamotoTenureDownloadState::GetTenureEndBlock(block_id, ..) = td.state else {
         panic!("wrong state");
     };
     assert_eq!(block_id, next_tenure_start_block.header.block_id());
@@ -274,7 +288,8 @@ fn test_nakamoto_tenure_downloader() {
     assert_eq!(
         td.state,
         NakamotoTenureDownloadState::GetTenureBlocks(
-            next_tenure_start_block.header.parent_block_id.clone()
+            next_tenure_start_block.header.parent_block_id.clone(),
+            td.state.request_time().unwrap(),
         )
     );
     assert_eq!(td.tenure_end_block, Some(next_tenure_start_block.clone()));
@@ -300,7 +315,10 @@ fn test_nakamoto_tenure_downloader() {
         // tail pointer moved
         assert_eq!(
             td.state,
-            NakamotoTenureDownloadState::GetTenureBlocks(block.header.parent_block_id.clone())
+            NakamotoTenureDownloadState::GetTenureBlocks(
+                block.header.parent_block_id.clone(),
+                td.state.request_time().unwrap()
+            )
         );
     }
 
@@ -572,7 +590,8 @@ fn test_nakamoto_unconfirmed_tenure_downloader() {
         assert_eq!(
             ntd.state,
             NakamotoTenureDownloadState::GetTenureStartBlock(
-                unconfirmed_wanted_tenure.winning_block_id.clone()
+                unconfirmed_wanted_tenure.winning_block_id.clone(),
+                ntd.state.request_time().unwrap()
             )
         );
     }
@@ -670,7 +689,8 @@ fn test_nakamoto_unconfirmed_tenure_downloader() {
         assert_eq!(
             ntd.state,
             NakamotoTenureDownloadState::GetTenureStartBlock(
-                unconfirmed_wanted_tenure.winning_block_id.clone()
+                unconfirmed_wanted_tenure.winning_block_id.clone(),
+                ntd.state.request_time().unwrap()
             )
         );
     }
@@ -770,7 +790,8 @@ fn test_nakamoto_unconfirmed_tenure_downloader() {
         assert_eq!(
             ntd.state,
             NakamotoTenureDownloadState::GetTenureStartBlock(
-                unconfirmed_wanted_tenure.winning_block_id.clone()
+                unconfirmed_wanted_tenure.winning_block_id.clone(),
+                ntd.state.request_time().unwrap()
             )
         );
     }
@@ -847,7 +868,8 @@ fn test_nakamoto_unconfirmed_tenure_downloader() {
         assert_eq!(
             ntd.state,
             NakamotoTenureDownloadState::GetTenureStartBlock(
-                unconfirmed_wanted_tenure.winning_block_id.clone()
+                unconfirmed_wanted_tenure.winning_block_id.clone(),
+                ntd.state.request_time().unwrap()
             )
         );
     }
@@ -987,7 +1009,8 @@ fn test_nakamoto_unconfirmed_tenure_downloader() {
         assert_eq!(
             ntd.state,
             NakamotoTenureDownloadState::GetTenureStartBlock(
-                unconfirmed_wanted_tenure.winning_block_id.clone()
+                unconfirmed_wanted_tenure.winning_block_id.clone(),
+                ntd.state.request_time().unwrap()
             )
         );
     }