diff --git a/.github/workflows/bitcoin-tests.yml b/.github/workflows/bitcoin-tests.yml index fd2d5606a2..60886ad4a7 100644 --- a/.github/workflows/bitcoin-tests.yml +++ b/.github/workflows/bitcoin-tests.yml @@ -124,6 +124,7 @@ jobs: - 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::idle_tenure_extend_active_mining - 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/libsigner/src/v0/messages.rs b/libsigner/src/v0/messages.rs index fd639a91f4..087c4ba7a3 100644 --- a/libsigner/src/v0/messages.rs +++ b/libsigner/src/v0/messages.rs @@ -670,6 +670,22 @@ impl BlockResponse { timestamp, )) } + + /// Get the tenure extend timestamp from the block response + pub fn get_tenure_extend_timestamp(&self) -> u64 { + match self { + BlockResponse::Accepted(accepted) => accepted.response_data.tenure_extend_timestamp, + BlockResponse::Rejected(rejection) => rejection.response_data.tenure_extend_timestamp, + } + } + + /// Get the signer signature hash from the block response + pub fn get_signer_signature_hash(&self) -> Sha512Trunc256Sum { + match self { + BlockResponse::Accepted(accepted) => accepted.signer_signature_hash, + BlockResponse::Rejected(rejection) => rejection.signer_signature_hash, + } + } } impl StacksMessageCodec for BlockResponse { diff --git a/testnet/stacks-node/src/run_loop/neon.rs b/testnet/stacks-node/src/run_loop/neon.rs index 5e021e50ab..b2171b4e8b 100644 --- a/testnet/stacks-node/src/run_loop/neon.rs +++ b/testnet/stacks-node/src/run_loop/neon.rs @@ -73,6 +73,18 @@ impl Default for RunLoopCounter { } } +impl RunLoopCounter { + #[cfg(test)] + pub fn get(&self) -> u64 { + self.0.load(Ordering::SeqCst) + } + + #[cfg(test)] + pub fn load(&self, ordering: Ordering) -> u64 { + self.0.load(ordering) + } +} + #[cfg(test)] impl std::ops::Deref for RunLoopCounter { type Target = Arc; diff --git a/testnet/stacks-node/src/tests/signer/mod.rs b/testnet/stacks-node/src/tests/signer/mod.rs index 946a566c13..ff128d0a03 100644 --- a/testnet/stacks-node/src/tests/signer/mod.rs +++ b/testnet/stacks-node/src/tests/signer/mod.rs @@ -36,7 +36,9 @@ use std::time::{Duration, Instant}; use clarity::boot_util::boot_code_id; use clarity::vm::types::PrincipalData; -use libsigner::v0::messages::{BlockResponse, SignerMessage}; +use libsigner::v0::messages::{ + BlockAccepted, BlockResponse, MessageSlotID, PeerInfo, SignerMessage, +}; use libsigner::{SignerEntries, SignerEventTrait}; use stacks::chainstate::coordinator::comm::CoordinatorChannels; use stacks::chainstate::nakamoto::signer_set::NakamotoSigners; @@ -53,14 +55,14 @@ use stacks_common::codec::StacksMessageCodec; use stacks_common::consts::SIGNER_SLOTS_PER_USER; use stacks_common::types::StacksEpochId; use stacks_common::util::hash::Sha512Trunc256Sum; -use stacks_signer::client::{ClientError, SignerSlotID, StacksClient}; +use stacks_signer::client::{ClientError, SignerSlotID, StackerDB, StacksClient}; use stacks_signer::config::{build_signer_config_tomls, GlobalConfig as SignerConfig, Network}; use stacks_signer::runloop::{SignerResult, State, StateInfo}; use stacks_signer::{Signer, SpawnedSigner}; use super::nakamoto_integrations::{check_nakamoto_empty_block_heuristics, wait_for}; use crate::config::{Config as NeonConfig, EventKeyType, EventObserverConfig, InitialBalance}; -use crate::neon::{Counters, TestFlag}; +use crate::neon::{Counters, RunLoopCounter, TestFlag}; use crate::run_loop::boot_nakamoto; use crate::tests::bitcoin_regtest::BitcoinCoreController; use crate::tests::nakamoto_integrations::{ @@ -81,13 +83,13 @@ pub struct RunningNodes { pub btcd_controller: BitcoinCoreController, pub run_loop_thread: thread::JoinHandle<()>, pub run_loop_stopper: Arc, - pub vrfs_submitted: Arc, - pub commits_submitted: Arc, - pub blocks_processed: Arc, - pub nakamoto_blocks_proposed: Arc, - pub nakamoto_blocks_mined: Arc, - pub nakamoto_blocks_rejected: Arc, - pub nakamoto_blocks_signer_pushed: Arc, + pub vrfs_submitted: RunLoopCounter, + pub commits_submitted: RunLoopCounter, + pub blocks_processed: RunLoopCounter, + pub nakamoto_blocks_proposed: RunLoopCounter, + pub nakamoto_blocks_mined: RunLoopCounter, + pub nakamoto_blocks_rejected: RunLoopCounter, + pub nakamoto_blocks_signer_pushed: RunLoopCounter, pub nakamoto_test_skip_commit_op: TestFlag, pub coord_channel: Arc>, pub conf: NeonConfig, @@ -307,10 +309,12 @@ impl + Send + 'static, T: SignerEventTrait + 'static> SignerTest + Send + 'static, T: SignerEventTrait + 'static> SignerTest info_before.stacks_tip_height) + let info_after = self.get_peer_info(); + let blocks_mined = self.running_nodes.nakamoto_blocks_mined.get(); + Ok(info_after.stacks_tip_height > info_before.stacks_tip_height + && blocks_mined > mined_before) }) .unwrap(); let mined_block_elapsed_time = mined_block_time.elapsed(); @@ -355,6 +361,26 @@ impl + Send + 'static, T: SignerEventTrait + 'static> SignerTest ()) { + let blocks_before = self.running_nodes.nakamoto_blocks_mined.get(); + let info_before = self.get_peer_info(); + + f(); + + // Verify that the block was mined + wait_for(timeout_secs, || { + let blocks_mined = self.running_nodes.nakamoto_blocks_mined.get(); + let info = self.get_peer_info(); + Ok(blocks_mined > blocks_before + && info.stacks_tip_height > info_before.stacks_tip_height) + }) + .expect("Timed out waiting for nakamoto block to be mined"); + } + /// Wait for a confirmed block and return a list of individual /// signer signatures fn wait_for_confirmed_block_v0( @@ -618,6 +644,45 @@ impl + Send + 'static, T: SignerEventTrait + 'static> SignerTest BlockResponse { + let mut stackerdb = StackerDB::new( + &self.running_nodes.conf.node.rpc_bind, + StacksPrivateKey::new(), // We are just reading so don't care what the key is + false, + self.get_current_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(block_response) = latest_msg else { + panic!("Latest message from slot #{slot_id} isn't a block acceptance"); + }; + block_response.clone() + } + + /// Get the latest block acceptance from the given slot + pub fn get_latest_block_acceptance(&self, slot_id: u32) -> BlockAccepted { + let block_response = self.get_latest_block_response(slot_id); + match block_response { + BlockResponse::Accepted(accepted) => accepted, + _ => panic!("Latest block response from slot #{slot_id} isn't a block acceptance"), + } + } + + /// Get /v2/info from the node + pub fn get_peer_info(&self) -> PeerInfo { + self.stacks_client + .get_peer_info() + .expect("Failed to get peer info") + } } fn setup_stx_btc_node( @@ -747,13 +812,13 @@ fn setup_stx_btc_node( btc_regtest_controller, run_loop_thread, run_loop_stopper, - vrfs_submitted: vrfs_submitted.0, - commits_submitted: commits_submitted.0, - blocks_processed: blocks_processed.0, - nakamoto_blocks_proposed: naka_blocks_proposed.0, - nakamoto_blocks_mined: naka_blocks_mined.0, - nakamoto_blocks_rejected: naka_blocks_rejected.0, - nakamoto_blocks_signer_pushed: naka_signer_pushed_blocks.0, + vrfs_submitted, + commits_submitted, + blocks_processed, + nakamoto_blocks_proposed: naka_blocks_proposed, + nakamoto_blocks_mined: naka_blocks_mined, + nakamoto_blocks_rejected: naka_blocks_rejected, + nakamoto_blocks_signer_pushed: naka_signer_pushed_blocks, nakamoto_test_skip_commit_op, coord_channel, conf: naka_conf, diff --git a/testnet/stacks-node/src/tests/signer/v0.rs b/testnet/stacks-node/src/tests/signer/v0.rs index ef05f8e9cb..bac82e93ef 100644 --- a/testnet/stacks-node/src/tests/signer/v0.rs +++ b/testnet/stacks-node/src/tests/signer/v0.rs @@ -45,6 +45,7 @@ use stacks::net::api::postblock_proposal::{ use stacks::net::relay::fault_injection::set_ignore_block; use stacks::types::chainstate::{StacksAddress, StacksBlockId, StacksPrivateKey, StacksPublicKey}; use stacks::types::PublicKey; +use stacks::util::get_epoch_time_secs; use stacks::util::hash::{hex_bytes, Hash160, MerkleHashFunc, Sha512Trunc256Sum}; use stacks::util::secp256k1::{Secp256k1PrivateKey, Secp256k1PublicKey}; use stacks::util_lib::boot::boot_code_id; @@ -83,7 +84,9 @@ use crate::tests::neon_integrations::{ get_account, get_chain_info, get_chain_info_opt, next_block_and_wait, run_until_burnchain_height, submit_tx, submit_tx_fallible, test_observer, }; -use crate::tests::{self, gen_random_port, make_stacks_transfer}; +use crate::tests::{ + self, gen_random_port, make_contract_call, make_contract_publish, make_stacks_transfer, +}; use crate::{nakamoto_node, BitcoinRegtestController, BurnchainController, Config, Keychain}; impl SignerTest { @@ -2589,7 +2592,6 @@ fn tenure_extend_after_idle() { 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; }, |_| {}, @@ -2601,24 +2603,8 @@ fn tenure_extend_after_idle() { 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 @@ -2659,7 +2645,6 @@ fn stx_transfers_dont_effect_idle_timeout() { 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; }, |_| {}, @@ -2674,35 +2659,14 @@ fn stx_transfers_dont_effect_idle_timeout() { // 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); + let info_before = signer_test.get_peer_info(); + let blocks_before = signer_test.running_nodes.nakamoto_blocks_mined.get(); 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(); @@ -2726,29 +2690,7 @@ fn stx_transfers_dont_effect_idle_timeout() { 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); + let initial_acceptance = signer_test.get_latest_block_acceptance(slot_id); assert_eq!(initial_acceptance.signer_signature_hash, last_block_hash); info!( @@ -2765,30 +2707,20 @@ fn stx_transfers_dont_effect_idle_timeout() { 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"); + signer_test.wait_for_nakamoto_block(30, || { + 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 latest_acceptance = get_last_block_response(slot_id); + let latest_acceptance = signer_test.get_latest_block_acceptance(slot_id); let last_block_hash = get_last_block_hash(); assert_eq!(latest_acceptance.signer_signature_hash, last_block_hash); @@ -2813,6 +2745,263 @@ fn stx_transfers_dont_effect_idle_timeout() { signer_test.shutdown(); } +#[test] +#[ignore] +/// Verify that a tenure extend will occur after an idle timeout +/// while actively mining. +fn idle_tenure_extend_active_mining() { + 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 deployer_sk = Secp256k1PrivateKey::new(); + let deployer_addr = tests::to_addr(&deployer_sk); + let send_amt = 100; + let send_fee = 180; + let num_txs = 5; + let num_naka_blocks = 5; + let tenure_count = 2; + let tx_fee = 10000; + let deploy_fee = 190200; + let amount = + deploy_fee + tx_fee * num_txs * tenure_count * num_naka_blocks * 100 + 100 * tenure_count; + let recipient = PrincipalData::from(StacksAddress::burn_address(false)); + let idle_timeout = Duration::from_secs(60); + let mut signer_test: SignerTest = SignerTest::new_with_config_modifications( + num_signers, + vec![(sender_addr, amount), (deployer_addr, amount)], + |config| { + 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); + let mut sender_nonces: HashMap = HashMap::new(); + + let get_and_increment_nonce = + |sender_sk: &Secp256k1PrivateKey, sender_nonces: &mut HashMap| { + let nonce = sender_nonces.get(&sender_sk.to_hex()).unwrap_or(&0); + let result = *nonce; + sender_nonces.insert(sender_sk.to_hex(), result + 1); + result + }; + + signer_test.boot_to_epoch_3(); + + // Add a delay to the block validation process + TEST_VALIDATE_DELAY_DURATION_SECS.lock().unwrap().replace(3); + + signer_test.mine_nakamoto_block(Duration::from_secs(30)); + + info!("---- Getting current idle timeout ----"); + + 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_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 log_idle_diff = |timestamp: u64| { + let now = get_epoch_time_secs(); + let diff = timestamp.saturating_sub(now); + info!("----- Idle diff: {diff} seconds -----"); + }; + + let initial_response = signer_test.get_latest_block_response(slot_id); + assert_eq!( + initial_response.get_signer_signature_hash(), + last_block_hash + ); + + info!( + "---- Last idle timeout: {} ----", + initial_response.get_tenure_extend_timestamp() + ); + + // Deploy a contract that will be called a lot + + let contract_src = format!( + r#" +(define-data-var my-var uint u0) +(define-public (f) (begin {} (ok 1))) (begin (f)) + "#, + (0..250) + .map(|_| format!("(var-get my-var)")) + .collect::>() + .join(" ") + ); + + // First, lets deploy the contract + let deployer_nonce = get_and_increment_nonce(&deployer_sk, &mut sender_nonces); + let contract_tx = make_contract_publish( + &deployer_sk, + deployer_nonce, + deploy_fee, + naka_conf.burnchain.chain_id, + "small-contract", + &contract_src, + ); + submit_tx(&http_origin, &contract_tx); + + info!("----- Submitted deploy txs, mining BTC block -----"); + + signer_test.mine_nakamoto_block(Duration::from_secs(30)); + let mut last_response = signer_test.get_latest_block_response(slot_id); + + // Make multiple tenures that get extended through idle timeouts + for t in 1..=tenure_count { + info!("----- Mining tenure {t} -----"); + log_idle_diff(last_response.get_tenure_extend_timestamp()); + // Now, start a tenure with contract calls + for i in 1..=num_naka_blocks { + // Just in case these Nakamoto blocks pass the idle timeout (probably because CI is slow), exit early + if i != 1 && last_block_contains_tenure_change_tx(TenureChangeCause::Extended) { + info!("---- Tenure extended before mining {i} nakamoto blocks -----"); + break; + } + info!("----- Mining nakamoto block {i} in tenure {t} -----"); + + signer_test.wait_for_nakamoto_block(30, || { + // Throw in a STX transfer to test mixed blocks + let sender_nonce = get_and_increment_nonce(&sender_sk, &mut sender_nonces); + 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); + + for _ in 0..num_txs { + let deployer_nonce = get_and_increment_nonce(&deployer_sk, &mut sender_nonces); + // Fill up the mempool with contract calls + let contract_tx = make_contract_call( + &deployer_sk, + deployer_nonce, + tx_fee, + naka_conf.burnchain.chain_id, + &deployer_addr, + "small-contract", + "f", + &[], + ); + match submit_tx_fallible(&http_origin, &contract_tx) { + Ok(_txid) => {} + Err(_e) => { + // If we fail to submit a tx, we need to make sure we don't + // increment the nonce for this sender, so we don't end up + // skipping a tx. + sender_nonces.insert(deployer_sk.to_hex(), deployer_nonce); + } + } + } + }); + let latest_response = signer_test.get_latest_block_response(slot_id); + let naka_blocks = test_observer::get_mined_nakamoto_blocks(); + info!( + "----- Latest tenure extend timestamp: {} -----", + latest_response.get_tenure_extend_timestamp() + ); + log_idle_diff(latest_response.get_tenure_extend_timestamp()); + info!( + "----- Latest block transaction events: {} -----", + naka_blocks.last().unwrap().tx_events.len() + ); + assert_eq!( + latest_response.get_signer_signature_hash(), + get_last_block_hash(), + "Expected the latest block response to be for the latest block" + ); + assert_ne!( + last_response.get_tenure_extend_timestamp(), + latest_response.get_tenure_extend_timestamp(), + "Tenure extend timestamp should change with each block" + ); + last_response = latest_response; + } + + let current_time = get_epoch_time_secs(); + let extend_diff = last_response + .get_tenure_extend_timestamp() + .saturating_sub(current_time); + + info!( + "----- After mining {num_naka_blocks} nakamoto blocks in tenure {t}, waiting for TenureExtend -----"; + "tenure_extend_timestamp" => last_response.get_tenure_extend_timestamp(), + "extend_diff" => extend_diff, + "current_time" => current_time, + ); + + // Now, wait for the idle timeout to trigger + wait_for(extend_diff + 30, || { + Ok(last_block_contains_tenure_change_tx( + TenureChangeCause::Extended, + )) + }) + .expect("Expected a tenure extend after idle timeout"); + + last_response = signer_test.get_latest_block_response(slot_id); + + info!("----- Tenure {t} extended -----"); + log_idle_diff(last_response.get_tenure_extend_timestamp()); + } + + // After the last extend, mine a few more naka blocks + for i in 1..=num_naka_blocks { + // Just in case these Nakamoto blocks pass the idle timeout (probably because CI is slow), exit early + if i != 1 && last_block_contains_tenure_change_tx(TenureChangeCause::Extended) { + info!("---- Tenure extended before mining {i} nakamoto blocks -----"); + break; + } + info!("----- Mining nakamoto block {i} after last tenure extend -----"); + + signer_test.wait_for_nakamoto_block(30, || { + // Throw in a STX transfer to test mixed blocks + let sender_nonce = get_and_increment_nonce(&sender_sk, &mut sender_nonces); + 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); + }); + } + + info!("------------------------- Test Shutdown -------------------------"); + signer_test.shutdown(); +} + #[test] #[ignore] /// This test checks the behaviour of signers when a sortition is empty. Specifically: