Repository: stacks-network/stacks-core (language: python)

Issue:
☂️ Tenure extends for increasing tenure budgets
The goal of the performance improvements (#5430, #5431, #5432) is to make the `stacks-node` more performant right now, and in particular, free up CPU time in the `stacks-node` such that if it is spending more time performing block processing, the nodes will continue to be able to stay in sync and responsive on their network interfaces (this is important for stackerdb messages to propagate, signers and miners to stay in sync, etc).

Once these improvements are in place, the tenure budget can be safely increased. This can (and should) be done without consensus changes. This can be done by simply issuing a tenure extend from the miner and the signer set approving it.

The basic idea is to have the miner thread time the length of its tenure, along with a configuration setting that tells it when it should try to perform a tenure extend. The signer set will similarly hold timers (measured from when they last signed off on a block proposal which spent some amount of block budget: the timer isn’t reset when they sign a block with just transfers, but it is reset if they process a block with contract-calls, e.g.), and when the timer expires, they would allow a tenure extend.

This would still allow the “spikiness” in budget consumption that we have today (the spikiness issue is somewhat orthogonal, and would be treated by #5433), but the budget would itself be higher, and the timing of extends would enforce some metering of the spikes (so that contract call budgets would be reset at, e.g., every 5 minutes rather than every bitcoin block, or whatever the timeout is set to). During initial rollout, this timeout will need to be set conservatively, but could be made more aggressive through configuration changes in miners and signers.



Discussion / hints:
> The signer set will similarly hold timers (measured from when they last signed off on a block proposal which spent some amount of block budget: the timer isn’t reset when they sign a block with just transfers, but it is reset if they process a block with contract-calls, e.g.), and when the timer expires, they would allow a tenure extend.

Can you expand on this - specifically, why would the timer only reset when a block with contract calls is processed? Wouldn't that _encourage_ spikiness? My assumption would be that this timer resets when a block includes a TenureExtend.
> Can you expand on this - specifically, why would the timer only reset when a block with contract calls is processed? Wouldn't that encourage spikiness? My assumption would be that this timer resets when a block includes a TenureExtend.

Yes, I think you’re right, the timer should start when a tenure begins (or the extension begins: basically the timer should start whenever there's a tenure change payload).

However, the signers must also do _some_ metering according to the block evaluation time. Right now, its the case that the tenure budget is expended often with just a few seconds of evaluation, but the cost tracker is an imperfect (and pessimistic) estimator of runtime. Things like cache locality in the MARF definitely impact block evaluation time, and so the signers should take that into account. This is simple enough for them to do naively by just tracking the wall clock time of processing the block proposals.

I _think_ the way to do this is to "bump" the budget timer by the amount of time they spend processing proposals during the tenure: so if a proposal takes them 1 minute to evaluate, they bump the budget timer by 1 minute (so if they would have allowed the budget to be reset at time `t`, they instead will allow the reset at time `t + 60s`.
Could you have signers track based on the last time they saw a tenure change payload rather than a contract call? I ask because the tenure change payload is always guaranteed to be the very first transaction in the block so might be easier to track that rather than the last block with a contract call. 
I had not thought about it this way, but I like the idea of factoring in the actual block processing time. To put it another way, we can think of it as the signer saying, "once I have seen X minutes of downtime, I will allow a tenure extend." So when the tenure starts or extends, I start a countdown at X minutes. When I get a block proposal, I pause the countdown, process the block, send my signature, and resume the countdown. When my countdown reaches 0, I will allow a tenure extension in the next block I process.

One simple way to synchronize between miners and signers could be for the signer to include a flag in its block signature message indicating to the miner that it is ready for a tenure extend. When the miner sees that enough signers have set this flag, it can go ahead and issue one in its next block.
Assuming we do some measurement of wall-clock time on block processing, I just want to note that we should have the node track this and return it to the signer in the HTTP response to the block proposal. If the signer tries to track this, we can end up with too much variance from other reasons for latency.
@obycode, to enlist the help of @hstove and @jferrant can you split this into smaller issues that they can handle in parallel?

Fix patch:
diff --git a/stackslib/src/net/api/postblock_proposal.rs b/stackslib/src/net/api/postblock_proposal.rs
index 5648c578b3..b2abc56dd6 100644
--- a/stackslib/src/net/api/postblock_proposal.rs
+++ b/stackslib/src/net/api/postblock_proposal.rs
@@ -16,6 +16,8 @@
 
 use std::io::{Read, Write};
 use std::thread::{self, JoinHandle, Thread};
+#[cfg(any(test, feature = "testing"))]
+use std::time::Duration;
 
 use clarity::vm::ast::ASTRules;
 use clarity::vm::costs::ExecutionCost;
@@ -65,6 +67,10 @@ use crate::util_lib::db::Error as DBError;
 
 #[cfg(any(test, feature = "testing"))]
 pub static TEST_VALIDATE_STALL: std::sync::Mutex<Option<bool>> = std::sync::Mutex::new(None);
+#[cfg(any(test, feature = "testing"))]
+/// Artificial delay to add to block validation.
+pub static TEST_VALIDATE_DELAY_DURATION_SECS: std::sync::Mutex<Option<u64>> =
+    std::sync::Mutex::new(None);
 
 // This enum is used to supply a `reason_code` for validation
 //  rejection responses. This is serialized as an enum with string
@@ -364,6 +370,14 @@ impl NakamotoBlockProposal {
                 .unwrap_or(u64::MAX)
         };
 
+        #[cfg(any(test, feature = "testing"))]
+        {
+            if let Some(delay) = *TEST_VALIDATE_DELAY_DURATION_SECS.lock().unwrap() {
+                warn!("Sleeping for {} seconds to simulate slow processing", delay);
+                thread::sleep(Duration::from_secs(delay));
+            }
+        }
+
         let mainnet = self.chain_id == CHAIN_ID_MAINNET;
         if self.chain_id != chainstate.chain_id || mainnet != chainstate.mainnet {
             warn!(


Test patch:
diff --git a/.github/workflows/bitcoin-tests.yml b/.github/workflows/bitcoin-tests.yml
index 04e74f94e8..fd2d5606a2 100644
--- a/.github/workflows/bitcoin-tests.yml
+++ b/.github/workflows/bitcoin-tests.yml
@@ -122,6 +122,8 @@ jobs:
           - tests::signer::v0::signer_set_rollover
           - tests::signer::v0::signing_in_0th_tenure_of_reward_cycle
           - tests::signer::v0::continue_after_tenure_extend
+          - tests::signer::v0::tenure_extend_after_idle
+          - tests::signer::v0::stx_transfers_dont_effect_idle_timeout
           - tests::signer::v0::multiple_miners_with_custom_chain_id
           - tests::signer::v0::block_commit_delay
           - tests::signer::v0::continue_after_fast_block_no_sortition
diff --git a/testnet/stacks-node/src/tests/signer/v0.rs b/testnet/stacks-node/src/tests/signer/v0.rs
index 0051902852..b27cd1c1fa 100644
--- a/testnet/stacks-node/src/tests/signer/v0.rs
+++ b/testnet/stacks-node/src/tests/signer/v0.rs
@@ -39,11 +39,13 @@ use stacks::codec::StacksMessageCodec;
 use stacks::core::{StacksEpochId, CHAIN_ID_TESTNET};
 use stacks::libstackerdb::StackerDBChunkData;
 use stacks::net::api::getsigner::GetSignerResponse;
-use stacks::net::api::postblock_proposal::{ValidateRejectCode, TEST_VALIDATE_STALL};
+use stacks::net::api::postblock_proposal::{
+    ValidateRejectCode, TEST_VALIDATE_DELAY_DURATION_SECS, TEST_VALIDATE_STALL,
+};
 use stacks::net::relay::fault_injection::set_ignore_block;
 use stacks::types::chainstate::{StacksAddress, StacksBlockId, StacksPrivateKey, StacksPublicKey};
 use stacks::types::PublicKey;
-use stacks::util::hash::{hex_bytes, Hash160, MerkleHashFunc};
+use stacks::util::hash::{hex_bytes, Hash160, MerkleHashFunc, Sha512Trunc256Sum};
 use stacks::util::secp256k1::{Secp256k1PrivateKey, Secp256k1PublicKey};
 use stacks::util_lib::boot::boot_code_id;
 use stacks::util_lib::signed_structured_data::pox4::{
@@ -2562,6 +2564,255 @@ fn signers_broadcast_signed_blocks() {
     signer_test.shutdown();
 }
 
+#[test]
+#[ignore]
+/// This test verifies that a miner will produce a TenureExtend transaction after the idle timeout is reached.
+fn tenure_extend_after_idle() {
+    if env::var("BITCOIND_TEST") != Ok("1".into()) {
+        return;
+    }
+
+    tracing_subscriber::registry()
+        .with(fmt::layer())
+        .with(EnvFilter::from_default_env())
+        .init();
+
+    info!("------------------------- Test Setup -------------------------");
+    let num_signers = 5;
+    let sender_sk = Secp256k1PrivateKey::new();
+    let sender_addr = tests::to_addr(&sender_sk);
+    let send_amt = 100;
+    let send_fee = 180;
+    let _recipient = PrincipalData::from(StacksAddress::burn_address(false));
+    let idle_timeout = Duration::from_secs(30);
+    let mut signer_test: SignerTest<SpawnedSigner> = SignerTest::new_with_config_modifications(
+        num_signers,
+        vec![(sender_addr, send_amt + send_fee)],
+        |config| {
+            // make the duration long enough that the miner will be marked as malicious
+            config.tenure_idle_timeout = idle_timeout;
+        },
+        |_| {},
+        None,
+        None,
+    );
+    let _http_origin = format!("http://{}", &signer_test.running_nodes.conf.node.rpc_bind);
+
+    signer_test.boot_to_epoch_3();
+
+    info!("---- Nakamoto booted, starting test ----");
+    let info_before = get_chain_info(&signer_test.running_nodes.conf);
+    let blocks_before = signer_test
+        .running_nodes
+        .nakamoto_blocks_mined
+        .load(Ordering::SeqCst);
+    signer_test.mine_nakamoto_block(Duration::from_secs(30));
+
+    // Verify that the block was mined
+    wait_for(30, || {
+        let blocks_mined = signer_test
+            .running_nodes
+            .nakamoto_blocks_mined
+            .load(Ordering::SeqCst);
+        let info = get_chain_info(&signer_test.running_nodes.conf);
+        Ok(blocks_mined > blocks_before && info.stacks_tip_height > info_before.stacks_tip_height)
+    })
+    .expect("Timed out waiting for first nakamoto block to be mined");
+
+    info!("---- Waiting for a tenure extend ----");
+
+    // Now, wait for a block with a tenure extend
+    wait_for(idle_timeout.as_secs() + 10, || {
+        Ok(last_block_contains_tenure_change_tx(
+            TenureChangeCause::Extended,
+        ))
+    })
+    .expect("Timed out waiting for a block with a tenure extend");
+
+    signer_test.shutdown();
+}
+
+#[test]
+#[ignore]
+/// Verify that Nakamoto blocks that don't modify the tenure's execution cost
+/// don't modify the idle timeout.
+fn stx_transfers_dont_effect_idle_timeout() {
+    if env::var("BITCOIND_TEST") != Ok("1".into()) {
+        return;
+    }
+
+    tracing_subscriber::registry()
+        .with(fmt::layer())
+        .with(EnvFilter::from_default_env())
+        .init();
+
+    info!("------------------------- Test Setup -------------------------");
+    let num_signers = 5;
+    let sender_sk = Secp256k1PrivateKey::new();
+    let sender_addr = tests::to_addr(&sender_sk);
+    let send_amt = 100;
+    let send_fee = 180;
+    let num_txs = 5;
+    let recipient = PrincipalData::from(StacksAddress::burn_address(false));
+    let idle_timeout = Duration::from_secs(60);
+    let mut signer_test: SignerTest<SpawnedSigner> = SignerTest::new_with_config_modifications(
+        num_signers,
+        vec![(sender_addr, (send_amt + send_fee) * num_txs)],
+        |config| {
+            // make the duration long enough that the miner will be marked as malicious
+            config.tenure_idle_timeout = idle_timeout;
+        },
+        |_| {},
+        None,
+        None,
+    );
+    let naka_conf = signer_test.running_nodes.conf.clone();
+    let http_origin = format!("http://{}", &naka_conf.node.rpc_bind);
+
+    signer_test.boot_to_epoch_3();
+
+    // Add a delay to the block validation process
+    TEST_VALIDATE_DELAY_DURATION_SECS.lock().unwrap().replace(5);
+
+    let info_before = signer_test
+        .stacks_client
+        .get_peer_info()
+        .expect("Failed to get peer info");
+    let blocks_before = signer_test
+        .running_nodes
+        .nakamoto_blocks_mined
+        .load(Ordering::SeqCst);
+    info!("---- Nakamoto booted, starting test ----";
+        "info_height" => info_before.stacks_tip_height,
+        "blocks_before" => blocks_before,
+    );
+    signer_test.mine_nakamoto_block(Duration::from_secs(30));
+
+    info!("---- Verifying that the block was mined ----");
+    // Verify that the block was mined
+    wait_for(30, || {
+        let blocks_mined = signer_test
+            .running_nodes
+            .nakamoto_blocks_mined
+            .load(Ordering::SeqCst);
+        let info = signer_test
+            .stacks_client
+            .get_peer_info()
+            .expect("Failed to get peer info");
+        Ok(blocks_mined > blocks_before && info.stacks_tip_height > info_before.stacks_tip_height)
+    })
+    .expect("Timed out waiting for first nakamoto block to be mined");
+
+    info!("---- Getting current idle timeout ----");
+
+    let reward_cycle = signer_test.get_current_reward_cycle();
+
+    let signer_slot_ids: Vec<_> = signer_test
+        .get_signer_indices(reward_cycle)
+        .iter()
+        .map(|id| id.0)
+        .collect();
+    assert_eq!(signer_slot_ids.len(), num_signers);
+
+    let get_last_block_hash = || {
+        let blocks = test_observer::get_blocks();
+        let last_block = blocks.last().unwrap();
+        let block_hash =
+            hex_bytes(&last_block.get("block_hash").unwrap().as_str().unwrap()[2..]).unwrap();
+        Sha512Trunc256Sum::from_vec(&block_hash).unwrap()
+    };
+
+    let last_block_hash = get_last_block_hash();
+
+    let slot_id = 0_u32;
+
+    let get_last_block_response = |slot_id: u32| {
+        let mut stackerdb = StackerDB::new(
+            &naka_conf.node.rpc_bind,
+            StacksPrivateKey::new(), // We are just reading so don't care what the key is
+            false,
+            reward_cycle,
+            SignerSlotID(0), // We are just reading so again, don't care about index.
+        );
+        let latest_msgs = StackerDB::get_messages(
+            stackerdb
+                .get_session_mut(&MessageSlotID::BlockResponse)
+                .expect("Failed to get BlockResponse stackerdb session"),
+            &[slot_id],
+        )
+        .expect("Failed to get message from stackerdb");
+        let latest_msg = latest_msgs.last().unwrap();
+        let SignerMessage::BlockResponse(BlockResponse::Accepted(accepted)) = latest_msg else {
+            panic!("Latest message from slot #{slot_id} isn't a block acceptance");
+        };
+        accepted.clone()
+    };
+
+    let initial_acceptance = get_last_block_response(slot_id);
+    assert_eq!(initial_acceptance.signer_signature_hash, last_block_hash);
+
+    info!(
+        "---- Last idle timeout: {} ----",
+        initial_acceptance.response_data.tenure_extend_timestamp
+    );
+
+    // Now, mine a few nakamoto blocks with just transfers
+
+    let mut sender_nonce = 0;
+
+    // Note that this response was BEFORE the block was globally accepted. it will report a guestimated idle time
+    let initial_acceptance = initial_acceptance;
+    let mut first_global_acceptance = None;
+    for i in 0..num_txs {
+        info!("---- Mining interim block {} ----", i + 1);
+        let transfer_tx = make_stacks_transfer(
+            &sender_sk,
+            sender_nonce,
+            send_fee,
+            naka_conf.burnchain.chain_id,
+            &recipient,
+            send_amt,
+        );
+        submit_tx(&http_origin, &transfer_tx);
+        sender_nonce += 1;
+        let info_before = signer_test
+            .stacks_client
+            .get_peer_info()
+            .expect("Failed to get peer info");
+        wait_for(30, || {
+            let info = signer_test
+                .stacks_client
+                .get_peer_info()
+                .expect("Failed to get peer info");
+            Ok(info.stacks_tip_height > info_before.stacks_tip_height)
+        })
+        .expect("Timed out waiting for nakamoto block to be mined");
+
+        let latest_acceptance = get_last_block_response(slot_id);
+        let last_block_hash = get_last_block_hash();
+
+        assert_eq!(latest_acceptance.signer_signature_hash, last_block_hash);
+
+        if first_global_acceptance.is_none() {
+            assert!(latest_acceptance.response_data.tenure_extend_timestamp < initial_acceptance.response_data.tenure_extend_timestamp, "First global acceptance should be less than initial guesstimated acceptance as its based on block proposal time rather than epoch time at time of response.");
+            first_global_acceptance = Some(latest_acceptance);
+        } else {
+            // Because the block only contains transfers, the idle timeout should not have changed between blocks post the tenure change
+            assert_eq!(
+                latest_acceptance.response_data.tenure_extend_timestamp,
+                first_global_acceptance
+                    .as_ref()
+                    .map(|acceptance| acceptance.response_data.tenure_extend_timestamp)
+                    .unwrap()
+            );
+        };
+    }
+
+    info!("---- Waiting for a tenure extend ----");
+
+    signer_test.shutdown();
+}
+
 #[test]
 #[ignore]
 /// This test checks the behaviour of signers when a sortition is empty. Specifically: