fix: adjust difficulty in the mining loop

closes #154

When the timestamp is adjusted in the mining loop it is necessary to
also adjust the difficulty and difficulty threshhold.  This was not
happening before, which led to:

 1. occasional difficulty validation errors
 2. mean time-to-find-block that does not match expected mean.

This commit also adds a target_block_interval param to the mining
loop function, which enables tests to perform simulated mining at much
higher speeds, eg 1 second per block.

Changes:

 block/mod.rs:
   * Block::set_header_timestamp() -->
      Block::set_header_timestamp_and_difficulty()
   * log actual and expected valuus if difficulty validation fails
   * add test difficulty_control_matches()

 mine_loop.rs:
   * adjust difficulty and threshold in mining loop with the timestamp
   * mining_loop fn accepts a target_block_interval
   * improve test mine_ten_blocks_in_ten_seconds()

src/mine_loop.rs

@@ -102,13 +102,16 @@ fn make_block_template(
 }
 
 /// Attempt to mine a valid block for the network
+#[allow(clippy::too_many_arguments)]
 async fn mine_block(
     block_header: BlockHeader,
     block_body: BlockBody,
+    previous_block: Block,
     sender: oneshot::Sender<NewBlockFound>,
     coinbase_utxo_info: ExpectedUtxo,
     difficulty: U32s<5>,
     unrestricted_mining: bool,
+    target_block_interval: Option<u64>,
 ) {
     // We wrap mining loop with spawn_blocking() because it is a
     // very lengthy and CPU intensive task, which should execute
@@ -126,25 +129,30 @@ async fn mine_block(
         mine_block_worker(
             block_header,
             block_body,
+            previous_block,
             sender,
             coinbase_utxo_info,
             difficulty,
             unrestricted_mining,
+            target_block_interval,
         )
     })
     .await
     .unwrap()
 }
 
+#[allow(clippy::too_many_arguments)]
 fn mine_block_worker(
     block_header: BlockHeader,
     block_body: BlockBody,
+    previous_block: Block,
     sender: oneshot::Sender<NewBlockFound>,
     coinbase_utxo_info: ExpectedUtxo,
     difficulty: U32s<5>,
     unrestricted_mining: bool,
+    target_block_interval: Option<u64>,
 ) {
-    let threshold = Block::difficulty_to_digest_threshold(difficulty);
+    let mut threshold = Block::difficulty_to_digest_threshold(difficulty);
     info!(
         "Mining on block with {} outputs. Attempting to find block with height {} with digest less than difficulty threshold: {}",
         block_body.transaction.kernel.outputs.len(),
@@ -186,7 +194,11 @@ fn mine_block_worker(
         // this ensures header timestamp represents the moment block is found.
         // this is simplest impl.  Efficiencies can perhaps be gained by only
         // performing every N iterations, or other strategies.
-        block.set_header_timestamp(Timestamp::now());
+        let now = Timestamp::now();
+        let new_difficulty: U32s<5> =
+            Block::difficulty_control(&previous_block, now, target_block_interval);
+        threshold = Block::difficulty_to_digest_threshold(new_difficulty);
+        block.set_header_timestamp_and_difficulty(now, new_difficulty);
     }
 
     let nonce = block.kernel.header.nonce;
@@ -380,10 +392,12 @@ pub async fn mine(
                 let miner_task = mine_block(
                     block_header,
                     block_body,
+                    latest_block.clone(),
                     worker_thread_tx,
                     coinbase_utxo_info,
                     latest_block.kernel.header.difficulty,
                     global_state_lock.cli().unrestricted_mining,
+                    None, // using default TARGET_BLOCK_INTERVAL
                 );
                 global_state_lock.set_mining(true).await;
                 Some(
@@ -660,10 +674,12 @@ mod mine_loop_tests {
         mine_block_worker(
             block_header,
             block_body,
+            tip_block_orig.clone(),
             worker_thread_tx,
             coinbase_utxo_info,
             difficulty,
             unrestricted_mining,
+            None,
         );
 
         let mined_block_info = worker_thread_rx.await.unwrap();
@@ -714,10 +730,12 @@ mod mine_loop_tests {
         mine_block_worker(
             block_header,
             block_body,
+            tip_block_orig.clone(),
             worker_thread_tx,
             coinbase_utxo_info,
             difficulty,
             unrestricted_mining,
+            None,
         );
 
         let mined_block_info = worker_thread_rx.await.unwrap();
@@ -738,15 +756,20 @@ mod mine_loop_tests {
     /// We mine ten blocks with a target block interval of 1 second, so all
     /// blocks should be mined in approx 10 seconds.
     ///
-    /// We set a time limit of 2x the expected time, ie 20 seconds, and panic if
-    /// mining all blocks takes longer than that.  We also assert that
-    /// total time should not be less than 0.5x, ie 5 seconds.
+    /// We set a test time limit of 3x the expected time, ie 30 seconds, and
+    /// panic if mining all blocks takes longer than that.
+    ///
+    /// We also assert upper and lower bounds for variance from the expected 10
+    /// seconds.  The variance limit is 1.3, so the upper bound is 13 seconds
+    /// and the lower bound is 7692.
+    ///
+    /// We ignore the first 2 blocks after genesis because they are typically
+    /// mined very fast.
     ///
-    /// We use unrestricted mining (100% CPU) to avoid complications
-    /// from the sleep(100 millis) call in mining loop when restricted mining is
-    /// enabled.
+    /// We use unrestricted mining (100% CPU) to avoid complications from the
+    /// sleep(100 millis) call in mining loop when restricted mining is enabled.
     ///
-    /// This also serves as a regression test for issue #154.
+    /// This serves as a regression test for issue #154.
     /// https://github.com/Neptune-Crypto/neptune-core/issues/154
     #[traced_test]
     #[tokio::test]
@@ -762,15 +785,30 @@ mod mine_loop_tests {
             .light_state()
             .clone();
 
-        let unrestricted_mining = false;
-        let target_block_interval = 1000; // 1 second.
+        // adjust these to simulate longer mining runs, possibly
+        // with shorter or longer target intervals.
+        // expected_duration = num_blocks * target_block_interval
         let num_blocks = 10;
+        let target_block_interval = 1000; // 1 seconds.
+
+        let unrestricted_mining = false;
         let expected_duration = (target_block_interval * num_blocks) as u128;
-        let max_duration = expected_duration * 2;
+        let allowed_variance = 1.3;
+        let min_duration = (expected_duration as f64 / allowed_variance) as u64;
+        let max_duration = (expected_duration as f64 * allowed_variance) as u64;
+        let max_test_time = expected_duration * 3;
+
+        // we ignore the first 2 blocks after genesis because they are
+        // typically mined very fast.
+        let ignore_first_n_blocks = 2;
 
-        let start_instant = std::time::SystemTime::now();
+        let mut start_instant = std::time::SystemTime::now();
+
+        for i in 0..num_blocks + ignore_first_n_blocks {
+            if i == ignore_first_n_blocks {
+                start_instant = std::time::SystemTime::now();
+            }
 
-        for _i in 0..num_blocks {
             let start_time = Timestamp::now();
             let start_st = std::time::SystemTime::now();
 
@@ -798,10 +836,12 @@ mod mine_loop_tests {
             mine_block_worker(
                 block_header,
                 block_body,
+                prev_block.clone(),
                 worker_thread_tx,
                 coinbase_utxo_info,
                 difficulty,
                 unrestricted_mining,
+                Some(target_block_interval),
             );
 
             let mined_block_info = worker_thread_rx.await.unwrap();
@@ -822,17 +862,17 @@ mod mine_loop_tests {
             );
 
             let elapsed = start_instant.elapsed()?.as_millis();
-            if elapsed > max_duration {
-                panic!("test time limit exceeded.  expected_duration: {expected_duration}, limit: {max_duration}, actual: {elapsed}");
+            if elapsed > max_test_time {
+                panic!("test time limit exceeded.  expected_duration: {expected_duration}, limit: {max_test_time}, actual: {elapsed}");
             }
         }
 
-        let actual_duration = start_instant.elapsed()?.as_millis();
+        let actual_duration = start_instant.elapsed()?.as_millis() as u64;
 
-        println!("actual duration: {actual_duration}, expected duration: {expected_duration}");
+        println!("actual duration: {actual_duration}\nexpected duration: {expected_duration}\nmin_duration: {min_duration}\nmax_duration: {max_duration}\nallowed_variance: {allowed_variance}");
 
-        assert!(actual_duration < expected_duration * 2);
-        assert!(actual_duration > expected_duration / 2);
+        assert!(actual_duration > min_duration);
+        assert!(actual_duration < max_duration);
 
         Ok(())
     }

src/models/blockchain/block/mod.rs

@@ -202,12 +202,21 @@ impl Block {
         self.unset_digest();
     }
 
-    /// sets header timestamp.
+    /// sets header timestamp and difficulty.
+    ///
+    /// These must be set as a pair because the difficulty depends
+    /// on the timestamp, and may change with it.
     ///
     /// note: this causes block digest to change.
     #[inline]
-    pub fn set_header_timestamp(&mut self, timestamp: Timestamp) {
+    pub fn set_header_timestamp_and_difficulty(
+        &mut self,
+        timestamp: Timestamp,
+        difficulty: U32s<5>,
+    ) {
         self.kernel.header.timestamp = timestamp;
+        self.kernel.header.difficulty = difficulty;
+
         self.unset_digest();
     }
 
@@ -510,7 +519,15 @@ impl Block {
                 target_block_interval,
             )
         {
-            warn!("Value for new difficulty is incorrect.");
+            warn!(
+                "Value for new difficulty is incorrect.  actual: {},  expected: {}",
+                block_copy.kernel.header.difficulty,
+                Self::difficulty_control(
+                    previous_block,
+                    block_copy.kernel.header.timestamp,
+                    target_block_interval
+                )
+            );
             return false;
         }
 
@@ -669,14 +686,14 @@ impl Block {
         let t = new_timestamp - old_block.kernel.header.timestamp;
 
         let new_error = t.0.value() as i64 - target_block_interval as i64;
-
         let adjustment = -new_error / 100;
         let absolute_adjustment = abs(adjustment) as u64;
         let adjustment_is_positive = adjustment >= 0;
         let adj_hi = (absolute_adjustment >> 32) as u32;
         let adj_lo = absolute_adjustment as u32;
         let adjustment_u32s =
             U32s::<TARGET_DIFFICULTY_U32_SIZE>::new([adj_lo, adj_hi, 0u32, 0u32, 0u32]);
+
         if adjustment_is_positive {
             old_block.kernel.header.difficulty + adjustment_u32s
         } else if adjustment_u32s > old_block.kernel.header.difficulty - MINIMUM_DIFFICULTY.into() {
@@ -767,6 +784,41 @@ mod block_tests {
         (genesis_block, block_1, block_1_merged)
     }
 
+    // #[traced_test]
+    #[test]
+    fn test_difficulty_control_matches() {
+        let mut rng = thread_rng();
+        let network = Network::RegTest;
+
+        let a_wallet_secret = WalletSecret::new_random();
+        let a_recipient_address = a_wallet_secret.nth_generation_spending_key(0).to_address();
+
+        for multiplier in [10, 100, 1000, 10000, 100000, 1000000] {
+            let mut block_prev = Block::genesis_block(network);
+            let mut now = block_prev.kernel.header.timestamp;
+
+            for i in (0..100).step_by(1) {
+                let duration = i as u64 * multiplier;
+                now = now + Timestamp::millis(duration);
+
+                let (block, _, _) =
+                    make_mock_block(&block_prev, Some(now), a_recipient_address, rng.gen());
+
+                println!(
+                    "height: {}, now: {}",
+                    block.kernel.header.height,
+                    now.standard_format()
+                );
+
+                let control =
+                    Block::difficulty_control(&block_prev, block.kernel.header.timestamp, None);
+                assert_eq!(block.kernel.header.difficulty, control);
+
+                block_prev = block;
+            }
+        }
+    }
+
     #[traced_test]
     #[tokio::test]
     async fn merge_transaction_test() {