Merge branch 'develop' of https://github.com/stacks-network/stacks-core into feat/signer-track-validation-submission-with-config-timeout

Author: jferrant

.github/workflows/bitcoin-tests.yml

@@ -99,6 +99,8 @@ jobs:
           - tests::signer::v0::forked_tenure_okay
           - tests::signer::v0::forked_tenure_invalid
           - tests::signer::v0::empty_sortition
+          - tests::signer::v0::empty_sortition_before_approval
+          - tests::signer::v0::empty_sortition_before_proposal
           - tests::signer::v0::bitcoind_forking_test
           - tests::signer::v0::multiple_miners
           - tests::signer::v0::mock_sign_epoch_25
@@ -112,6 +114,7 @@ jobs:
           - tests::signer::v0::locally_accepted_blocks_overriden_by_global_rejection
           - tests::signer::v0::locally_rejected_blocks_overriden_by_global_acceptance
           - tests::signer::v0::reorg_locally_accepted_blocks_across_tenures_succeeds
+          - tests::signer::v0::reorg_locally_accepted_blocks_across_tenures_fails
           - tests::signer::v0::miner_recovers_when_broadcast_block_delay_across_tenures_occurs
           - tests::signer::v0::multiple_miners_with_nakamoto_blocks
           - tests::signer::v0::partial_tenure_fork
@@ -134,6 +137,7 @@ jobs:
           - tests::nakamoto_integrations::utxo_check_on_startup_panic
           - tests::nakamoto_integrations::utxo_check_on_startup_recover
           - tests::nakamoto_integrations::v3_signer_api_endpoint
+          - tests::nakamoto_integrations::signer_chainstate
           # TODO: enable these once v1 signer is supported by a new nakamoto epoch
           # - tests::signer::v1::dkg
           # - tests::signer::v1::sign_request_rejected

CHANGELOG.md

@@ -7,6 +7,25 @@ and this project adheres to the versioning scheme outlined in the [README.md](RE
 
 ## [Unreleased]
 
+### Changed
+- Add index for StacksBlockId to nakamoto block headers table (improves node performance)
+- Remove the panic for reporting DB deadlocks (just error and continue waiting)
+
+## [3.0.0.0.1]
+
+### Changed
+- Add index for StacksBlockId to nakamoto block headers table (improves node performance)
+- Remove the panic for reporting DB deadlocks (just error and continue waiting)
+- Various test fixes for CI (5353, 5368, 5372, 5371, 5380, 5378, 5387, 5396, 5390, 5394)
+- Various log fixes: 
+    - don't say proceeding to mine blocks if not a miner
+    - misc. warns downgraded to debugs
+- 5391: Update default block proposal timeout to 10 minutes
+- 5406: After block rejection, miner pauses
+- Docs fixes
+    - Fix signer docs link
+    - Specify burn block in clarity docs
+
 ## [3.0.0.0.0]
 
 ### Added

Cargo.lock

@@ -21,6 +21,7 @@ rand = "0.8"
 rand_chacha = "0.3.1"
 tikv-jemallocator = "0.5.4"
 rusqlite = { version = "0.31.0", features = ["blob", "serde_json", "i128_blob", "bundled", "trace"] }
+thiserror = { version = "1.0.65" }
 
 # Use a bit more than default optimization for
 #  dev builds to speed up test execution

Cargo.toml

@@ -30,7 +30,7 @@ slog-term = "2.6.0"
 slog-json = { version = "2.3.0", optional = true }
 stacks-common = { path = "../stacks-common" }
 stackslib = { path = "../stackslib"}
-thiserror = "1.0"
+thiserror = { workspace = true }
 tiny_http = "0.12"
 
 [dev-dependencies]

libsigner/Cargo.toml

@@ -51,26 +51,25 @@ pub fn update_lock_table(conn: &Connection) {
 /// Called by `rusqlite` if we are waiting too long on a database lock
 /// If called too many times, will assume a deadlock and panic
 pub fn tx_busy_handler(run_count: i32) -> bool {
-    const TIMEOUT: Duration = Duration::from_secs(300);
     const AVG_SLEEP_TIME_MS: u64 = 100;
 
+    // Every ~5min, report an error with a backtrace
+    //   5min * 60s/min * 1_000ms/s / 100ms
+    const ERROR_COUNT: u32 = 3_000;
+
     // First, check if this is taking unreasonably long. If so, it's probably a deadlock
     let run_count = run_count.unsigned_abs();
-    let approx_time_elapsed =
-        Duration::from_millis(AVG_SLEEP_TIME_MS.saturating_mul(u64::from(run_count)));
-    if approx_time_elapsed > TIMEOUT {
-        error!("Deadlock detected. Waited {} seconds (estimated) for database lock. Giving up", approx_time_elapsed.as_secs();
+    if run_count > 0 && run_count % ERROR_COUNT == 0 {
+        error!("Deadlock detected. Waited 5 minutes (estimated) for database lock.";
             "run_count" => run_count,
             "backtrace" => ?Backtrace::capture()
         );
         for (k, v) in LOCK_TABLE.lock().unwrap().iter() {
             error!("Database '{k}' last locked by {v}");
         }
-        panic!("Deadlock in thread {:?}", thread::current().name());
     }
 
     let mut sleep_time_ms = 2u64.saturating_pow(run_count);
-
     sleep_time_ms = sleep_time_ms.saturating_add(thread_rng().gen_range(0..sleep_time_ms));
 
     if sleep_time_ms > AVG_SLEEP_TIME_MS {

stacks-common/src/util/db.rs

@@ -215,14 +215,13 @@ fn make_json_logger() -> Logger {
     panic!("Tried to construct JSON logger, but stacks-blockchain built without slog_json feature enabled.")
 }
 
-#[cfg(not(any(test, feature = "testing")))]
 fn make_logger() -> Logger {
     if env::var("STACKS_LOG_JSON") == Ok("1".into()) {
         make_json_logger()
     } else {
         let debug = env::var("STACKS_LOG_DEBUG") == Ok("1".into());
         let pretty_print = env::var("STACKS_LOG_PP") == Ok("1".into());
-        let decorator = slog_term::PlainSyncDecorator::new(std::io::stderr());
+        let decorator = get_decorator();
         let atty = isatty(Stream::Stderr);
         let drain = TermFormat::new(decorator, pretty_print, debug, atty);
         let logger = Logger::root(drain.ignore_res(), o!());
@@ -231,17 +230,13 @@ fn make_logger() -> Logger {
 }
 
 #[cfg(any(test, feature = "testing"))]
-fn make_logger() -> Logger {
-    if env::var("STACKS_LOG_JSON") == Ok("1".into()) {
-        make_json_logger()
-    } else {
-        let debug = env::var("STACKS_LOG_DEBUG") == Ok("1".into());
-        let plain = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter);
-        let isatty = isatty(Stream::Stdout);
-        let drain = TermFormat::new(plain, false, debug, isatty);
-        let logger = Logger::root(drain.ignore_res(), o!());
-        logger
-    }
+fn get_decorator() -> slog_term::PlainSyncDecorator<slog_term::TestStdoutWriter> {
+    slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter)
+}
+
+#[cfg(not(any(test, feature = "testing")))]
+fn get_decorator() -> slog_term::PlainSyncDecorator<std::io::Stderr> {
+    slog_term::PlainSyncDecorator::new(std::io::stderr())
 }
 
 fn inner_get_loglevel() -> slog::Level {

stacks-common/src/util/log.rs

@@ -11,7 +11,21 @@ and this project adheres to the versioning scheme outlined in the [README.md](RE
 
 ### Changed
 
-## [3.0.0.0.0]
+## [3.0.0.0.1.0]
+
+### Changed
+
+- Change block rejection message to generic block response
+
+## [3.0.0.0.0.1]
+
+### Added
+
+### Changed
+- Update block proposal timeout default to 10 minutes (#5391)
+- Updated documentation link in output (#5363)
+
+## [3.0.0.0.0.0]
 
 ### Added
 

stacks-signer/CHANGELOG.md

@@ -38,7 +38,7 @@ slog-json = { version = "2.3.0", optional = true }
 slog-term = "2.6.0"
 stacks-common = { path = "../stacks-common" }
 stackslib = { path = "../stackslib" }
-thiserror = "1.0"
+thiserror = { workspace = true }
 tiny_http = { version = "0.12", optional = true }
 toml = "0.5.6"
 tracing = "0.1.37"

stacks-signer/Cargo.toml

@@ -19,15 +19,15 @@ use blockstack_lib::chainstate::nakamoto::NakamotoBlock;
 use blockstack_lib::chainstate::stacks::TenureChangePayload;
 use blockstack_lib::net::api::getsortition::SortitionInfo;
 use blockstack_lib::util_lib::db::Error as DBError;
-use clarity::types::chainstate::BurnchainHeaderHash;
 use slog::{slog_info, slog_warn};
-use stacks_common::types::chainstate::{ConsensusHash, StacksPublicKey};
+use stacks_common::types::chainstate::{BurnchainHeaderHash, ConsensusHash, StacksPublicKey};
+use stacks_common::util::get_epoch_time_secs;
 use stacks_common::util::hash::Hash160;
 use stacks_common::{info, warn};
 
 use crate::client::{ClientError, CurrentAndLastSortition, StacksClient};
 use crate::config::SignerConfig;
-use crate::signerdb::{BlockState, SignerDb};
+use crate::signerdb::{BlockInfo, BlockState, SignerDb};
 
 #[derive(thiserror::Error, Debug)]
 /// Error type for the signer chainstate module
@@ -119,13 +119,17 @@ pub struct ProposalEvalConfig {
     pub first_proposal_burn_block_timing: Duration,
     /// Time between processing a sortition and proposing a block before the block is considered invalid
     pub block_proposal_timeout: Duration,
+    /// Time to wait for the last block of a tenure to be globally accepted or rejected before considering
+    /// a new miner's block at the same height as valid.
+    pub tenure_last_block_proposal_timeout: Duration,
 }
 
 impl From<&SignerConfig> for ProposalEvalConfig {
     fn from(value: &SignerConfig) -> Self {
         Self {
             first_proposal_burn_block_timing: value.first_proposal_burn_block_timing,
             block_proposal_timeout: value.block_proposal_timeout,
+            tenure_last_block_proposal_timeout: value.tenure_last_block_proposal_timeout,
         }
     }
 }
@@ -460,7 +464,36 @@ impl SortitionsView {
         Ok(true)
     }
 
-    /// Check if the tenure change block confirms the expected parent block (i.e., the last globally accepted block in the parent tenure)
+    /// Get the last block from the given tenure
+    /// Returns the last locally accepted block if it is not timed out, otherwise it will return the last globally accepted block.
+    fn get_tenure_last_block_info(
+        consensus_hash: &ConsensusHash,
+        signer_db: &SignerDb,
+        tenure_last_block_proposal_timeout: Duration,
+    ) -> Result<Option<BlockInfo>, ClientError> {
+        // Get the last known block in the previous tenure
+        let last_locally_accepted_block = signer_db
+            .get_last_accepted_block(consensus_hash)
+            .map_err(|e| ClientError::InvalidResponse(e.to_string()))?;
+
+        if let Some(local_info) = last_locally_accepted_block {
+            if let Some(signed_over_time) = local_info.signed_self {
+                if signed_over_time + tenure_last_block_proposal_timeout.as_secs()
+                    > get_epoch_time_secs()
+                {
+                    // The last locally accepted block is not timed out, return it
+                    return Ok(Some(local_info));
+                }
+            }
+        }
+        // The last locally accepted block is timed out, get the last globally accepted block
+        signer_db
+            .get_last_globally_accepted_block(consensus_hash)
+            .map_err(|e| ClientError::InvalidResponse(e.to_string()))
+    }
+
+    /// Check if the tenure change block confirms the expected parent block
+    /// (i.e., the last locally accepted block in the parent tenure, or if that block is timed out, the last globally accepted block in the parent tenure)
     /// It checks the local DB first, and if the block is not present in the local DB, it asks the
     /// Stacks node for the highest processed block header in the given tenure (and then caches it
     /// in the DB).
@@ -473,24 +506,27 @@ impl SortitionsView {
         reward_cycle: u64,
         signer_db: &mut SignerDb,
         client: &StacksClient,
+        tenure_last_block_proposal_timeout: Duration,
     ) -> Result<bool, ClientError> {
-        // If the tenure change block confirms the expected parent block, it should confirm at least one more block than the last globally accepted block in the parent tenure.
-        let last_globally_accepted_block = signer_db
-            .get_last_globally_accepted_block(&tenure_change.prev_tenure_consensus_hash)
-            .map_err(|e| ClientError::InvalidResponse(e.to_string()))?;
+        // If the tenure change block confirms the expected parent block, it should confirm at least one more block than the last accepted block in the parent tenure.
+        let last_block_info = Self::get_tenure_last_block_info(
+            &tenure_change.prev_tenure_consensus_hash,
+            signer_db,
+            tenure_last_block_proposal_timeout,
+        )?;
 
-        if let Some(global_info) = last_globally_accepted_block {
+        if let Some(info) = last_block_info {
             // N.B. this block might not be the last globally accepted block across the network;
             // it's just the highest one in this tenure that we know about.  If this given block is
             // no higher than it, then it's definitely no higher than the last globally accepted
             // block across the network, so we can do an early rejection here.
-            if block.header.chain_length <= global_info.block.header.chain_length {
+            if block.header.chain_length <= info.block.header.chain_length {
                 warn!(
                     "Miner's block proposal does not confirm as many blocks as we expect";
                     "proposed_block_consensus_hash" => %block.header.consensus_hash,
                     "proposed_block_signer_sighash" => %block.header.signer_signature_hash(),
                     "proposed_chain_length" => block.header.chain_length,
-                    "expected_at_least" => global_info.block.header.chain_length + 1,
+                    "expected_at_least" => info.block.header.chain_length + 1,
                 );
                 return Ok(false);
             }
@@ -558,6 +594,7 @@ impl SortitionsView {
             reward_cycle,
             signer_db,
             client,
+            self.config.tenure_last_block_proposal_timeout,
         )?;
         if !confirms_expected_parent {
             return Ok(false);
@@ -573,15 +610,15 @@ impl SortitionsView {
         if !is_valid_parent_tenure {
             return Ok(false);
         }
-        let last_in_tenure = signer_db
+        let last_in_current_tenure = signer_db
             .get_last_globally_accepted_block(&block.header.consensus_hash)
             .map_err(|e| ClientError::InvalidResponse(e.to_string()))?;
-        if let Some(last_in_tenure) = last_in_tenure {
+        if let Some(last_in_current_tenure) = last_in_current_tenure {
             warn!(
                 "Miner block proposal contains a tenure change, but we've already signed a block in this tenure. Considering proposal invalid.";
                 "proposed_block_consensus_hash" => %block.header.consensus_hash,
                 "proposed_block_signer_sighash" => %block.header.signer_signature_hash(),
-                "last_in_tenure_signer_sighash" => %last_in_tenure.block.header.signer_signature_hash(),
+                "last_in_tenure_signer_sighash" => %last_in_current_tenure.block.header.signer_signature_hash(),
             );
             return Ok(false);
         }