From fd09625cd4febaa716da8e024ea1cb0d08aa2352 Mon Sep 17 00:00:00 2001 From: Aaron Blankstein Date: Fri, 31 Jan 2025 07:40:26 -0600 Subject: [PATCH 1/6] test: fix flake in multiple_miners_empty_sortition --- testnet/stacks-node/src/tests/signer/v0.rs | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/testnet/stacks-node/src/tests/signer/v0.rs b/testnet/stacks-node/src/tests/signer/v0.rs index 2e71cb8910..30b61477cd 100644 --- a/testnet/stacks-node/src/tests/signer/v0.rs +++ b/testnet/stacks-node/src/tests/signer/v0.rs @@ -11737,13 +11737,17 @@ fn multiple_miners_empty_sortition() { // lets mine a btc flash block let rl2_commits_before = rl2_commits.load(Ordering::SeqCst); let rl1_commits_before = rl1_commits.load(Ordering::SeqCst); + let info_before = get_chain_info(&conf); + signer_test .running_nodes .btc_regtest_controller .build_next_block(2); wait_for(60, || { - Ok(rl2_commits.load(Ordering::SeqCst) > rl2_commits_before + let info = get_chain_info(&conf); + Ok(info.burn_block_height >= 2 + info_before.burn_block_height + && rl2_commits.load(Ordering::SeqCst) > rl2_commits_before && rl1_commits.load(Ordering::SeqCst) > rl1_commits_before) }) .unwrap(); From 3ea5c858fa3d089095cd45bf737141c4e6c646c5 Mon Sep 17 00:00:00 2001 From: Aaron Blankstein Date: Fri, 31 Jan 2025 09:15:06 -0600 Subject: [PATCH 2/6] test: refactor nakamoto tests to use better wait-for-commit logic --- .../src/tests/nakamoto_integrations.rs | 374 +++++------------- testnet/stacks-node/src/tests/signer/mod.rs | 13 +- testnet/stacks-node/src/tests/signer/v0.rs | 49 ++- 3 files changed, 120 insertions(+), 316 deletions(-) diff --git a/testnet/stacks-node/src/tests/nakamoto_integrations.rs b/testnet/stacks-node/src/tests/nakamoto_integrations.rs index 71775742d0..0c60902fa0 100644 --- a/testnet/stacks-node/src/tests/nakamoto_integrations.rs +++ b/testnet/stacks-node/src/tests/nakamoto_integrations.rs @@ -728,14 +728,14 @@ pub fn next_block_and_process_new_stacks_block( pub fn next_block_and_mine_commit( btc_controller: &mut BitcoinRegtestController, timeout_secs: u64, - coord_channels: &Arc>, - commits_submitted: &Arc, + node_conf: &Config, + node_counters: &Counters, ) -> Result<(), String> { next_block_and_wait_for_commits( btc_controller, timeout_secs, - &[coord_channels], - &[commits_submitted], + &[node_conf], + &[node_counters], true, ) } @@ -745,14 +745,14 @@ pub fn next_block_and_mine_commit( pub fn next_block_and_commits_only( btc_controller: &mut BitcoinRegtestController, timeout_secs: u64, - coord_channels: &Arc>, - commits_submitted: &Arc, + node_conf: &Config, + node_counters: &Counters, ) -> Result<(), String> { next_block_and_wait_for_commits( btc_controller, timeout_secs, - &[coord_channels], - &[commits_submitted], + &[node_conf], + &[node_counters], false, ) } @@ -765,98 +765,48 @@ pub fn next_block_and_commits_only( pub fn next_block_and_wait_for_commits( btc_controller: &mut BitcoinRegtestController, timeout_secs: u64, - coord_channels: &[&Arc>], - commits_submitted: &[&Arc], + node_confs: &[&Config], + node_counters: &[&Counters], wait_for_stacks_block: bool, ) -> Result<(), String> { - let commits_submitted: Vec<_> = commits_submitted.to_vec(); - let blocks_processed_before: Vec<_> = coord_channels + let infos_before: Vec<_> = node_confs.iter().map(|c| get_chain_info(c)).collect(); + let burn_ht_before = infos_before .iter() - .map(|x| { - x.lock() - .expect("Mutex poisoned") - .get_stacks_blocks_processed() - }) + .map(|info| info.burn_block_height) + .max() + .unwrap(); + let stacks_ht_before = infos_before + .iter() + .map(|info| info.stacks_tip_height) + .max() + .unwrap(); + let last_commit_burn_hts: Vec<_> = node_counters + .iter() + .map(|c| &c.naka_submitted_commit_last_burn_height) .collect(); - let commits_before: Vec<_> = commits_submitted + let last_commit_stacks_hts: Vec<_> = node_counters .iter() - .map(|x| x.load(Ordering::SeqCst)) + .map(|c| &c.naka_submitted_commit_last_stacks_tip) .collect(); - let mut block_processed_time: Vec> = vec![None; commits_before.len()]; - let mut commit_sent_time: Vec> = vec![None; commits_before.len()]; next_block_and(btc_controller, timeout_secs, || { - for i in 0..commits_submitted.len() { - let commits_sent = commits_submitted[i].load(Ordering::SeqCst); - let blocks_processed = coord_channels[i] - .lock() - .expect("Mutex poisoned") - .get_stacks_blocks_processed(); - let now = Instant::now(); - if blocks_processed > blocks_processed_before[i] && block_processed_time[i].is_none() { - block_processed_time[i].replace(now); - } - if commits_sent > commits_before[i] && commit_sent_time[i].is_none() { - commit_sent_time[i].replace(now); - } - } - + let burn_height_committed_to = last_commit_burn_hts.iter().all(|last_commit_burn_height| { + last_commit_burn_height.load(Ordering::SeqCst) > burn_ht_before + }); if !wait_for_stacks_block { - for i in 0..commits_submitted.len() { - // just wait for the commit - let commits_sent = commits_submitted[i].load(Ordering::SeqCst); - if commits_sent <= commits_before[i] { - return Ok(false); - } - - // if two commits have been sent, one of them must have been after - if commits_sent >= commits_before[i] + 1 { - continue; - } - return Ok(false); - } - return Ok(true); - } - - // waiting for both commit and stacks block - for i in 0..commits_submitted.len() { - let blocks_processed = coord_channels[i] - .lock() - .expect("Mutex poisoned") - .get_stacks_blocks_processed(); - let commits_sent = commits_submitted[i].load(Ordering::SeqCst); - - if blocks_processed > blocks_processed_before[i] { - // either we don't care about the stacks block count, or the block count advanced. - // Check the block-commits. - let block_processed_time = block_processed_time[i] - .as_ref() - .ok_or("TEST-ERROR: Processed block time wasn't set")?; - if commits_sent <= commits_before[i] { - return Ok(false); - } - let commit_sent_time = commit_sent_time[i] - .as_ref() - .ok_or("TEST-ERROR: Processed commit time wasn't set")?; - // try to ensure the commit was sent after the block was processed - if commit_sent_time > block_processed_time { - continue; - } - // if two commits have been sent, one of them must have been after - if commits_sent >= commits_before[i] + 2 { - continue; - } - // otherwise, just timeout if the commit was sent and its been long enough - // for a new commit pass to have occurred - if block_processed_time.elapsed() > Duration::from_secs(10) { - continue; - } - return Ok(false); - } else { + Ok(burn_height_committed_to) + } else { + if !burn_height_committed_to { return Ok(false); } + let stacks_tip_committed_to = + last_commit_stacks_hts + .iter() + .all(|last_commit_stacks_height| { + last_commit_stacks_height.load(Ordering::SeqCst) > stacks_ht_before + }); + return Ok(stacks_tip_committed_to); } - Ok(true) }) } @@ -1541,6 +1491,7 @@ fn simple_neon_integration() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let node_counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -1598,13 +1549,8 @@ fn simple_neon_integration() { // Mine 15 nakamoto tenures for _i in 0..15 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &node_counters) + .unwrap(); } // Submit a TX @@ -1652,13 +1598,8 @@ fn simple_neon_integration() { // Mine 15 more nakamoto tenures for _i in 0..15 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &node_counters) + .unwrap(); } // load the chain tip, and assert that it is a nakamoto block and at least 30 blocks have advanced in epoch 3 @@ -1794,17 +1735,17 @@ fn restarting_miner() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let rl1_counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); let mut run_loop_2 = boot_nakamoto::BootRunLoop::new(naka_conf.clone()).unwrap(); let _run_loop_2_stopper = run_loop.get_termination_switch(); let Counters { blocks_processed: blocks_processed_2, - naka_submitted_commits: commits_submitted_2, naka_proposed_blocks: proposals_submitted_2, .. } = run_loop_2.counters(); - let coord_channel_2 = run_loop_2.coordinator_channels(); + let rl2_counters = run_loop.counters(); let run_loop_thread = thread::spawn(move || run_loop.start(None, 0)); wait_for_runloop(&blocks_processed); @@ -1846,13 +1787,8 @@ fn restarting_miner() { // Mine 2 nakamoto tenures for _i in 0..2 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &rl1_counters) + .unwrap(); } let last_tip = NakamotoChainState::get_canonical_block_header(chainstate.db(), &sortdb) @@ -1915,13 +1851,8 @@ fn restarting_miner() { // Mine 2 more nakamoto tenures for _i in 0..2 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel_2, - &commits_submitted_2, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &rl2_counters) + .unwrap(); } // load the chain tip, and assert that it is a nakamoto block and at least 30 blocks have advanced in epoch 3 @@ -2020,6 +1951,7 @@ fn flash_blocks_on_epoch_3() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -2094,13 +2026,7 @@ fn flash_blocks_on_epoch_3() { // Mine 15 nakamoto tenures for _i in 0..15 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } // Submit a TX @@ -2136,13 +2062,7 @@ fn flash_blocks_on_epoch_3() { // Mine 15 more nakamoto tenures for _i in 0..15 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } // load the chain tip, and assert that it is a nakamoto block and at least 30 blocks have advanced in epoch 3 @@ -2719,6 +2639,7 @@ fn correct_burn_outs() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -2891,12 +2812,9 @@ fn correct_burn_outs() { let prior_tip = SortitionDB::get_canonical_burn_chain_tip(sortdb.conn()) .unwrap() .block_height; - if let Err(e) = next_block_and_mine_commit( - &mut btc_regtest_controller, - 30, - &coord_channel, - &commits_submitted, - ) { + if let Err(e) = + next_block_and_mine_commit(&mut btc_regtest_controller, 30, &naka_conf, &counters) + { warn!( "Error while minting a bitcoin block and waiting for stacks-node activity: {e:?}" ); @@ -3036,6 +2954,7 @@ fn block_proposal_api_endpoint() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -3076,13 +2995,7 @@ fn block_proposal_api_endpoint() { // Mine 3 nakamoto tenures for _ in 0..3 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &conf, &counters).unwrap(); } // TODO (hack) instantiate the sortdb in the burnchain @@ -3414,6 +3327,7 @@ fn miner_writes_proposed_block_to_stackerdb() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -3434,13 +3348,7 @@ fn miner_writes_proposed_block_to_stackerdb() { wait_for_first_naka_block_commit(60, &commits_submitted); // Mine 1 nakamoto tenure - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); let sortdb = naka_conf.get_burnchain().open_sortition_db(true).unwrap(); @@ -3525,6 +3433,7 @@ fn vote_for_aggregate_key_burn_op() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -3607,13 +3516,7 @@ fn vote_for_aggregate_key_burn_op() { ); for _i in 0..(blocks_until_prepare) { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } let reward_cycle = reward_cycle + 1; @@ -3663,13 +3566,7 @@ fn vote_for_aggregate_key_burn_op() { // the second block should process the vote, after which the vote should be set for _i in 0..2 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } let mut vote_for_aggregate_key_found = false; @@ -4631,6 +4528,7 @@ fn burn_ops_integration_test() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -4682,13 +4580,7 @@ fn burn_ops_integration_test() { "Pre-stx operation should submit successfully" ); - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); let mut miner_signer_2 = Keychain::default(naka_conf.node.seed.clone()).generate_op_signer(); info!("Submitting second pre-stx op"); @@ -4816,13 +4708,7 @@ fn burn_ops_integration_test() { ); for _i in 0..(blocks_until_prepare) { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } let reward_cycle = reward_cycle + 1; @@ -4979,13 +4865,7 @@ fn burn_ops_integration_test() { // the second block should process the ops // Also mine 2 interim blocks to ensure the stack-stx ops are not processed in them for _i in 0..2 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); for interim_block_ix in 0..2 { info!("Mining interim block {interim_block_ix}"); let blocks_processed_before = coord_channel @@ -6032,6 +5912,7 @@ fn nakamoto_attempt_time() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -6071,13 +5952,7 @@ fn nakamoto_attempt_time() { // Mine 3 nakamoto tenures for _ in 0..3 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } // TODO (hack) instantiate the sortdb in the burnchain @@ -6603,6 +6478,7 @@ fn signer_chainstate() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -6680,13 +6556,7 @@ fn signer_chainstate() { // hold the first and last blocks of the first tenure. we'll use this to submit reorging proposals let mut first_tenure_blocks: Option> = None; for i in 0..15 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); // this config disallows any reorg due to poorly timed block commits let proposal_conf = ProposalEvalConfig { @@ -7197,6 +7067,7 @@ fn continue_tenure_extend() { naka_skip_commit_op: test_skip_commit_op, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -7258,13 +7129,7 @@ fn continue_tenure_extend() { wait_for_first_naka_block_commit(60, &commits_submitted); // Mine a regular nakamoto tenure - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); wait_for(5, || { let blocks_processed = coord_channel @@ -8728,6 +8593,7 @@ fn check_block_info_rewards() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -8926,13 +8792,7 @@ fn check_block_info_rewards() { // (only 2 blocks maturation time in tests) info!("Mining 6 tenures to mature the block reward"); for i in 0..6 { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 20, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 20, &naka_conf, &counters).unwrap(); info!("Mined a block ({i})"); } @@ -9498,10 +9358,10 @@ fn v3_signer_api_endpoint() { let run_loop_stopper = run_loop.get_termination_switch(); let Counters { blocks_processed, - naka_submitted_commits: commits_submitted, naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -9562,13 +9422,7 @@ fn v3_signer_api_endpoint() { // Mine some nakamoto tenures for _i in 0..naka_tenures { - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &conf, &counters).unwrap(); } let block_height = btc_regtest_controller.get_headers_height(); let reward_cycle = btc_regtest_controller @@ -9674,7 +9528,7 @@ fn v3_blockbyheight_api_endpoint() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); - + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); let run_loop_thread = thread::spawn(move || run_loop.start(None, 0)); @@ -9696,13 +9550,7 @@ fn v3_blockbyheight_api_endpoint() { wait_for_first_naka_block_commit(60, &commits_submitted); // Mine 1 nakamoto tenure - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &conf, &counters).unwrap(); let burnchain = conf.get_burnchain(); let sortdb = burnchain.open_sortition_db(true).unwrap(); @@ -9797,11 +9645,10 @@ fn nakamoto_lockup_events() { let run_loop_stopper = run_loop.get_termination_switch(); let Counters { blocks_processed, - naka_submitted_commits: commits_submitted, naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); - + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); let run_loop_thread = thread::spawn(move || run_loop.start(None, 0)); @@ -9832,13 +9679,7 @@ fn nakamoto_lockup_events() { info!("------------------------- Setup finished, run test -------------------------"); - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &conf, &counters).unwrap(); let http_origin = format!("http://{}", &conf.node.rpc_bind); @@ -9982,6 +9823,7 @@ fn skip_mining_long_tx() { naka_mined_blocks: mined_naka_blocks, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -10020,13 +9862,7 @@ fn skip_mining_long_tx() { // Mine a few nakamoto tenures with some interim blocks in them for i in 0..5 { let mined_before = mined_naka_blocks.load(Ordering::SeqCst); - next_block_and_mine_commit( - &mut btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); if i == 0 { // we trigger the nakamoto miner to evaluate the long running transaction, @@ -10134,17 +9970,10 @@ fn test_shadow_recovery() { let naka_conf = signer_test.running_nodes.conf.clone(); let btc_regtest_controller = &mut signer_test.running_nodes.btc_regtest_controller; - let coord_channel = signer_test.running_nodes.coord_channel.clone(); - let commits_submitted = signer_test.running_nodes.commits_submitted.clone(); + let counters = signer_test.running_nodes.counters.clone(); // make another tenure - next_block_and_mine_commit( - btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); let block_height = btc_regtest_controller.get_headers_height(); let reward_cycle = btc_regtest_controller @@ -10219,13 +10048,7 @@ fn test_shadow_recovery() { } // make another tenure - next_block_and_mine_commit( - btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); // all shadow blocks are present and processed let mut shadow_ids = HashSet::new(); @@ -10950,6 +10773,7 @@ fn test_tenure_extend_from_flashblocks() { let coord_channel = signer_test.running_nodes.coord_channel.clone(); let commits_submitted = signer_test.running_nodes.commits_submitted.clone(); let sortitions_processed = signer_test.running_nodes.sortitions_processed.clone(); + let counters = signer_test.running_nodes.counters.clone(); let nakamoto_test_skip_commit_op = signer_test .running_nodes .nakamoto_test_skip_commit_op @@ -10969,13 +10793,7 @@ fn test_tenure_extend_from_flashblocks() { .unwrap(); for _ in 0..3 { - next_block_and_mine_commit( - btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } let burn_view_contract = r#" @@ -11021,24 +10839,12 @@ fn test_tenure_extend_from_flashblocks() { }) .expect("Timed out waiting for interim blocks to be mined"); - next_block_and_mine_commit( - btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_mine_commit(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); // stall miner and relayer // make tenure but don't wait for a stacks block - next_block_and_commits_only( - btc_regtest_controller, - 60, - &coord_channel, - &commits_submitted, - ) - .unwrap(); + next_block_and_commits_only(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); // prevent the mienr from sending another block-commit nakamoto_test_skip_commit_op.set(true); diff --git a/testnet/stacks-node/src/tests/signer/mod.rs b/testnet/stacks-node/src/tests/signer/mod.rs index 1bf57444ed..6b355fe5aa 100644 --- a/testnet/stacks-node/src/tests/signer/mod.rs +++ b/testnet/stacks-node/src/tests/signer/mod.rs @@ -336,15 +336,14 @@ impl + Send + 'static, T: SignerEventTrait + 'static> SignerTest + Send + 'static, T: SignerEventTrait + 'static> SignerTest>], - commits_submitted: &[&Arc], + node_confs: &[&NeonConfig], + node_counters: &[&Counters], timeout: Duration, ) { let blocks_len = test_observer::get_blocks().len(); @@ -370,8 +369,8 @@ impl + Send + 'static, T: SignerEventTrait + 'static> SignerTest rl1_commits_before) + let info = get_chain_info(&conf); + Ok(info.burn_block_height >= 2 + info_before.burn_block_height + && rl1_commits.load(Ordering::SeqCst) > rl1_commits_before) }) .unwrap(); From bbc6ab82cc6aa76954d38cb6b0907eaa91204201 Mon Sep 17 00:00:00 2001 From: Aaron Blankstein Date: Fri, 31 Jan 2025 10:52:45 -0600 Subject: [PATCH 3/6] fix revealed flake in restarting_miner and test_shadow_recovery --- .../stacks-node/src/tests/nakamoto_integrations.rs | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/testnet/stacks-node/src/tests/nakamoto_integrations.rs b/testnet/stacks-node/src/tests/nakamoto_integrations.rs index 0c60902fa0..3a75e6b630 100644 --- a/testnet/stacks-node/src/tests/nakamoto_integrations.rs +++ b/testnet/stacks-node/src/tests/nakamoto_integrations.rs @@ -1745,7 +1745,7 @@ fn restarting_miner() { naka_proposed_blocks: proposals_submitted_2, .. } = run_loop_2.counters(); - let rl2_counters = run_loop.counters(); + let rl2_counters = run_loop_2.counters(); let run_loop_thread = thread::spawn(move || run_loop.start(None, 0)); wait_for_runloop(&blocks_processed); @@ -1832,13 +1832,16 @@ fn restarting_miner() { let tip = NakamotoChainState::get_canonical_block_header(chainstate.db(), &sortdb) .unwrap() .unwrap(); - Ok(tip.stacks_block_height > last_tip.stacks_block_height) + let stacks_tip_committed_to = rl2_counters + .naka_submitted_commit_last_stacks_tip + .load(Ordering::SeqCst); + Ok(tip.stacks_block_height > last_tip.stacks_block_height + && stacks_tip_committed_to > last_tip.stacks_block_height) }) .unwrap_or_else(|e| { let tip = NakamotoChainState::get_canonical_block_header(chainstate.db(), &sortdb) .unwrap() .unwrap(); - error!( "Failed to get a new block after restart"; "last_tip_height" => last_tip.stacks_block_height, @@ -10043,8 +10046,7 @@ fn test_shadow_recovery() { // revive ATC-C by waiting for commits for _i in 0..4 { - btc_regtest_controller.bootstrap_chain(1); - sleep_ms(30_000); + next_block_and_commits_only(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); } // make another tenure From 60634c20c0392e30f812d5e942fe4a5721435e5d Mon Sep 17 00:00:00 2001 From: Aaron Blankstein Date: Fri, 31 Jan 2025 12:03:43 -0600 Subject: [PATCH 4/6] fix flake in check_block_times --- .../src/tests/nakamoto_integrations.rs | 49 ++++++++----------- 1 file changed, 20 insertions(+), 29 deletions(-) diff --git a/testnet/stacks-node/src/tests/nakamoto_integrations.rs b/testnet/stacks-node/src/tests/nakamoto_integrations.rs index 3a75e6b630..f426995595 100644 --- a/testnet/stacks-node/src/tests/nakamoto_integrations.rs +++ b/testnet/stacks-node/src/tests/nakamoto_integrations.rs @@ -780,19 +780,18 @@ pub fn next_block_and_wait_for_commits( .map(|info| info.stacks_tip_height) .max() .unwrap(); - let last_commit_burn_hts: Vec<_> = node_counters + let last_commit_burn_hts = node_counters .iter() - .map(|c| &c.naka_submitted_commit_last_burn_height) - .collect(); - let last_commit_stacks_hts: Vec<_> = node_counters + .map(|c| &c.naka_submitted_commit_last_burn_height); + let last_commit_stacks_hts = node_counters .iter() - .map(|c| &c.naka_submitted_commit_last_stacks_tip) - .collect(); + .map(|c| &c.naka_submitted_commit_last_stacks_tip); next_block_and(btc_controller, timeout_secs, || { - let burn_height_committed_to = last_commit_burn_hts.iter().all(|last_commit_burn_height| { - last_commit_burn_height.load(Ordering::SeqCst) > burn_ht_before - }); + let burn_height_committed_to = + last_commit_burn_hts.clone().all(|last_commit_burn_height| { + last_commit_burn_height.load(Ordering::SeqCst) > burn_ht_before + }); if !wait_for_stacks_block { Ok(burn_height_committed_to) } else { @@ -801,7 +800,7 @@ pub fn next_block_and_wait_for_commits( } let stacks_tip_committed_to = last_commit_stacks_hts - .iter() + .clone() .all(|last_commit_stacks_height| { last_commit_stacks_height.load(Ordering::SeqCst) > stacks_ht_before }); @@ -7564,6 +7563,7 @@ fn check_block_times() { naka_proposed_blocks: proposals_submitted, .. } = run_loop.counters(); + let counters = run_loop.counters(); let coord_channel = run_loop.coordinator_channels(); @@ -7606,19 +7606,13 @@ fn check_block_times() { info!("Nakamoto miner started..."); blind_signer(&naka_conf, &signers, proposals_submitted); + wait_for_first_naka_block_commit(60, &counters.naka_submitted_commits); - let epochs = naka_conf.burnchain.epochs.clone().unwrap(); - let epoch_3 = &epochs[StacksEpochId::Epoch30]; - let epoch_3_start = epoch_3.start_height; - let mut last_stacks_block_height = 0; - let mut last_tenure_height = 0; - next_block_and(&mut btc_regtest_controller, 60, || { - let info = get_chain_info_result(&naka_conf).unwrap(); - last_stacks_block_height = info.stacks_tip_height as u128; - last_tenure_height = last_stacks_block_height + 1; - Ok(info.burn_block_height == epoch_3_start) - }) - .unwrap(); + let info = get_chain_info_result(&naka_conf).unwrap(); + let mut last_stacks_block_height = info.stacks_tip_height as u128; + let mut last_tenure_height = last_stacks_block_height + 1; + + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); let time0_value = call_read_only( &naka_conf, @@ -7676,16 +7670,13 @@ fn check_block_times() { Ok(stacks_block_height > last_stacks_block_height && cur_sender_nonce == sender_nonce) }) .expect("Timed out waiting for contracts to publish"); - last_stacks_block_height = stacks_block_height; // Repeat these tests for 5 tenures for _ in 0..5 { - next_block_and(&mut btc_regtest_controller, 60, || { - let info = get_chain_info_result(&naka_conf).unwrap(); - stacks_block_height = info.stacks_tip_height as u128; - Ok(stacks_block_height > last_stacks_block_height) - }) - .unwrap(); + next_block_and_mine_commit(&mut btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); + let info = get_chain_info_result(&naka_conf).unwrap(); + stacks_block_height = info.stacks_tip_height as u128; + last_stacks_block_height = stacks_block_height; last_tenure_height += 1; info!("New tenure {last_tenure_height}, Stacks height: {last_stacks_block_height}"); From fb2a70717b9544b542490cabd83927e96f201326 Mon Sep 17 00:00:00 2001 From: Aaron Blankstein Date: Fri, 31 Jan 2025 12:30:08 -0600 Subject: [PATCH 5/6] test: fix reward-cycle flake in multiple_miners_empty_sortition --- testnet/stacks-node/src/tests/signer/v0.rs | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/testnet/stacks-node/src/tests/signer/v0.rs b/testnet/stacks-node/src/tests/signer/v0.rs index fa4a6ec672..cf3b45656c 100644 --- a/testnet/stacks-node/src/tests/signer/v0.rs +++ b/testnet/stacks-node/src/tests/signer/v0.rs @@ -85,8 +85,9 @@ use crate::tests::nakamoto_integrations::{ POX_4_DEFAULT_STACKER_BALANCE, POX_4_DEFAULT_STACKER_STX_AMT, }; use crate::tests::neon_integrations::{ - get_account, get_chain_info, get_chain_info_opt, get_sortition_info, get_sortition_info_ch, - next_block_and_wait, run_until_burnchain_height, submit_tx, submit_tx_fallible, test_observer, + get_account, get_chain_info, get_chain_info_opt, get_pox_info, get_sortition_info, + get_sortition_info_ch, next_block_and_wait, run_until_burnchain_height, submit_tx, + submit_tx_fallible, test_observer, }; use crate::tests::{ self, gen_random_port, make_contract_call, make_contract_publish, make_stacks_transfer, @@ -11729,6 +11730,15 @@ fn multiple_miners_empty_sortition() { let last_active_sortition = get_sortition_info(&conf); assert!(last_active_sortition.was_sortition); + // check if we're about to cross a reward cycle boundary -- if so, we can't + // perform this test, because we can't tenure extend across the boundary + let pox_info = get_pox_info(&conf.node.data_url).unwrap(); + let blocks_until_next_cycle = pox_info.next_cycle.blocks_until_reward_phase; + if blocks_until_next_cycle == 1 { + info!("We're about to cross a reward cycle boundary, cannot perform a tenure extend here!"); + continue; + } + // lets mine a btc flash block let rl2_commits_before = rl2_commits.load(Ordering::SeqCst); let rl1_commits_before = rl1_commits.load(Ordering::SeqCst); From eb8e944862f0b876203cb5983725073edd41a1e5 Mon Sep 17 00:00:00 2001 From: Aaron Blankstein Date: Fri, 31 Jan 2025 13:42:27 -0600 Subject: [PATCH 6/6] test: fix flake in test_tenure_extend_from_flashblocks, bump default test retry sleep from 100ms to 500ms (less log spam in tests) --- .../src/tests/nakamoto_integrations.rs | 83 ++++--------------- 1 file changed, 16 insertions(+), 67 deletions(-) diff --git a/testnet/stacks-node/src/tests/nakamoto_integrations.rs b/testnet/stacks-node/src/tests/nakamoto_integrations.rs index f426995595..1ae369a17e 100644 --- a/testnet/stacks-node/src/tests/nakamoto_integrations.rs +++ b/testnet/stacks-node/src/tests/nakamoto_integrations.rs @@ -693,7 +693,7 @@ where error!("Timed out waiting for check to process"); return Err("Timed out".into()); } - thread::sleep(Duration::from_millis(100)); + thread::sleep(Duration::from_millis(500)); } Ok(()) } @@ -10764,8 +10764,6 @@ fn test_tenure_extend_from_flashblocks() { let http_origin = format!("http://{}", &naka_conf.node.rpc_bind); let btc_regtest_controller = &mut signer_test.running_nodes.btc_regtest_controller; let coord_channel = signer_test.running_nodes.coord_channel.clone(); - let commits_submitted = signer_test.running_nodes.commits_submitted.clone(); - let sortitions_processed = signer_test.running_nodes.sortitions_processed.clone(); let counters = signer_test.running_nodes.counters.clone(); let nakamoto_test_skip_commit_op = signer_test .running_nodes @@ -10818,17 +10816,9 @@ fn test_tenure_extend_from_flashblocks() { ); submit_tx(&http_origin, &contract_tx); - let blocks_processed_before = coord_channel - .lock() - .expect("Mutex poisoned") - .get_stacks_blocks_processed(); - wait_for(120, || { - let blocks_processed = coord_channel - .lock() - .expect("Mutex poisoned") - .get_stacks_blocks_processed(); - Ok(blocks_processed > blocks_processed_before) + let sender_nonce = get_account(&naka_conf.node.data_url, &deployer_addr).nonce; + Ok(sender_nonce > 0) }) .expect("Timed out waiting for interim blocks to be mined"); @@ -10836,39 +10826,23 @@ fn test_tenure_extend_from_flashblocks() { // stall miner and relayer - // make tenure but don't wait for a stacks block - next_block_and_commits_only(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); + // make tenure + next_block_and_mine_commit(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); - // prevent the mienr from sending another block-commit + // prevent the miner from sending another block-commit nakamoto_test_skip_commit_op.set(true); - // make sure we get a block-found tenure change - let blocks_processed_before = coord_channel - .lock() - .expect("Mutex poisoned") - .get_stacks_blocks_processed(); - - // make sure the relayer processes both sortitions - let sortitions_processed_before = sortitions_processed.load(Ordering::SeqCst); + let info_before = get_chain_info(&naka_conf); // mine another Bitcoin block right away, since it will contain a block-commit btc_regtest_controller.bootstrap_chain(1); - wait_for(60, || { - sleep_ms(100); - let sortitions_cnt = sortitions_processed.load(Ordering::SeqCst); - Ok(sortitions_cnt > sortitions_processed_before) - }) - .unwrap(); - wait_for(120, || { - let blocks_processed = coord_channel - .lock() - .expect("Mutex poisoned") - .get_stacks_blocks_processed(); - Ok(blocks_processed > blocks_processed_before) + let info = get_chain_info(&naka_conf); + Ok(info.burn_block_height > info_before.burn_block_height + && info.stacks_tip_height > info_before.stacks_tip_height) }) - .expect("Timed out waiting for interim blocks to be mined"); + .unwrap(); let (canonical_stacks_tip_ch, _) = SortitionDB::get_canonical_stacks_chain_tip_hash(sortdb.conn()).unwrap(); @@ -10895,11 +10869,9 @@ fn test_tenure_extend_from_flashblocks() { // Given the above, this will be an `Extend` tenure. TEST_MINER_THREAD_STALL.set(false); - let sortitions_processed_before = sortitions_processed.load(Ordering::SeqCst); wait_for(60, || { - sleep_ms(100); - let sortitions_cnt = sortitions_processed.load(Ordering::SeqCst); - Ok(sortitions_cnt > sortitions_processed_before) + let cur_sort_tip = SortitionDB::get_canonical_burn_chain_tip(sortdb.conn()).unwrap(); + Ok(cur_sort_tip.block_height > sort_tip.block_height) }) .unwrap(); @@ -10977,7 +10949,6 @@ fn test_tenure_extend_from_flashblocks() { // wait for the miner directive to be processed wait_for(60, || { - sleep_ms(30_000); let directives_cnt = nakamoto_miner_directives.load(Ordering::SeqCst); Ok(directives_cnt > miner_directives_before) }) @@ -10985,7 +10956,7 @@ fn test_tenure_extend_from_flashblocks() { // wait for all of the aforementioned transactions to get mined wait_for(120, || { - // fill mempool with transactions that depend on the burn view + // check account nonces from the sent transactions for (sender_sk, account_before) in account_keys.iter().zip(accounts_before.iter()) { let sender_addr = tests::to_addr(sender_sk); let account = loop { @@ -11042,28 +11013,7 @@ fn test_tenure_extend_from_flashblocks() { } // mine one additional tenure, to verify that we're on track - let commits_before = commits_submitted.load(Ordering::SeqCst); - let node_info_before = get_chain_info_opt(&naka_conf).unwrap(); - - btc_regtest_controller.bootstrap_chain(1); - - wait_for(20, || { - Ok(commits_submitted.load(Ordering::SeqCst) > commits_before) - }) - .unwrap(); - - // there was a sortition winner - let sort_tip = SortitionDB::get_canonical_burn_chain_tip(sortdb.conn()).unwrap(); - assert!(sort_tip.sortition); - - wait_for(20, || { - let node_info = get_chain_info_opt(&naka_conf).unwrap(); - Ok( - node_info.burn_block_height > node_info_before.burn_block_height - && node_info.stacks_tip_height > node_info_before.stacks_tip_height, - ) - }) - .unwrap(); + next_block_and_mine_commit(btc_regtest_controller, 60, &naka_conf, &counters).unwrap(); // boot a follower. it should reach the chain tip info!("----- BEGIN FOLLOWR BOOTUP ------"); @@ -11118,9 +11068,8 @@ fn test_tenure_extend_from_flashblocks() { debug!("Booted follower-thread"); - let miner_info = get_chain_info_result(&naka_conf).unwrap(); - wait_for(300, || { + let miner_info = get_chain_info_result(&naka_conf).unwrap(); let Ok(info) = get_chain_info_result(&follower_conf) else { sleep_ms(1000); return Ok(false);