From d67b3b641d2a9bb5680c91cd3281bddf40670c42 Mon Sep 17 00:00:00 2001 From: Arya Date: Sun, 5 Feb 2023 17:18:18 -0500 Subject: [PATCH] removes excessive logs, adds docs. (#6102) --- .../get_block_template.rs | 64 ++++++++----------- 1 file changed, 28 insertions(+), 36 deletions(-) diff --git a/zebrad/tests/common/get_block_template_rpcs/get_block_template.rs b/zebrad/tests/common/get_block_template_rpcs/get_block_template.rs index fc284aa1..c913b8a6 100644 --- a/zebrad/tests/common/get_block_template_rpcs/get_block_template.rs +++ b/zebrad/tests/common/get_block_template_rpcs/get_block_template.rs @@ -25,22 +25,34 @@ use crate::common::{ test_type::TestType, }; -/// How long the test waits for the mempool to download and verify transactions. -/// -/// We've seen it take anywhere from 1-45 seconds for the mempool to have some transactions in it. -pub const EXPECTED_MEMPOOL_TRANSACTION_TIME: Duration = Duration::from_secs(45); - /// Delay between getting block proposal results and cancelling long poll requests. +/// +/// This ensures that a new template can be deserialized and sent to interrupt the +/// block proposal requests if the old template is no longer valid in edge-cases where +/// an old template becomes invalid right after it's returned. We've seen the getblocktemplate +/// respond within ~50ms of a request locallly, and this test is run on GCP compute instances +/// that should offer comparable latency in CI. pub const EXTRA_LONGPOLL_WAIT_TIME: Duration = Duration::from_millis(150); /// Delay between attempts to validate a template as block proposals. /// /// Running many iterations in short intervals tests that long poll requests correctly /// return `submit_old: false` when the old template becomes invalid. -pub const BLOCK_PROPOSAL_INTERVAL: Duration = Duration::from_millis(300); +/// +/// We've seen a typical call to `try_validate_block_template` take ~900ms, a minimum +/// spacing of 1s ensures that this test samples various chain states and mempool contents. +pub const BLOCK_PROPOSAL_INTERVAL: Duration = Duration::from_secs(1); /// Number of times we want to try submitting a block template as a block proposal at an interval /// that allows testing the varying mempool contents. +/// +/// We usually see at least 1 template with a `submit_old` of false from a long poll request +/// with 1000 `try_validate_block_template` calls. +/// +/// The block proposal portion of this test should take ~18 minutes for 1000 iterations at +/// an interval of 1s. +/// +/// See [`BLOCK_PROPOSAL_INTERVAL`] for more information. const NUM_SUCCESSFUL_BLOCK_PROPOSALS_REQUIRED: usize = 1000; /// Launch Zebra, wait for it to sync, and check the getblocktemplate RPC returns without errors. @@ -102,22 +114,7 @@ pub(crate) async fn run() -> Result<()> { assert!(is_response_success); - tokio::time::sleep(EXPECTED_MEMPOOL_TRANSACTION_TIME).await; - for _ in 0..NUM_SUCCESSFUL_BLOCK_PROPOSALS_REQUIRED { - tracing::info!( - "waiting {EXPECTED_MEMPOOL_TRANSACTION_TIME:?} for the mempool \ - to download and verify some transactions...", - ); - - tokio::time::sleep(BLOCK_PROPOSAL_INTERVAL).await; - - tracing::info!( - "calling getblocktemplate RPC method at {rpc_address}, \ - with a mempool that likely has transactions and attempting \ - to validate response result as a block proposal", - ); - let (validation_result, _) = futures::future::join( try_validate_block_template(&client), tokio::time::sleep(BLOCK_PROPOSAL_INTERVAL), @@ -202,23 +199,16 @@ async fn try_validate_block_template(client: &RPCRequestClient) -> Result<()> { }; loop { - tracing::info!( - ?response_json_result, - "got getblocktemplate response, hopefully with transactions" - ); - let mut proposal_requests = vec![]; for time_source in TimeSource::valid_sources() { // Propose a new block with an empty solution and nonce field - tracing::info!( - "calling getblocktemplate with a block proposal and time source {time_source:?}...", - ); let raw_proposal_block = hex::encode( proposal_block_from_template(&response_json_result, time_source)? .zcash_serialize_to_vec()?, ); + let template = response_json_result.clone(); proposal_requests.push(async move { ( @@ -228,6 +218,7 @@ async fn try_validate_block_template(client: &RPCRequestClient) -> Result<()> { format!(r#"[{{"mode":"proposal","data":"{raw_proposal_block}"}}]"#), ) .await, + template, time_source, ) }); @@ -249,17 +240,18 @@ async fn try_validate_block_template(client: &RPCRequestClient) -> Result<()> { results }) => { let _ = done_tx.send(()).await; - for (proposal_result, time_source) in proposal_results { + for (proposal_result, template, time_source) in proposal_results { let proposal_result = proposal_result .expect("response should be success output with with a serialized `ProposalResponse`"); - tracing::info!( - ?proposal_result, - ?time_source, - "got getblocktemplate proposal response" - ); - if let ProposalResponse::Rejected(reject_reason) = proposal_result { + tracing::info!( + ?reject_reason, + ?template, + ?time_source, + "failed to validate template as a block proposal" + ); + Err(eyre!( "unsuccessful block proposal validation, reason: {reject_reason:?}" ))?;