diff --git a/.github/workflows/bitcoin-tests.yml b/.github/workflows/bitcoin-tests.yml index eac32cdfc4..baf6e91d17 100644 --- a/.github/workflows/bitcoin-tests.yml +++ b/.github/workflows/bitcoin-tests.yml @@ -62,6 +62,7 @@ jobs: - tests::neon_integrations::fuzzed_median_fee_rate_estimation_test_window5 - tests::neon_integrations::fuzzed_median_fee_rate_estimation_test_window10 - tests::neon_integrations::use_latest_tip_integration_test + - tests::neon_integrations::test_flash_block_skip_tenure - tests::epoch_205::test_dynamic_db_method_costs - tests::epoch_205::transition_empty_blocks - tests::epoch_205::test_cost_limit_switch_version205 diff --git a/CHANGELOG.md b/CHANGELOG.md index 8d3794ff07..a988a664d3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -47,6 +47,22 @@ and this project adheres to the versioning scheme outlined in the [README.md](RE sync, the p2p state machine will immediately transition from the inventory sync work state to the block downloader work state, and immediately proceed to fetch the available block or microblock stream. (#2862) +- Nodes will push recently-obtained blocks and microblock streams to outbound + neighbors if their cached inventories indicate that they do not yet have them +(#2986). +- Nodes will no longer perform full inventory scans on their peers, except + during boot-up, in a bid to minimize block-download stalls (#2986). +- Nodes will process sortitions in parallel to downloading the Stacks blocks for + a reward cycle, instead of doing these tasks sequentially (#2986). +- The node's runloop will coalesce and expire stale requests to mine blocks on + top of parent blocks that are no longer the chain tip (#2969). +- Several database indexes have been updated to avoid table scans, which + significantly improves most RPC endpoint speed and cuts node spin-up time in +half (#2989, #3005). +- Fixed a rare denial-of-service bug whereby a node that processes a very deep + burnchain reorg can get stuck, and be rendered unable to process further +sortitions. This has never happened in production, but it can be replicated in +tests (#2989). ### Fixed - Updates the lookup key for contracts in the pessimistic cost estimator. Before, contracts diff --git a/README.md b/README.md index d0531e9a4f..d9f5146f60 100644 --- a/README.md +++ b/README.md @@ -337,12 +337,14 @@ wait_time_for_microblocks = 10000 [miner] # Smallest allowed tx fee, in microSTX min_tx_fee = 100 -# Time to spend on the first attempt to make a block. +# Time to spend on the first attempt to make a block, in milliseconds. # This can be small, so your node gets a block-commit into the Bitcoin mempool early. -first_attempt_time_ms: 1000 -# Time to spend on subsequent attempts to make a block. +first_attempt_time_ms = 1000 +# Time to spend on subsequent attempts to make a block, in milliseconds. # This can be bigger -- new block-commits will be RBF'ed. -subsequent_attempt_time_ms: 60000 +subsequent_attempt_time_ms = 60000 +# Time to spend mining a microblock, in milliseconds. +microblock_attempt_time_ms = 30000 ``` You can verify that your node is operating as a miner by checking its log output diff --git a/src/burnchains/bitcoin/indexer.rs b/src/burnchains/bitcoin/indexer.rs index 56e79aae96..8f68901134 100644 --- a/src/burnchains/bitcoin/indexer.rs +++ b/src/burnchains/bitcoin/indexer.rs @@ -370,6 +370,14 @@ impl BitcoinIndexer { true, false, )?; + if let Some(last_block) = last_block.as_ref() { + // do we need to do anything? + let cur_height = spv_client.get_headers_height()?; + if *last_block <= cur_height { + debug!("SPV client has all headers up to {}", cur_height); + return Ok(cur_height); + } + } spv_client .run(self) .and_then(|_r| Ok(spv_client.end_block_height.unwrap())) diff --git a/src/burnchains/burnchain.rs b/src/burnchains/burnchain.rs index ae4e84227d..6db5c8a7c9 100644 --- a/src/burnchains/burnchain.rs +++ b/src/burnchains/burnchain.rs @@ -1245,6 +1245,9 @@ impl Burnchain { start_block + max_blocks ); end_block = start_block + max_blocks; + + // make sure we resume at this height next time + indexer.drop_headers(end_block.saturating_sub(1))?; } } diff --git a/src/burnchains/db.rs b/src/burnchains/db.rs index f312968524..4435c13ccf 100644 --- a/src/burnchains/db.rs +++ b/src/burnchains/db.rs @@ -122,6 +122,7 @@ CREATE TABLE burnchain_db_block_headers ( PRIMARY KEY(block_hash) ); +CREATE INDEX index_burnchain_db_block_headers_height_hash ON burnchain_db_block_headers(block_height DESC, block_hash ASC); CREATE TABLE burnchain_db_block_ops ( block_hash TEXT NOT NULL, @@ -130,6 +131,9 @@ CREATE TABLE burnchain_db_block_ops ( FOREIGN KEY(block_hash) REFERENCES burnchain_db_block_headers(block_hash) ); +CREATE INDEX index_burnchain_db_block_hash ON burnchain_db_block_ops(block_hash); +CREATE INDEX index_burnchain_db_txid ON burnchain_db_block_ops(txid); + CREATE TABLE db_config(version TEXT NOT NULL);"; impl<'a> BurnchainDBTransaction<'a> { diff --git a/src/chainstate/burn/db/sortdb.rs b/src/chainstate/burn/db/sortdb.rs index 2394922fe0..a3540f9088 100644 --- a/src/chainstate/burn/db/sortdb.rs +++ b/src/chainstate/burn/db/sortdb.rs @@ -515,6 +515,9 @@ const SORTITION_DB_INITIAL_SCHEMA: &'static [&'static str] = &[ FOREIGN KEY(sortition_id) REFERENCES snapshots(sortition_id) );"#, r#" + CREATE INDEX index_leader_keys_sortition_id_block_height_vtxindex ON leader_keys(sortition_id,block_height,vtxindex); + "#, + r#" CREATE TABLE block_commits( txid TEXT NOT NULL, vtxindex INTEGER NOT NULL, @@ -540,6 +543,10 @@ const SORTITION_DB_INITIAL_SCHEMA: &'static [&'static str] = &[ FOREIGN KEY(sortition_id) REFERENCES snapshots(sortition_id) );"#, r#" + CREATE INDEX index_block_commits_sortition_id_vtxindex ON block_commits(sortition_id,vtxindex); + CREATE INDEX index_block_commits_sortition_id_block_height_vtxindex ON block_commits(sortition_id,block_height,vtxindex); + "#, + r#" CREATE TABLE user_burn_support( txid TEXT NOT NULL, vtxindex INTEGER NOT NULL, @@ -560,6 +567,11 @@ const SORTITION_DB_INITIAL_SCHEMA: &'static [&'static str] = &[ FOREIGN KEY(sortition_id) REFERENCES snapshots(sortition_id) );"#, r#" + CREATE INDEX index_user_burn_support_txid ON user_burn_support(txid); + CREATE INDEX index_user_burn_support_sortition_id_vtxindex ON user_burn_support(sortition_id,vtxindex); + CREATE INDEX index_user_burn_support_sortition_id_hash_160_key_vtxindex_key_block_ptr_vtxindex ON user_burn_support(sortition_id,block_header_hash_160,key_vtxindex,key_block_ptr,vtxindex ASC); + "#, + r#" CREATE TABLE stack_stx ( txid TEXT NOT NULL, vtxindex INTEGER NOT NULL, @@ -574,6 +586,9 @@ const SORTITION_DB_INITIAL_SCHEMA: &'static [&'static str] = &[ PRIMARY KEY(txid) );"#, r#" + CREATE INDEX index_stack_stx_burn_header_hash ON stack_stx(burn_header_hash); + "#, + r#" CREATE TABLE transfer_stx ( txid TEXT NOT NULL, vtxindex INTEGER NOT NULL, @@ -588,6 +603,9 @@ const SORTITION_DB_INITIAL_SCHEMA: &'static [&'static str] = &[ PRIMARY KEY(txid) );"#, r#" + CREATE INDEX index_transfer_stx_burn_header_hash ON transfer_stx(burn_header_hash); + "#, + r#" CREATE TABLE missed_commits ( txid TEXT NOT NULL, input TEXT NOT NULL, @@ -596,6 +614,9 @@ const SORTITION_DB_INITIAL_SCHEMA: &'static [&'static str] = &[ PRIMARY KEY(txid, intended_sortition_id) );"#, r#" + CREATE INDEX index_missed_commits_intended_sortition_id ON missed_commits(intended_sortition_id); + "#, + r#" CREATE TABLE canonical_accepted_stacks_blocks( tip_consensus_hash TEXT NOT NULL, consensus_hash TEXT NOT NULL, @@ -1574,8 +1595,8 @@ impl<'a> SortitionHandleConn<'a> { let winning_block_hash160 = Hash160::from_sha256(snapshot.winning_stacks_block_hash.as_bytes()); - let qry = "SELECT * FROM user_burn_support - WHERE sortition_id = ?1 AND block_header_hash_160 = ?2 AND key_vtxindex = ?3 AND key_block_ptr = ?4 + let qry = "SELECT * FROM user_burn_support \ + WHERE sortition_id = ?1 AND block_header_hash_160 = ?2 AND key_vtxindex = ?3 AND key_block_ptr = ?4 \ ORDER BY vtxindex ASC"; let args: [&dyn ToSql; 4] = [ &snapshot.sortition_id, @@ -1587,7 +1608,7 @@ impl<'a> SortitionHandleConn<'a> { let mut winning_user_burns: Vec = query_rows(self, qry, &args)?; // were there multiple miners with the same VRF key and block header hash? (i.e., are these user burns shared?) - let qry = "SELECT COUNT(*) FROM block_commits + let qry = "SELECT COUNT(*) FROM block_commits \ WHERE sortition_id = ?1 AND block_header_hash = ?2 AND key_vtxindex = ?3 AND key_block_ptr = ?4"; let args: [&dyn ToSql; 4] = [ &snapshot.sortition_id, diff --git a/src/chainstate/stacks/db/blocks.rs b/src/chainstate/stacks/db/blocks.rs index f317716288..5cd82f8cb6 100644 --- a/src/chainstate/stacks/db/blocks.rs +++ b/src/chainstate/stacks/db/blocks.rs @@ -530,15 +530,26 @@ impl StreamCursor { })) } - pub fn new_tx_stream(tx_query: MemPoolSyncData, max_txs: u64, height: u64) -> StreamCursor { + pub fn new_tx_stream( + tx_query: MemPoolSyncData, + max_txs: u64, + height: u64, + page_id_opt: Option, + ) -> StreamCursor { + let last_randomized_txid = page_id_opt.unwrap_or_else(|| { + let random_bytes = rand::thread_rng().gen::<[u8; 32]>(); + Txid(random_bytes) + }); + StreamCursor::MempoolTxs(TxStreamData { tx_query, - last_randomized_txid: Txid([0u8; 32]), + last_randomized_txid: last_randomized_txid, tx_buf: vec![], tx_buf_ptr: 0, num_txs: 0, max_txs: max_txs, height: height, + corked: false, }) } @@ -2123,6 +2134,7 @@ impl StacksChainState { let block_bench_start = get_epoch_time_ms(); let mut parent_microblock_hash = None; + // TODO: just do a stat? cache this? match StacksChainState::load_block_header( &self.blocks_path, &consensus_hash, @@ -2150,6 +2162,7 @@ impl StacksChainState { let mblock_bench_begin = get_epoch_time_ms(); if let Some(parent_microblock) = parent_microblock_hash { + // TODO: can we cache this? if self.has_processed_microblocks_at_tail( &index_block_hash, &parent_microblock, diff --git a/src/chainstate/stacks/db/mod.rs b/src/chainstate/stacks/db/mod.rs index d0fd28404f..2cdf9dd652 100644 --- a/src/chainstate/stacks/db/mod.rs +++ b/src/chainstate/stacks/db/mod.rs @@ -549,12 +549,15 @@ pub struct TxStreamData { /// serialized transaction buffer that's being sent pub tx_buf: Vec, pub tx_buf_ptr: usize, - /// number of transactions sent so far + /// number of transactions visited in the DB so far pub num_txs: u64, - /// maximum we can send + /// maximum we can visit in the query pub max_txs: u64, /// height of the chain at time of query pub height: u64, + /// Are we done sending transactions, and are now in the process of sending the trailing page + /// ID? + pub corked: bool, } pub const CHAINSTATE_VERSION: &'static str = "2"; @@ -597,6 +600,7 @@ const CHAINSTATE_INITIAL_SCHEMA: &'static [&'static str] = &[ "CREATE INDEX index_block_hash_to_primary_key ON block_headers(index_block_hash,consensus_hash,block_hash);", "CREATE INDEX block_headers_hash_index ON block_headers(block_hash,block_height);", "CREATE INDEX block_index_hash_index ON block_headers(index_block_hash,consensus_hash,block_hash);", + "CREATE INDEX block_headers_burn_header_height ON block_headers(burn_header_height);", r#" -- scheduled payments -- no designated primary key since there can be duplicate entries @@ -620,6 +624,10 @@ const CHAINSTATE_INITIAL_SCHEMA: &'static [&'static str] = &[ vtxindex INT NOT NULL -- user burn support vtxindex );"#, r#" + CREATE INDEX index_payments_block_hash_consensus_hash_vtxindex ON payments(block_hash,consensus_hash,vtxindex ASC); + CREATE INDEX index_payments_index_block_hash_vtxindex ON payments(index_block_hash,vtxindex ASC); + "#, + r#" -- users who supported miners CREATE TABLE user_supporters( address TEXT NOT NULL, @@ -648,7 +656,11 @@ const CHAINSTATE_INITIAL_SCHEMA: &'static [&'static str] = &[ orphaned INT NOT NULL, PRIMARY KEY(anchored_block_hash,consensus_hash,microblock_hash) );"#, + "CREATE INDEX staging_microblocks_processed ON staging_microblocks(processed);", + "CREATE INDEX staging_microblocks_orphaned ON staging_microblocks(orphaned);", "CREATE INDEX staging_microblocks_index_hash ON staging_microblocks(index_block_hash);", + "CREATE INDEX staging_microblocks_index_hash_processed ON staging_microblocks(index_block_hash,processed);", + "CREATE INDEX staging_microblocks_index_hash_orphaned ON staging_microblocks(index_block_hash,orphaned);", r#" -- Staging microblocks data CREATE TABLE staging_microblocks_data(block_hash TEXT NOT NULL, @@ -688,6 +700,7 @@ const CHAINSTATE_INITIAL_SCHEMA: &'static [&'static str] = &[ "CREATE INDEX parent_blocks ON staging_blocks(parent_anchored_block_hash);", "CREATE INDEX parent_consensus_hashes ON staging_blocks(parent_consensus_hash);", "CREATE INDEX index_block_hashes ON staging_blocks(index_block_hash);", + "CREATE INDEX height_stacks_blocks ON staging_blocks(height);", r#" -- users who burned in support of a block CREATE TABLE staging_user_burn_support(anchored_block_hash TEXT NOT NULL, @@ -697,6 +710,9 @@ const CHAINSTATE_INITIAL_SCHEMA: &'static [&'static str] = &[ vtxindex INT NOT NULL );"#, r#" + CREATE INDEX index_staging_user_burn_support ON staging_user_burn_support(anchored_block_hash,consensus_hash); + "#, + r#" CREATE TABLE transactions( id INTEGER PRIMARY KEY, txid TEXT NOT NULL, diff --git a/src/core/mempool.rs b/src/core/mempool.rs index f9a31687e8..c34970aa59 100644 --- a/src/core/mempool.rs +++ b/src/core/mempool.rs @@ -371,6 +371,7 @@ const MEMPOOL_INITIAL_SCHEMA: &'static [&'static str] = &[ ); "#, "CREATE INDEX by_txid ON mempool(txid);", + "CREATE INDEX by_height ON mempool(height);", "CREATE INDEX by_txid_and_height ON mempool(txid,height);", "CREATE INDEX by_sponsor ON mempool(sponsor_address, sponsor_nonce);", "CREATE INDEX by_origin ON mempool(origin_address, origin_nonce);", @@ -417,6 +418,7 @@ const MEMPOOL_SCHEMA_3_BLOOM_STATE: &'static [&'static str] = &[ hashed_txid TEXT NOT NULL, FOREIGN KEY(txid) REFERENCES mempool(txid) ON DELETE CASCADE ); + CREATE INDEX IF NOT EXISTS by_ordered_hashed_txid ON randomized_txids(hashed_txid ASC); CREATE INDEX IF NOT EXISTS by_hashed_txid ON randomized_txids(txid,hashed_txid); "#, r#" @@ -1738,6 +1740,7 @@ impl MemPoolDB { /// (so if some nodes are configured to return fewer than MAX_BLOOM_COUNTER_TXS transactions, /// a requesting node will still have a good chance of getting something useful). /// Also, return the next value to pass for `last_randomized_txid` to load the next page. + /// Also, return the number of rows considered. pub fn find_next_missing_transactions( &self, data: &MemPoolSyncData, @@ -1745,9 +1748,9 @@ impl MemPoolDB { last_randomized_txid: &Txid, max_txs: u64, max_run: u64, - ) -> Result<(Vec, Option), db_error> { + ) -> Result<(Vec, Option, u64), db_error> { let mut ret = vec![]; - let sql = "SELECT mempool.txid as txid, mempool.tx as tx \ + let sql = "SELECT mempool.txid AS txid, mempool.tx AS tx, randomized_txids.hashed_txid AS hashed_txid \ FROM mempool JOIN randomized_txids \ ON mempool.txid = randomized_txids.txid \ WHERE randomized_txids.hashed_txid > ?1 \ @@ -1771,9 +1774,25 @@ impl MemPoolDB { let mut stmt = self.conn().prepare(sql)?; let mut rows = stmt.query(args)?; + let mut num_rows_visited = 0; + let mut next_page = None; while let Some(row) = rows.next()? { + if num_rows_visited >= max_run { + break; + } + let txid = Txid::from_column(row, "txid")?; - test_debug!("Consider txid {}", &txid); + num_rows_visited += 1; + + let hashed_txid = Txid::from_column(row, "hashed_txid")?; + test_debug!( + "Consider txid {} ({}) at or after {}", + &txid, + &hashed_txid, + last_randomized_txid + ); + next_page = Some(hashed_txid); + let contains = match data { MemPoolSyncData::BloomFilter(ref bf) => bf.contains_raw(&txid.0), MemPoolSyncData::TxTags(ref seed, ..) => { @@ -1796,17 +1815,11 @@ impl MemPoolDB { } } - // find next page, if needed - let next_last_randomized_txid = if let Some(last_tx) = ret.last() { - self.get_randomized_txid(&last_tx.txid())? - } else { - None - }; - - Ok((ret, next_last_randomized_txid)) + Ok((ret, next_page, num_rows_visited)) } - /// Stream transaction data + /// Stream transaction data. + /// Send back one transaction at a time. pub fn stream_txs( &self, fd: &mut W, @@ -1815,11 +1828,6 @@ impl MemPoolDB { ) -> Result { let mut num_written = 0; while num_written < count { - if query.num_txs >= query.max_txs { - // don't serve more than this many txs - break; - } - // write out bufferred tx let start = query.tx_buf_ptr; let end = cmp::min(query.tx_buf.len(), ((start as u64) + count) as usize); @@ -1832,37 +1840,104 @@ impl MemPoolDB { num_written += nw; if query.tx_buf_ptr >= query.tx_buf.len() { + if query.corked { + // we're done + test_debug!( + "Finished streaming txs; last page was {:?}", + &query.last_randomized_txid + ); + break; + } + + if query.num_txs >= query.max_txs { + // no more space in this stream + debug!( + "No more space in this query after {:?}. Corking tx stream.", + &query.last_randomized_txid + ); + + // send the next page ID + query.tx_buf_ptr = 0; + query.tx_buf.clear(); + query.corked = true; + + query + .last_randomized_txid + .consensus_serialize(&mut query.tx_buf) + .map_err(ChainstateError::CodecError)?; + continue; + } + // load next - let (mut next_txs, next_last_randomized_txid_opt) = self + let remaining = query.max_txs.saturating_sub(query.num_txs); + let (next_txs, next_last_randomized_txid_opt, num_rows_visited) = self .find_next_missing_transactions( &query.tx_query, query.height, &query.last_randomized_txid, 1, - MAX_BLOOM_COUNTER_TXS.into(), + remaining, )?; - if let Some(next_tx) = next_txs.pop() { + + debug!( + "Streaming mempool propagation stepped"; + "rows_visited" => num_rows_visited, + "last_rand_txid" => %query.last_randomized_txid, + "num_txs" => query.num_txs, + "max_txs" => query.max_txs + ); + + query.num_txs += num_rows_visited; + if next_txs.len() > 0 { query.tx_buf_ptr = 0; query.tx_buf.clear(); - query.num_txs += 1; - - next_tx - .consensus_serialize(&mut query.tx_buf) - .map_err(ChainstateError::CodecError)?; + for next_tx in next_txs.iter() { + next_tx + .consensus_serialize(&mut query.tx_buf) + .map_err(ChainstateError::CodecError)?; + } if let Some(next_last_randomized_txid) = next_last_randomized_txid_opt { query.last_randomized_txid = next_last_randomized_txid; } else { - test_debug!("No more txs after {}", &next_tx.txid()); + test_debug!( + "No more txs after {}", + &next_txs + .last() + .map(|tx| tx.txid()) + .unwrap_or(Txid([0u8; 32])) + ); break; } - } else { - // no more + } else if let Some(next_txid) = next_last_randomized_txid_opt { + test_debug!( + "No rows returned for {}; cork tx stream with next page {}", + &query.last_randomized_txid, + &next_txid + ); + + // no rows found + query.last_randomized_txid = next_txid; + + // send the next page ID + query.tx_buf_ptr = 0; + query.tx_buf.clear(); + query.corked = true; + + query + .last_randomized_txid + .consensus_serialize(&mut query.tx_buf) + .map_err(ChainstateError::CodecError)?; + } else if next_last_randomized_txid_opt.is_none() { + // no more transactions test_debug!( - "No more txs in query after {:?}", + "No more txs to send after {:?}; corking stream", &query.last_randomized_txid ); - break; + + query.tx_buf_ptr = 0; + query.tx_buf.clear(); + query.corked = true; } } } diff --git a/src/core/tests/mod.rs b/src/core/tests/mod.rs index 222f9e894a..a8856ab580 100644 --- a/src/core/tests/mod.rs +++ b/src/core/tests/mod.rs @@ -44,6 +44,7 @@ use core::mempool::{BLOOM_COUNTER_DEPTH, BLOOM_COUNTER_ERROR_RATE, MAX_BLOOM_COU use core::FIRST_BURNCHAIN_CONSENSUS_HASH; use core::FIRST_STACKS_BLOCK_HASH; use net::Error as NetError; +use net::HttpResponseType; use net::MemPoolSyncData; use util::bloom::test::setup_bloom_counter; use util::bloom::*; @@ -1476,7 +1477,8 @@ fn test_find_next_missing_transactions() { let txtags = mempool.get_txtags(&[0u8; 32]).unwrap(); // no txs returned for a full txtag set - let (txs, next_page_opt) = mempool + let ts_before = get_epoch_time_ms(); + let (txs, next_page_opt, _) = mempool .find_next_missing_transactions( &MemPoolSyncData::TxTags([0u8; 32], txtags.clone()), block_height, @@ -1485,11 +1487,18 @@ fn test_find_next_missing_transactions() { MAX_BLOOM_COUNTER_TXS as u64, ) .unwrap(); + let ts_after = get_epoch_time_ms(); + eprintln!( + "find_next_missing_transactions with full txtag set took {} ms", + ts_after.saturating_sub(ts_before) + ); + assert_eq!(txs.len(), 0); - assert!(next_page_opt.is_none()); + assert!(next_page_opt.is_some()); // all txs returned for an empty txtag set - let (txs, next_page_opt) = mempool + let ts_before = get_epoch_time_ms(); + let (txs, next_page_opt, _) = mempool .find_next_missing_transactions( &MemPoolSyncData::TxTags([0u8; 32], vec![]), block_height, @@ -1498,14 +1507,21 @@ fn test_find_next_missing_transactions() { MAX_BLOOM_COUNTER_TXS as u64, ) .unwrap(); + let ts_after = get_epoch_time_ms(); + eprintln!( + "find_next_missing_transactions with empty txtag set took {} ms", + ts_after.saturating_sub(ts_before) + ); + for tx in txs { assert!(txid_set.contains(&tx.txid())); } assert!(next_page_opt.is_some()); // all bloom-filter-absent txids should be returned + let ts_before = get_epoch_time_ms(); let txid_bloom = mempool.get_txid_bloom_filter().unwrap(); - let (txs, next_page_opt) = mempool + let (txs, next_page_opt, _) = mempool .find_next_missing_transactions( &MemPoolSyncData::BloomFilter(txid_bloom), block_height, @@ -1514,8 +1530,14 @@ fn test_find_next_missing_transactions() { (2 * MAX_BLOOM_COUNTER_TXS) as u64, ) .unwrap(); + let ts_after = get_epoch_time_ms(); + eprintln!( + "find_next_missing_transactions with full bloom filter set took {} ms", + ts_after.saturating_sub(ts_before) + ); + assert_eq!(txs.len(), 0); - assert!(next_page_opt.is_none()); + assert!(next_page_opt.is_some()); let mut empty_bloom_conn = setup_bloom_counter("find_next_missing_txs_empty"); let mut empty_tx = tx_begin_immediate(&mut empty_bloom_conn).unwrap(); @@ -1530,7 +1552,8 @@ fn test_find_next_missing_transactions() { .unwrap(); empty_tx.commit().unwrap(); - let (txs, next_page_opt) = mempool + let ts_before = get_epoch_time_ms(); + let (txs, next_page_opt, _) = mempool .find_next_missing_transactions( &MemPoolSyncData::BloomFilter(empty_bloom.to_bloom_filter(&empty_bloom_conn).unwrap()), block_height, @@ -1539,6 +1562,12 @@ fn test_find_next_missing_transactions() { (2 * MAX_BLOOM_COUNTER_TXS) as u64, ) .unwrap(); + let ts_after = get_epoch_time_ms(); + eprintln!( + "find_next_missing_transactions with empty bloom filter set took {} ms", + ts_after.saturating_sub(ts_before) + ); + for tx in txs { assert!(txid_set.contains(&tx.txid())); } @@ -1546,10 +1575,10 @@ fn test_find_next_missing_transactions() { // paginated access works too let mut last_txid = Txid([0u8; 32]); - let page_size = 10; + let page_size = 128; let mut all_txs = vec![]; for i in 0..(txtags.len() / (page_size as usize)) + 1 { - let (mut txs, next_page_opt) = mempool + let (mut txs, next_page_opt, num_visited) = mempool .find_next_missing_transactions( &MemPoolSyncData::TxTags([0u8; 32], vec![]), block_height, @@ -1559,6 +1588,7 @@ fn test_find_next_missing_transactions() { ) .unwrap(); assert!(txs.len() <= page_size as usize); + assert!(num_visited <= page_size as u64); if txs.len() == 0 { assert!(next_page_opt.is_none()); @@ -1581,7 +1611,8 @@ fn test_find_next_missing_transactions() { last_txid = Txid([0u8; 32]); all_txs = vec![]; for i in 0..(txtags.len() / (page_size as usize)) + 1 { - let (mut txs, next_page_opt) = mempool + let ts_before = get_epoch_time_ms(); + let (mut txs, next_page_opt, num_visited) = mempool .find_next_missing_transactions( &MemPoolSyncData::BloomFilter( empty_bloom.to_bloom_filter(&empty_bloom_conn).unwrap(), @@ -1592,7 +1623,11 @@ fn test_find_next_missing_transactions() { page_size, ) .unwrap(); + let ts_after = get_epoch_time_ms(); + eprintln!("find_next_missing_transactions with empty bloom filter took {} ms to serve {} transactions", ts_after.saturating_sub(ts_before), page_size); + assert!(txs.len() <= page_size as usize); + assert!(num_visited <= page_size as u64); if txs.len() == 0 { assert!(next_page_opt.is_none()); @@ -1613,25 +1648,25 @@ fn test_find_next_missing_transactions() { } // old transactions are ignored - let (old_txs, next_page_opt) = mempool + let (old_txs, next_page_opt, num_visited) = mempool .find_next_missing_transactions( &MemPoolSyncData::TxTags([0u8; 32], vec![]), block_height + (BLOOM_COUNTER_DEPTH as u64) + 1, &last_txid, (2 * MAX_BLOOM_COUNTER_TXS) as u64, - page_size, + (2 * MAX_BLOOM_COUNTER_TXS) as u64, ) .unwrap(); assert_eq!(old_txs.len(), 0); assert!(next_page_opt.is_none()); - let (old_txs, next_page_opt) = mempool + let (old_txs, next_page_opt, num_visited) = mempool .find_next_missing_transactions( &MemPoolSyncData::BloomFilter(empty_bloom.to_bloom_filter(&empty_bloom_conn).unwrap()), block_height + (BLOOM_COUNTER_DEPTH as u64) + 1, &last_txid, (2 * MAX_BLOOM_COUNTER_TXS) as u64, - page_size, + (2 * MAX_BLOOM_COUNTER_TXS) as u64, ) .unwrap(); assert_eq!(old_txs.len(), 0); @@ -1709,6 +1744,7 @@ fn test_stream_txs() { MemPoolSyncData::TxTags([0u8; 32], vec![]), MAX_BLOOM_COUNTER_TXS.into(), block_height, + Some(Txid([0u8; 32])), ); let mut tx_stream_data = if let StreamCursor::MempoolTxs(stream_data) = stream { stream_data @@ -1717,9 +1753,13 @@ fn test_stream_txs() { }; loop { - let nw = mempool - .stream_txs(&mut buf, &mut tx_stream_data, 10) - .unwrap(); + let nw = match mempool.stream_txs(&mut buf, &mut tx_stream_data, 10) { + Ok(nw) => nw, + Err(e) => { + error!("Failed to stream_to: {:?}", &e); + panic!(); + } + }; if nw == 0 { break; } @@ -1761,4 +1801,220 @@ fn test_stream_txs() { for tx in decoded_txs { assert!(tx_set.contains(&tx.txid())); } + + // verify that we can stream through pagination, with an empty tx tags + let mut page_id = Txid([0u8; 32]); + let mut decoded_txs = vec![]; + loop { + let stream = StreamCursor::new_tx_stream( + MemPoolSyncData::TxTags([0u8; 32], vec![]), + 1, + block_height, + Some(page_id), + ); + + let mut tx_stream_data = if let StreamCursor::MempoolTxs(stream_data) = stream { + stream_data + } else { + unreachable!(); + }; + + let mut buf = vec![]; + loop { + let nw = match mempool.stream_txs(&mut buf, &mut tx_stream_data, 10) { + Ok(nw) => nw, + Err(e) => { + error!("Failed to stream_to: {:?}", &e); + panic!(); + } + }; + if nw == 0 { + break; + } + } + + // buf decodes to the list of txs we have, plus page ids + let mut ptr = &buf[..]; + test_debug!("Decode {}", to_hex(ptr)); + let (mut next_txs, next_page) = HttpResponseType::decode_tx_stream(&mut ptr, None).unwrap(); + + decoded_txs.append(&mut next_txs); + + // for fun, use a page ID that is actually a well-formed prefix of a transaction + if let Some(ref tx) = decoded_txs.last() { + let mut evil_buf = tx.serialize_to_vec(); + let mut evil_page_id = [0u8; 32]; + evil_page_id.copy_from_slice(&evil_buf[0..32]); + evil_buf.extend_from_slice(&evil_page_id); + + test_debug!("Decode evil buf {}", &to_hex(&evil_buf)); + + let (evil_next_txs, evil_next_page) = + HttpResponseType::decode_tx_stream(&mut &evil_buf[..], None).unwrap(); + + // should still work + assert_eq!(evil_next_txs.len(), 1); + assert_eq!(evil_next_txs[0].txid(), tx.txid()); + assert_eq!(evil_next_page.unwrap().0[0..32], evil_buf[0..32]); + } + + if let Some(next_page) = next_page { + page_id = next_page; + } else { + break; + } + } + + // make sure we got them all + let mut tx_set = HashSet::new(); + for tx in txs.iter() { + tx_set.insert(tx.txid()); + } + + // the order won't be preserved + assert_eq!(tx_set.len(), decoded_txs.len()); + for tx in decoded_txs { + assert!(tx_set.contains(&tx.txid())); + } + + // verify that we can stream through pagination, with a full bloom filter + let mut page_id = Txid([0u8; 32]); + let all_txs_tags: Vec<_> = txs + .iter() + .map(|tx| TxTag::from(&[0u8; 32], &tx.txid())) + .collect(); + loop { + let stream = StreamCursor::new_tx_stream( + MemPoolSyncData::TxTags([0u8; 32], all_txs_tags.clone()), + 1, + block_height, + Some(page_id), + ); + + let mut tx_stream_data = if let StreamCursor::MempoolTxs(stream_data) = stream { + stream_data + } else { + unreachable!(); + }; + + let mut buf = vec![]; + loop { + let nw = match mempool.stream_txs(&mut buf, &mut tx_stream_data, 10) { + Ok(nw) => nw, + Err(e) => { + error!("Failed to stream_to: {:?}", &e); + panic!(); + } + }; + if nw == 0 { + break; + } + } + + // buf decodes to an empty list of txs, plus page ID + let mut ptr = &buf[..]; + test_debug!("Decode {}", to_hex(ptr)); + let (next_txs, next_page) = HttpResponseType::decode_tx_stream(&mut ptr, None).unwrap(); + + assert_eq!(next_txs.len(), 0); + + if let Some(next_page) = next_page { + page_id = next_page; + } else { + break; + } + } +} + +#[test] +fn test_decode_tx_stream() { + let addr = StacksAddress { + version: 1, + bytes: Hash160([0xff; 20]), + }; + let mut txs = vec![]; + for _i in 0..10 { + let pk = StacksPrivateKey::new(); + let mut tx = StacksTransaction { + version: TransactionVersion::Testnet, + chain_id: 0x80000000, + auth: TransactionAuth::from_p2pkh(&pk).unwrap(), + anchor_mode: TransactionAnchorMode::Any, + post_condition_mode: TransactionPostConditionMode::Allow, + post_conditions: vec![], + payload: TransactionPayload::TokenTransfer( + addr.to_account_principal(), + 123, + TokenTransferMemo([0u8; 34]), + ), + }; + tx.set_tx_fee(1000); + tx.set_origin_nonce(0); + txs.push(tx); + } + + // valid empty tx stream + let empty_stream = [0x11u8; 32]; + let (next_txs, next_page) = + HttpResponseType::decode_tx_stream(&mut empty_stream.as_ref(), None).unwrap(); + assert_eq!(next_txs.len(), 0); + assert_eq!(next_page, Some(Txid([0x11; 32]))); + + // valid tx stream with a page id at the end + let mut tx_stream: Vec = vec![]; + for tx in txs.iter() { + tx.consensus_serialize(&mut tx_stream).unwrap(); + } + tx_stream.extend_from_slice(&[0x22; 32]); + + let (next_txs, next_page) = + HttpResponseType::decode_tx_stream(&mut &tx_stream[..], None).unwrap(); + assert_eq!(next_txs, txs); + assert_eq!(next_page, Some(Txid([0x22; 32]))); + + // valid tx stream with _no_ page id at the end + let mut partial_stream: Vec = vec![]; + txs[0].consensus_serialize(&mut partial_stream).unwrap(); + let (next_txs, next_page) = + HttpResponseType::decode_tx_stream(&mut &partial_stream[..], None).unwrap(); + assert_eq!(next_txs.len(), 1); + assert_eq!(next_txs[0], txs[0]); + assert!(next_page.is_none()); + + // garbage tx stream + let garbage_stream = [0xff; 256]; + let err = HttpResponseType::decode_tx_stream(&mut garbage_stream.as_ref(), None); + match err { + Err(NetError::ExpectedEndOfStream) => {} + x => { + error!("did not fail: {:?}", &x); + panic!(); + } + } + + // tx stream that is too short + let short_stream = [0x33u8; 33]; + let err = HttpResponseType::decode_tx_stream(&mut short_stream.as_ref(), None); + match err { + Err(NetError::ExpectedEndOfStream) => {} + x => { + error!("did not fail: {:?}", &x); + panic!(); + } + } + + // tx stream has a tx, a page ID, and then another tx + let mut interrupted_stream = vec![]; + txs[0].consensus_serialize(&mut interrupted_stream).unwrap(); + interrupted_stream.extend_from_slice(&[0x00u8; 32]); + txs[1].consensus_serialize(&mut interrupted_stream).unwrap(); + + let err = HttpResponseType::decode_tx_stream(&mut &interrupted_stream[..], None); + match err { + Err(NetError::ExpectedEndOfStream) => {} + x => { + error!("did not fail: {:?}", &x); + panic!(); + } + } } diff --git a/src/net/connection.rs b/src/net/connection.rs index f85e28f3be..b783a85748 100644 --- a/src/net/connection.rs +++ b/src/net/connection.rs @@ -50,7 +50,7 @@ use net::StacksHttp; use net::StacksP2P; use net::download::BLOCK_DOWNLOAD_INTERVAL; -use net::inv::{FULL_INV_SYNC_INTERVAL, INV_REWARD_CYCLES, INV_SYNC_INTERVAL}; +use net::inv::{INV_REWARD_CYCLES, INV_SYNC_INTERVAL}; use net::neighbors::{ NEIGHBOR_REQUEST_TIMEOUT, NEIGHBOR_WALK_INTERVAL, NUM_INITIAL_WALKS, WALK_MAX_DURATION, WALK_MIN_DURATION, WALK_RESET_INTERVAL, WALK_RESET_PROB, WALK_RETRY_COUNT, WALK_STATE_TIMEOUT, @@ -349,7 +349,6 @@ pub struct ConnectionOptions { pub walk_reset_interval: u64, pub walk_state_timeout: u64, pub inv_sync_interval: u64, - pub full_inv_sync_interval: u64, pub inv_reward_cycles: u64, pub download_interval: u64, pub pingback_timeout: u64, @@ -391,6 +390,8 @@ pub struct ConnectionOptions { pub disable_network_prune: bool, pub disable_network_bans: bool, pub disable_block_advertisement: bool, + pub disable_block_push: bool, + pub disable_microblock_push: bool, pub disable_pingbacks: bool, pub disable_inbound_walks: bool, pub disable_natpunch: bool, @@ -431,7 +432,6 @@ impl std::default::Default for ConnectionOptions { walk_reset_interval: WALK_RESET_INTERVAL, walk_state_timeout: WALK_STATE_TIMEOUT, inv_sync_interval: INV_SYNC_INTERVAL, // how often to synchronize block inventories - full_inv_sync_interval: FULL_INV_SYNC_INTERVAL, // how often to synchronize the *full* inventory inv_reward_cycles: INV_REWARD_CYCLES, // how many reward cycles of blocks to sync in a non-full inventory sync download_interval: BLOCK_DOWNLOAD_INTERVAL, // how often to scan for blocks to download pingback_timeout: 60, @@ -457,15 +457,15 @@ impl std::default::Default for ConnectionOptions { public_ip_max_retries: 3, // maximum number of retries before self-throttling for $public_ip_timeout max_block_push: 10, // maximum number of blocksData messages to push out via our anti-entropy protocol max_microblock_push: 10, // maximum number of microblocks messages to push out via our anti-entropy protocol - antientropy_retry: 3600, // retry pushing data only once every hour + antientropy_retry: 60, // retry pushing data once every minute antientropy_public: true, // run antientropy even if we're NOT NAT'ed max_buffered_blocks_available: 1, max_buffered_microblocks_available: 1, max_buffered_blocks: 1, max_buffered_microblocks: 10, mempool_sync_interval: 30, // number of seconds in-between mempool sync - mempool_max_tx_query: MAX_BLOOM_COUNTER_TXS.into(), - mempool_sync_timeout: 60, // how long a mempool sync can go for + mempool_max_tx_query: 128, // maximum number of transactions to visit per mempool query + mempool_sync_timeout: 180, // how long a mempool sync can go for (3 minutes) // no faults on by default disable_neighbor_walk: false, @@ -476,6 +476,8 @@ impl std::default::Default for ConnectionOptions { disable_network_prune: false, disable_network_bans: false, disable_block_advertisement: false, + disable_block_push: false, + disable_microblock_push: false, disable_pingbacks: false, disable_inbound_walks: false, disable_natpunch: false, @@ -1058,7 +1060,10 @@ impl ConnectionOutbox

{ message_eof = true; 0 } - Ok(read_len) => read_len, + Ok(read_len) => { + test_debug!("Connection message pipe returned {} bytes", read_len); + read_len + } Err(ioe) => match ioe.kind() { io::ErrorKind::WouldBlock => { // no data consumed, but we may need to make a break for it @@ -1088,14 +1093,13 @@ impl ConnectionOutbox

{ self.socket_out_buf.extend_from_slice(&buf[0..nr_input]); - if nr_input > 0 { - trace!( - "Connection buffered {} bytes from pipe ({} total, ptr = {})", - nr_input, - self.socket_out_buf.len(), - self.socket_out_ptr - ); - } + test_debug!( + "Connection buffered {} bytes from pipe ({} total, ptr = {}, blocked = {})", + nr_input, + self.socket_out_buf.len(), + self.socket_out_ptr, + blocked + ); nr_input } None => { @@ -1134,7 +1138,7 @@ impl ConnectionOutbox

{ self.socket_out_ptr += num_written; - trace!( + test_debug!( "Connection wrote {} bytes to socket (buffer len = {}, ptr = {})", num_written, self.socket_out_buf.len(), @@ -1155,7 +1159,7 @@ impl ConnectionOutbox

{ } } - trace!( + test_debug!( "Connection send_bytes finished: blocked = {}, disconnected = {}", blocked, disconnected diff --git a/src/net/dns.rs b/src/net/dns.rs index 50617098b7..1f37ceb1a5 100644 --- a/src/net/dns.rs +++ b/src/net/dns.rs @@ -173,6 +173,7 @@ impl DNSResolver { if addrs.len() == 0 { return DNSResponse::error(req, "DNS resolve error: got zero addresses".to_string()); } + test_debug!("{}:{} resolved to {:?}", &req.host, req.port, &addrs); DNSResponse::new(req, Ok(addrs)) } diff --git a/src/net/download.rs b/src/net/download.rs index 063b9d9be8..d9271d6275 100644 --- a/src/net/download.rs +++ b/src/net/download.rs @@ -2879,6 +2879,7 @@ pub mod test { sortdb, chainstate, mempool, + false, None, None, ) diff --git a/src/net/http.rs b/src/net/http.rs index 4543365ebc..3424e9f38f 100644 --- a/src/net/http.rs +++ b/src/net/http.rs @@ -1729,6 +1729,27 @@ impl HttpRequestType { } } + /// get the mempool page ID optional query argument (`page_id`) + /// Take the first value we can parse. + fn get_mempool_page_id_query(query: Option<&str>) -> Option { + match query { + Some(query_string) => { + for (key, value) in form_urlencoded::parse(query_string.as_bytes()) { + if key != "page_id" { + continue; + } + if let Ok(page_id) = Txid::from_hex(&value) { + return Some(page_id); + } + } + return None; + } + None => { + return None; + } + } + } + fn parse_get_account( _protocol: &mut StacksHttp, preamble: &HttpRequestPreamble, @@ -2556,7 +2577,7 @@ impl HttpRequestType { _protocol: &mut StacksHttp, preamble: &HttpRequestPreamble, _regex: &Captures, - _query: Option<&str>, + query: Option<&str>, fd: &mut R, ) -> Result { if preamble.get_content_length() == 0 { @@ -2590,10 +2611,12 @@ impl HttpRequestType { let mut bound_fd = BoundReader::from_reader(fd, preamble.get_content_length() as u64); let mempool_query = MemPoolSyncData::consensus_deserialize(&mut bound_fd)?; + let page_id_opt = HttpRequestType::get_mempool_page_id_query(query); Ok(HttpRequestType::MemPoolQuery( HttpRequestMetadata::from_preamble(preamble), mempool_query, + page_id_opt, )) } @@ -2672,7 +2695,7 @@ impl HttpRequestType { } } - fn make_query_string(tip_req: &TipRequest, with_proof: bool) -> String { + fn make_tip_query_string(tip_req: &TipRequest, with_proof: bool) -> String { match tip_req { TipRequest::UseLatestUnconfirmedTip => { format!("?tip=latest{}", if with_proof { "" } else { "&proof=0" }) @@ -2695,13 +2718,13 @@ impl HttpRequestType { HttpRequestType::GetInfo(_md) => "/v2/info".to_string(), HttpRequestType::GetPoxInfo(_md, tip_req) => format!( "/v2/pox{}", - HttpRequestType::make_query_string(tip_req, true) + HttpRequestType::make_tip_query_string(tip_req, true) ), HttpRequestType::GetNeighbors(_md) => "/v2/neighbors".to_string(), HttpRequestType::GetHeaders(_md, quantity, tip_req) => format!( "/v2/headers/{}{}", quantity, - HttpRequestType::make_query_string(tip_req, true) + HttpRequestType::make_tip_query_string(tip_req, true) ), HttpRequestType::GetBlock(_md, block_hash) => { format!("/v2/blocks/{}", block_hash.to_hex()) @@ -2724,13 +2747,13 @@ impl HttpRequestType { HttpRequestType::PostBlock(_md, ch, ..) => format!("/v2/blocks/upload/{}", &ch), HttpRequestType::PostMicroblock(_md, _, tip_req) => format!( "/v2/microblocks{}", - HttpRequestType::make_query_string(tip_req, true) + HttpRequestType::make_tip_query_string(tip_req, true) ), HttpRequestType::GetAccount(_md, principal, tip_req, with_proof) => { format!( "/v2/accounts/{}{}", &principal.to_string(), - HttpRequestType::make_query_string(tip_req, *with_proof,) + HttpRequestType::make_tip_query_string(tip_req, *with_proof,) ) } HttpRequestType::GetDataVar( @@ -2745,7 +2768,7 @@ impl HttpRequestType { &contract_addr.to_string(), contract_name.as_str(), var_name.as_str(), - HttpRequestType::make_query_string(tip_req, *with_proof) + HttpRequestType::make_tip_query_string(tip_req, *with_proof) ), HttpRequestType::GetMapEntry( _md, @@ -2760,14 +2783,14 @@ impl HttpRequestType { &contract_addr.to_string(), contract_name.as_str(), map_name.as_str(), - HttpRequestType::make_query_string(tip_req, *with_proof) + HttpRequestType::make_tip_query_string(tip_req, *with_proof) ), HttpRequestType::GetTransferCost(_md) => "/v2/fees/transfer".into(), HttpRequestType::GetContractABI(_, contract_addr, contract_name, tip_req) => format!( "/v2/contracts/interface/{}/{}{}", contract_addr, contract_name.as_str(), - HttpRequestType::make_query_string(tip_req, true,) + HttpRequestType::make_tip_query_string(tip_req, true,) ), HttpRequestType::GetContractSrc( _, @@ -2779,7 +2802,7 @@ impl HttpRequestType { "/v2/contracts/source/{}/{}{}", contract_addr, contract_name.as_str(), - HttpRequestType::make_query_string(tip_req, *with_proof) + HttpRequestType::make_tip_query_string(tip_req, *with_proof) ), HttpRequestType::GetIsTraitImplemented( _, @@ -2794,7 +2817,7 @@ impl HttpRequestType { trait_id.name.to_string(), StacksAddress::from(trait_id.clone().contract_identifier.issuer), trait_id.contract_identifier.name.as_str(), - HttpRequestType::make_query_string(tip_req, true) + HttpRequestType::make_tip_query_string(tip_req, true) ), HttpRequestType::CallReadOnlyFunction( _, @@ -2809,7 +2832,7 @@ impl HttpRequestType { contract_addr, contract_name.as_str(), func_name.as_str(), - HttpRequestType::make_query_string(tip_req, true) + HttpRequestType::make_tip_query_string(tip_req, true) ), HttpRequestType::OptionsPreflight(_md, path) => path.to_string(), HttpRequestType::GetAttachmentsInv(_md, index_block_hash, pages_indexes) => { @@ -2830,7 +2853,12 @@ impl HttpRequestType { HttpRequestType::GetAttachment(_, content_hash) => { format!("/v2/attachments/{}", to_hex(&content_hash.0[..])) } - HttpRequestType::MemPoolQuery(..) => "/v2/mempool/query".to_string(), + HttpRequestType::MemPoolQuery(_, _, page_id_opt) => match page_id_opt { + Some(page_id) => { + format!("/v2/mempool/query?page_id={}", page_id) + } + None => "/v2/mempool/query".to_string(), + }, HttpRequestType::FeeRateEstimate(_, _, _) => self.get_path().to_string(), HttpRequestType::ClientError(_md, e) => match e { ClientError::NotFound(path) => path.to_string(), @@ -3026,7 +3054,7 @@ impl HttpRequestType { fd.write_all(&request_body_bytes) .map_err(net_error::WriteError)?; } - HttpRequestType::MemPoolQuery(md, query) => { + HttpRequestType::MemPoolQuery(md, query, ..) => { let request_body_bytes = query.serialize_to_vec(); HttpRequestPreamble::new_serialized( fd, @@ -3747,36 +3775,138 @@ impl HttpResponseType { )) } - fn parse_post_mempool_query( - _protocol: &mut StacksHttp, - request_version: HttpVersion, - preamble: &HttpResponsePreamble, + /// Read the trailing page ID from a transaction stream + fn parse_mempool_query_page_id( + pos: usize, + retry_reader: &mut RetryReader<'_, R>, + ) -> Result, net_error> { + // possibly end-of-transactions, in which case, the last 32 bytes should be + // a page ID. Expect end-of-stream after this. + retry_reader.set_position(pos); + let next_page: Txid = match read_next(retry_reader) { + Ok(txid) => txid, + Err(e) => match e { + codec_error::ReadError(ref ioe) => match ioe.kind() { + io::ErrorKind::UnexpectedEof => { + if pos == retry_reader.position() { + // this is fine -- the node didn't get another page + return Ok(None); + } else { + // partial data -- corrupt stream + test_debug!("Unexpected EOF: {} != {}", pos, retry_reader.position()); + return Err(e.into()); + } + } + _ => { + return Err(e.into()); + } + }, + e => { + return Err(e.into()); + } + }, + }; + + test_debug!("Read page_id {:?}", &next_page); + Ok(Some(next_page)) + } + + /// Decode a transaction stream, returned from /v2/mempool/query. + /// The wire format is a list of transactions (no SIP-003 length prefix), followed by an + /// optional 32-byte page ID. Obtain both the transactions and page ID, if it exists. + pub fn decode_tx_stream( fd: &mut R, len_hint: Option, - ) -> Result { - // NOTE: there will be no length prefix on this - let mut txs = vec![]; + ) -> Result<(Vec, Option), net_error> { + // The wire format is `tx, tx, tx, tx, .., tx, txid`. + // The last 32 bytes are the page ID for the next mempool query. + // NOTE: there will be no length prefix on this. + let mut txs: Vec = vec![]; let max_len = len_hint.unwrap_or(MAX_MESSAGE_LEN as usize) as u64; let mut bound_reader = BoundReader::from_reader(fd, max_len); + let mut retry_reader = RetryReader::new(&mut bound_reader); + let mut page_id = None; + let mut expect_eof = false; + loop { - let tx: StacksTransaction = match read_next(&mut bound_reader) { - Ok(tx) => Ok(tx), + let pos = retry_reader.position(); + let next_msg: Result = read_next(&mut retry_reader); + match next_msg { + Ok(tx) => { + if expect_eof { + // this should have failed + test_debug!("Expected EOF; got transaction {}", tx.txid()); + return Err(net_error::ExpectedEndOfStream); + } + + test_debug!("Read transaction {}", tx.txid()); + txs.push(tx); + Ok(()) + } Err(e) => match e { codec_error::ReadError(ref ioe) => match ioe.kind() { io::ErrorKind::UnexpectedEof => { - // end of stream -- this is fine + if expect_eof { + if pos != retry_reader.position() { + // read partial data. The stream is corrupt. + test_debug!( + "Expected EOF; stream advanced from {} to {}", + pos, + retry_reader.position() + ); + return Err(net_error::ExpectedEndOfStream); + } + } else { + // couldn't read a full transaction. This is possibly a page ID, whose + // 32 bytes decode to the prefix of a well-formed transaction. + test_debug!("Try to read page ID trailer after ReadError"); + page_id = HttpResponseType::parse_mempool_query_page_id( + pos, + &mut retry_reader, + )?; + } break; } _ => Err(e), }, + codec_error::DeserializeError(_msg) => { + if expect_eof { + // this should have failed due to EOF + test_debug!("Expected EOF; got DeserializeError '{}'", &_msg); + return Err(net_error::ExpectedEndOfStream); + } + + // failed to parse a transaction. This is possibly a page ID. + test_debug!("Try to read page ID trailer after ReadError"); + page_id = + HttpResponseType::parse_mempool_query_page_id(pos, &mut retry_reader)?; + + // do one more pass to make sure we're actually end-of-stream. + // otherwise, the stream itself was corrupt, since any 32 bytes is a valid + // txid and the presence of more bytes means that we simply got a bad tx + // that we couldn't decode. + expect_eof = true; + Ok(()) + } _ => Err(e), }, }?; - - txs.push(tx); } + + Ok((txs, page_id)) + } + + fn parse_post_mempool_query( + _protocol: &mut StacksHttp, + request_version: HttpVersion, + preamble: &HttpResponsePreamble, + fd: &mut R, + len_hint: Option, + ) -> Result { + let (txs, page_id) = HttpResponseType::decode_tx_stream(fd, len_hint)?; Ok(HttpResponseType::MemPoolTxs( HttpResponseMetadata::from_preamble(request_version, preamble), + page_id, txs, )) } @@ -4109,7 +4239,7 @@ impl HttpResponseType { |ref mut fd| keep_alive_headers(fd, md), )?; } - HttpResponseType::MemPoolTxs(ref md, ref txs) => { + HttpResponseType::MemPoolTxs(ref md, ref page_id, ref txs) => { HttpResponsePreamble::new_serialized( fd, 200, @@ -4119,7 +4249,27 @@ impl HttpResponseType { md.request_id, |ref mut fd| keep_alive_headers(fd, md), )?; - HttpResponseType::send_bytestream(protocol, md, fd, txs)?; + match page_id { + Some(txid) => { + if md.content_length.is_some() { + // have explicit content-length, so we can send as-is + write_next(fd, txs)?; + write_next(fd, txid)?; + Ok(()) + } else { + // no content-length, so send as chunk-encoded + let mut write_state = + HttpChunkedTransferWriterState::new(protocol.chunk_size as usize); + let mut encoder = + HttpChunkedTransferWriter::from_writer_state(fd, &mut write_state); + write_next(&mut encoder, txs)?; + write_next(&mut encoder, txid)?; + encoder.flush().map_err(codec_error::WriteError)?; + Ok(()) + } + } + None => HttpResponseType::send_bytestream(protocol, md, fd, txs), + }?; } HttpResponseType::OptionsPreflight(ref md) => { HttpResponsePreamble::new_serialized( diff --git a/src/net/inv.rs b/src/net/inv.rs index 6e3eab54a5..5cc2f762c8 100644 --- a/src/net/inv.rs +++ b/src/net/inv.rs @@ -74,12 +74,7 @@ pub const INV_SYNC_INTERVAL: u64 = 150; pub const INV_SYNC_INTERVAL: u64 = 0; #[cfg(not(test))] -pub const FULL_INV_SYNC_INTERVAL: u64 = 12 * 3600; -#[cfg(test)] -pub const FULL_INV_SYNC_INTERVAL: u64 = 60; - -#[cfg(not(test))] -pub const INV_REWARD_CYCLES: u64 = 3; +pub const INV_REWARD_CYCLES: u64 = 2; #[cfg(test)] pub const INV_REWARD_CYCLES: u64 = 1; @@ -546,7 +541,7 @@ pub struct NeighborBlockStats { pub pox_inv: Option, /// Received BlocksInv pub blocks_inv: Option, - /// Last time we did a full scan + /// Last time we did a scan pub last_rescan_timestamp: u64, /// Finished synchronizing? pub done: bool, @@ -990,14 +985,9 @@ pub struct InvState { hint_do_rescan: bool, /// last time a rescan was completed last_rescanned_at: u64, - /// Should we do a full rescan? - hint_do_full_rescan: bool, - /// last time a full rescan was completed, in seconds - last_full_rescanned_at: u64, /// How many passes -- short and full -- have we done? num_inv_syncs: u64, - num_full_inv_syncs: u64, /// What's the last reward cycle we _started_ the inv scan at? pub block_sortition_start: u64, @@ -1017,12 +1007,9 @@ impl InvState { hint_learned_data: false, hint_learned_data_height: u64::MAX, hint_do_rescan: true, - hint_do_full_rescan: false, last_rescanned_at: 0, - last_full_rescanned_at: 0, num_inv_syncs: 0, - num_full_inv_syncs: 0, block_sortition_start: 0, } @@ -1195,6 +1182,12 @@ impl InvState { ret = true; } } + if !ret { + debug!( + "Have {} block_stats, but none represent useful data for the downloader", + self.block_stats.len() + ); + } ret } @@ -1579,7 +1572,8 @@ impl PeerNetwork { .get_peer_sortition_snapshot(sortdb, &stable_tip_burn_block_hash)? .is_none() { - // we don't know about this remote peer's stable burnchain tip either + // we don't know about this remote peer's stable burnchain tip either, so ask + // for no blocks. debug!("{:?}: remote neighbor {:?}'s burnchain stable view tip is {}-{:?}, which we do not know", &self.local_peer, nk, stable_tip_height, &stable_tip_burn_block_hash); return Ok(0); } @@ -1602,7 +1596,12 @@ impl PeerNetwork { { self.burnchain.pox_constants.reward_cycle_length as u64 } else { - max_burn_block_height - target_block_height + 1 + if target_block_height > max_burn_block_height { + debug!("{:?}: will not send GetBlocksInv to {:?}, since we are sync'ed up to its highest sortition block (target block is {}, max burn block is {})", &self.local_peer, nk, target_block_height, max_burn_block_height); + 0 + } else { + max_burn_block_height - target_block_height + 1 + } }; if num_blocks == 0 { @@ -1650,20 +1649,22 @@ impl PeerNetwork { ); let num_blocks = match self.get_convo(nk) { - Some(convo) => match self.get_getblocksinv_num_blocks( - sortdb, - target_block_reward_cycle, - nk, - stats, - convo, - )? { - 0 => { - // cannot ask this peer for any blocks in this reward cycle - debug!("{:?}: no blocks available from {}", &self.local_peer, nk); - return Ok(None); + Some(convo) => { + match self.get_getblocksinv_num_blocks( + sortdb, + target_block_reward_cycle, + nk, + stats, + convo, + )? { + 0 => { + // cannot ask this peer for any blocks in this reward cycle + debug!("{:?}: no blocks available from {} at cycle {} (which starts at height {})", &self.local_peer, nk, target_block_reward_cycle, self.burnchain.reward_cycle_to_block_height(target_block_reward_cycle)); + return Ok(None); + } + x => x, } - x => x, - }, + } None => { debug!("{:?}: no conversation open for {}", &self.local_peer, nk); return Ok(None); @@ -1772,12 +1773,7 @@ impl PeerNetwork { } /// Determine at which reward cycle to begin scanning inventories - fn get_block_scan_start( - &self, - sortdb: &SortitionDB, - highest_remote_reward_cycle: u64, - full_rescan: bool, - ) -> u64 { + fn get_block_scan_start(&self, sortdb: &SortitionDB, highest_remote_reward_cycle: u64) -> u64 { let (consensus_hash, _) = SortitionDB::get_canonical_stacks_chain_tip_hash(sortdb.conn()) .unwrap_or((ConsensusHash::empty(), BlockHeaderHash([0u8; 32]))); @@ -1799,11 +1795,13 @@ impl PeerNetwork { highest_remote_reward_cycle.saturating_sub(self.connection_opts.inv_reward_cycles), ); - if full_rescan { - 0 - } else { - start_reward_cycle - } + test_debug!( + "begin blocks inv scan at {} = min({},{})", + start_reward_cycle, + stacks_tip_rc, + highest_remote_reward_cycle.saturating_sub(self.connection_opts.inv_reward_cycles) + ); + start_reward_cycle } /// Start requesting the next batch of PoX inventories @@ -1813,7 +1811,6 @@ impl PeerNetwork { nk: &NeighborKey, stats: &mut NeighborBlockStats, request_timeout: u64, - full_rescan: bool, ) -> Result<(), net_error> { let (target_pox_reward_cycle, getpoxinv) = match self .make_next_getpoxinv(sortdb, nk, stats)? @@ -1821,8 +1818,13 @@ impl PeerNetwork { Some(x) => x, None => { // proceed to block scan - let scan_start_rc = - self.get_block_scan_start(sortdb, stats.inv.get_pox_height(), full_rescan); + let scan_start_rc = self.get_block_scan_start( + sortdb, + self.burnchain + .block_height_to_reward_cycle(stats.inv.get_block_height()) + .unwrap_or(0), + ); + debug!("{:?}: cannot make any more GetPoxInv requests for {:?}; proceeding to block inventory scan at reward cycle {}", &self.local_peer, nk, scan_start_rc); stats.reset_block_scan(scan_start_rc); return Ok(()); @@ -1849,7 +1851,6 @@ impl PeerNetwork { sortdb: &SortitionDB, nk: &NeighborKey, stats: &mut NeighborBlockStats, - full_rescan: bool, ibd: bool, ) -> Result { if stats.done { @@ -1881,14 +1882,13 @@ impl PeerNetwork { // react to divergences by deepening our rescan. let scan_start_rc = self.get_block_scan_start( sortdb, - stats - .target_pox_reward_cycle - .saturating_sub(INV_REWARD_CYCLES), - full_rescan, + self.burnchain + .block_height_to_reward_cycle(stats.inv.get_block_height()) + .unwrap_or(0), ); debug!( - "{:?}: proceeding to block inventory scan for {:?} (diverged) at reward cycle {} (ibd={}, full={})", - &self.local_peer, nk, scan_start_rc, ibd, full_rescan + "{:?}: proceeding to block inventory scan for {:?} (diverged) at reward cycle {} (ibd={})", + &self.local_peer, nk, scan_start_rc, ibd ); stats.learned_data = true; @@ -1986,8 +1986,12 @@ impl PeerNetwork { } // proceed to block scan. - let scan_start = - self.get_block_scan_start(sortdb, stats.inv.get_pox_height(), full_rescan); + let scan_start = self.get_block_scan_start( + sortdb, + self.burnchain + .block_height_to_reward_cycle(stats.inv.get_block_height()) + .unwrap_or(0), + ); debug!( "{:?}: proceeding to block inventory scan for {:?} at reward cycle {}", &self.local_peer, nk, scan_start @@ -2056,8 +2060,9 @@ impl PeerNetwork { if ibd && stats.status == NodeStatus::Diverged { // we were in the initial block download, and we diverged. // we should try and deepen the scan. - stats.block_reward_cycle = - stats.block_reward_cycle.saturating_sub(INV_REWARD_CYCLES); + stats.block_reward_cycle = stats + .block_reward_cycle + .saturating_sub(self.connection_opts.inv_reward_cycles); let learned_data_height = self .burnchain .reward_cycle_to_block_height(stats.block_reward_cycle); @@ -2134,7 +2139,6 @@ impl PeerNetwork { nk: &NeighborKey, stats: &mut NeighborBlockStats, request_timeout: u64, - full_rescan: bool, ibd: bool, ) -> Result { while !stats.done { @@ -2146,10 +2150,10 @@ impl PeerNetwork { let again = match stats.state { InvWorkState::GetPoxInvBegin => self - .inv_getpoxinv_begin(sortdb, nk, stats, request_timeout, full_rescan) + .inv_getpoxinv_begin(sortdb, nk, stats, request_timeout) .and_then(|_| Ok(true))?, InvWorkState::GetPoxInvFinish => { - self.inv_getpoxinv_try_finish(sortdb, nk, stats, full_rescan, ibd)? + self.inv_getpoxinv_try_finish(sortdb, nk, stats, ibd)? } InvWorkState::GetBlocksInvBegin => self .inv_getblocksinv_begin(sortdb, nk, stats, request_timeout) @@ -2292,14 +2296,7 @@ impl PeerNetwork { stats.done ); if !stats.done { - match network.inv_sync_run( - sortdb, - nk, - stats, - inv_state.request_timeout, - inv_state.hint_do_full_rescan, - ibd, - ) { + match network.inv_sync_run(sortdb, nk, stats, inv_state.request_timeout, ibd) { Ok(d) => d, Err(net_error::StaleView) => { // stop work on this state machine -- it needs to be restarted. @@ -2345,7 +2342,7 @@ impl PeerNetwork { debug!("{:?}: remote neighbor {:?} diverged (at {}), so try re-scanning at height {}", &network.local_peer, &nk, stats.learned_data_height, inv_state.hint_learned_data_height); } else { debug!( - "{:?}: learned something new from {:?} at height {}", + "{:?}: learned to scan from {:?} at height {}", &network.local_peer, &nk, stats.learned_data_height ); } @@ -2379,51 +2376,15 @@ impl PeerNetwork { network.get_block_scan_start( sortdb, network.pox_id.num_inventory_reward_cycles() as u64, - inv_state.hint_do_full_rescan, ), )) .saturating_sub(sortdb.first_block_height); debug!( - "{:?}: inventory sync finished; sortition start is {} (do rescan? {})", - &network.local_peer, - inv_state.block_sortition_start, - inv_state.hint_do_full_rescan + "{:?}: inventory sync finished; sortition start is {}", + &network.local_peer, inv_state.block_sortition_start, ); - let was_full = inv_state.hint_do_full_rescan; - if was_full { - let synced_with_bootstrap_peer = if ibd { - // make sure we've sync'ed with at least one bootstrap peer before - // clearing the hint_do_full_rescan flag - let synced = bootstrap_peers.len() == 0 - || !bootstrap_peers.is_disjoint(&fully_synced_peers); - if synced { - debug!( - "{:?}: finished full inventory rescan in initial block download with {} always-allowed peer(s)", - &network.local_peer, - bootstrap_peers.len() - ); - } else { - debug!("{:?}: did NOT finish full inventory rescan in initial block download", &network.local_peer); - } - synced - } else { - // this is best-effort if not in initial block-download - debug!( - "{:?}: finished best-effort full inventory rescan", - &network.local_peer - ); - true - }; - - if synced_with_bootstrap_peer { - inv_state.last_full_rescanned_at = get_epoch_time_secs(); - inv_state.hint_do_full_rescan = false; - inv_state.num_full_inv_syncs += 1; - } - } - if !inv_state.hint_learned_data && inv_state.block_stats.len() > 0 { // did a full scan without learning anything new inv_state.last_rescanned_at = get_epoch_time_secs(); @@ -2435,9 +2396,7 @@ impl PeerNetwork { &network.local_peer, &inv_state.block_stats.len(); "ibd" => %ibd, - "was_full" => %was_full, "num_inv_syncs" => %inv_state.num_inv_syncs, - "num_full_inv_syncs" => %inv_state.num_full_inv_syncs, "num_sync_neighbors" => &inv_state.block_stats.len() ); } else { @@ -2451,22 +2410,11 @@ impl PeerNetwork { &network.local_peer, inv_state.block_stats.len(); "ibd" => %ibd, - "was_full" => %was_full, "num_inv_syncs" => %inv_state.num_inv_syncs, - "num_full_inv_syncs" => %inv_state.num_full_inv_syncs, "num_sync_neighbors" => &inv_state.block_stats.len() ); } - if inv_state.last_full_rescanned_at + network.connection_opts.full_inv_sync_interval - < get_epoch_time_secs() - { - if !ibd && !inv_state.hint_do_full_rescan { - debug!("{:?}: schedule full inventory sync", &network.local_peer); - inv_state.hint_do_full_rescan = true; - } - } - let bad_peers = inv_state.cull_bad_peers(); for bad_peer in bad_peers { info!( @@ -4094,221 +4042,6 @@ mod test { }) } - #[test] - #[ignore] - fn test_sync_inv_2_peers_plain_full_sync() { - with_timeout(600, || { - let mut peer_1_config = - TestPeerConfig::new("test_sync_inv_2_peers_full_sync", 32000, 42000); - let mut peer_2_config = - TestPeerConfig::new("test_sync_inv_2_peers_full_sync", 32001, 42001); - - peer_1_config.add_neighbor(&peer_2_config.to_neighbor()); - peer_2_config.add_neighbor(&peer_1_config.to_neighbor()); - - let mut peer_1 = TestPeer::new(peer_1_config); - let mut peer_2 = TestPeer::new(peer_2_config); - - let num_blocks = ((GETPOXINV_MAX_BITLEN as u64) + INV_REWARD_CYCLES) * 4; - let first_stacks_block_height = { - let sn = SortitionDB::get_canonical_burn_chain_tip( - &peer_1.sortdb.as_ref().unwrap().conn(), - ) - .unwrap(); - sn.block_height + 1 - }; - - for i in 0..num_blocks { - let (burn_ops, stacks_block, microblocks) = peer_2.make_default_tenure(); - - peer_1.next_burnchain_block(burn_ops.clone()); - peer_2.next_burnchain_block(burn_ops.clone()); - - peer_1.process_stacks_epoch_at_tip(&stacks_block, µblocks); - peer_2.process_stacks_epoch_at_tip(&stacks_block, µblocks); - } - - let num_burn_blocks = { - let sn = SortitionDB::get_canonical_burn_chain_tip( - peer_1.sortdb.as_ref().unwrap().conn(), - ) - .unwrap(); - sn.block_height + 1 - }; - - let mut round = 0; - let mut inv_1_count = 0; - let mut inv_2_count = 0; - let mut inv_1_full_count = 0; - let mut inv_2_full_count = 0; - - // there must be a wall-clock delay. - // the first full-sync happens immediately, so don't count it. - let start_time = get_epoch_time_secs(); - let num_full_syncs = 5; - let expected_time = (num_full_syncs - 1) * FULL_INV_SYNC_INTERVAL; - - while inv_1_count < num_blocks - || inv_2_count < num_blocks - || inv_1_full_count < num_full_syncs - || inv_2_full_count < num_full_syncs - { - let _ = peer_1.step(); - let _ = peer_2.step(); - - let x = match peer_1.network.inv_state { - Some(ref inv) => { - info!("Peer 1 stats: {:?}", &inv.block_stats); - ( - inv.get_inv_num_blocks(&peer_2.to_neighbor().addr), - inv.num_full_inv_syncs, - ) - } - None => (0, 0), - }; - inv_1_count = x.0; - inv_1_full_count = x.1; - - let x = match peer_2.network.inv_state { - Some(ref inv) => { - info!("Peer 2 stats: {:?}", &inv.block_stats); - ( - inv.get_inv_num_blocks(&peer_1.to_neighbor().addr), - inv.num_full_inv_syncs, - ) - } - None => (0, 0), - }; - inv_2_count = x.0; - inv_2_full_count = x.1; - - // nothing should break - match peer_1.network.inv_state { - Some(ref inv) => { - assert_eq!(inv.get_broken_peers().len(), 0); - assert_eq!(inv.get_dead_peers().len(), 0); - assert_eq!(inv.get_diverged_peers().len(), 0); - } - None => {} - } - - match peer_2.network.inv_state { - Some(ref inv) => { - assert_eq!(inv.get_broken_peers().len(), 0); - assert_eq!(inv.get_dead_peers().len(), 0); - assert_eq!(inv.get_diverged_peers().len(), 0); - } - None => {} - } - - round += 1; - - info!( - "Peer 1: {},{} Peer 2: {},{}", - inv_1_count, inv_1_full_count, inv_2_count, inv_2_full_count - ); - } - - let finish_time = get_epoch_time_secs(); - info!( - "Completed walk round {} step(s) and {} seconds", - round, - finish_time.saturating_sub(start_time) - ); - - assert!( - finish_time.saturating_sub(start_time) > expected_time, - "BUG: expected {}s, got {}s", - expected_time, - finish_time.saturating_sub(start_time) - ); - - peer_1.dump_frontier(); - peer_2.dump_frontier(); - - info!( - "Peer 1 stats: {:?}", - &peer_1.network.inv_state.as_ref().unwrap().block_stats - ); - info!( - "Peer 2 stats: {:?}", - &peer_2.network.inv_state.as_ref().unwrap().block_stats - ); - - let peer_1_inv = peer_2 - .network - .inv_state - .as_ref() - .unwrap() - .block_stats - .get(&peer_1.to_neighbor().addr) - .unwrap() - .inv - .clone(); - let peer_2_inv = peer_1 - .network - .inv_state - .as_ref() - .unwrap() - .block_stats - .get(&peer_2.to_neighbor().addr) - .unwrap() - .inv - .clone(); - - info!("Peer 1 inv: {:?}", &peer_1_inv); - info!("Peer 2 inv: {:?}", &peer_2_inv); - - info!("peer 1's view of peer 2: {:?}", &peer_2_inv); - - assert_eq!(peer_2_inv.num_sortitions, num_burn_blocks); - - // peer 1 should have learned that peer 2 has all the blocks - for i in 0..num_blocks { - assert!( - peer_2_inv.has_ith_block(i + first_stacks_block_height), - "Missing block {} (+ {})", - i, - first_stacks_block_height - ); - } - - // peer 1 should have learned that peer 2 has all the microblock streams - for i in 1..(num_blocks - 1) { - assert!( - peer_2_inv.has_ith_microblock_stream(i + first_stacks_block_height), - "Missing microblock {} (+ {})", - i, - first_stacks_block_height - ); - } - - let peer_1_inv = peer_2 - .network - .inv_state - .as_ref() - .unwrap() - .block_stats - .get(&peer_1.to_neighbor().addr) - .unwrap() - .inv - .clone(); - test_debug!("peer 2's view of peer 1: {:?}", &peer_1_inv); - - assert_eq!(peer_1_inv.num_sortitions, num_burn_blocks); - - // peer 2 should have learned that peer 1 has all the blocks as well - for i in 0..num_blocks { - assert!( - peer_1_inv.has_ith_block(i + first_stacks_block_height), - "Missing block {} (+ {})", - i, - first_stacks_block_height - ); - } - }) - } - #[test] #[ignore] fn test_sync_inv_2_peers_stale() { @@ -4428,6 +4161,8 @@ mod test { let mut peer_2_config = TestPeerConfig::new("test_sync_inv_2_peers_unstable", 31997, 41998); + let stable_confs = peer_1_config.burnchain.stable_confirmations as u64; + peer_1_config.add_neighbor(&peer_2_config.to_neighbor()); peer_2_config.add_neighbor(&peer_1_config.to_neighbor()); @@ -4460,7 +4195,7 @@ mod test { peer_1.process_stacks_epoch_at_tip(&stacks_block, µblocks); } else { // peer 1 diverges - test_debug!("Peer 1 diverges"); + test_debug!("Peer 1 diverges at {}", i + first_stacks_block_height); peer_1.next_burnchain_block(vec![]); } } @@ -4478,7 +4213,7 @@ mod test { assert_ne!(sn1.burn_header_hash, sn2.burn_header_hash); } - let num_stable_blocks = num_blocks - 1; + let num_stable_blocks = num_blocks - stable_confs; let num_burn_blocks = { let sn = SortitionDB::get_canonical_burn_chain_tip( @@ -4605,8 +4340,8 @@ mod test { .clone(); test_debug!("peer 2's view of peer 1: {:?}", &peer_1_inv); - assert_eq!(peer_2_inv.num_sortitions, num_burn_blocks - 1); - assert_eq!(peer_1_inv.num_sortitions, num_burn_blocks - 1); + assert_eq!(peer_2_inv.num_sortitions, num_burn_blocks - stable_confs); + assert_eq!(peer_1_inv.num_sortitions, num_burn_blocks - stable_confs); // only 8 reward cycles -- we couldn't agree on the 9th assert_eq!(peer_1_inv.pox_inv, vec![255]); @@ -4614,7 +4349,7 @@ mod test { // peer 1 should have learned that peer 2 has all the blocks, up to the point of // instability - for i in 0..(num_blocks - 1) { + for i in 0..(num_blocks - stable_confs) { assert!(peer_2_inv.has_ith_block(i + first_stacks_block_height)); if i > 0 { assert!(peer_2_inv.has_ith_microblock_stream(i + first_stacks_block_height)); @@ -4623,16 +4358,12 @@ mod test { } } - for i in 0..(num_blocks - 1) { + for i in 0..(num_blocks - stable_confs) { assert!(peer_1_inv.has_ith_block(i + first_stacks_block_height)); - if i > 0 && i != num_blocks - 2 { - // peer 1 doesn't have the final microblock stream, since no anchor block confirmed it - assert!(peer_1_inv.has_ith_microblock_stream(i + first_stacks_block_height)); - } } - assert!(!peer_2_inv.has_ith_block(num_blocks - 1)); - assert!(!peer_2_inv.has_ith_microblock_stream(num_blocks - 1)); + assert!(!peer_2_inv.has_ith_block(num_blocks - stable_confs)); + assert!(!peer_2_inv.has_ith_microblock_stream(num_blocks - stable_confs)); }) } @@ -4779,11 +4510,15 @@ mod test { round += 1; test_debug!( - "\n\ninv_1_count = {}, inv_2_count = {}, peer_1_sorts = {}, peer_2_sorts = {}", + "\n\ninv_1_count = {} for Error { @@ -317,6 +319,7 @@ impl fmt::Display for Error { Error::ConnectionCycle => write!(f, "Tried to connect to myself"), Error::NotFoundError => write!(f, "Requested data not found"), Error::Transient(ref s) => write!(f, "Transient network error: {}", s), + Error::ExpectedEndOfStream => write!(f, "Expected end-of-stream"), } } } @@ -376,6 +379,7 @@ impl error::Error for Error { Error::ConnectionCycle => None, Error::NotFoundError => None, Error::Transient(ref _s) => None, + Error::ExpectedEndOfStream => None, } } } @@ -1422,7 +1426,7 @@ pub enum HttpRequestType { TraitIdentifier, TipRequest, ), - MemPoolQuery(HttpRequestMetadata, MemPoolSyncData), + MemPoolQuery(HttpRequestMetadata, MemPoolSyncData, Option), /// catch-all for any errors we should surface from parsing ClientError(HttpRequestMetadata, ClientError), } @@ -1521,7 +1525,7 @@ pub enum HttpResponseType { GetAttachment(HttpResponseMetadata, GetAttachmentResponse), GetAttachmentsInv(HttpResponseMetadata, GetAttachmentsInvResponse), MemPoolTxStream(HttpResponseMetadata), - MemPoolTxs(HttpResponseMetadata, Vec), + MemPoolTxs(HttpResponseMetadata, Option, Vec), OptionsPreflight(HttpResponseMetadata), TransactionFeeEstimation(HttpResponseMetadata, RPCFeeEstimateResponse), // peer-given error responses @@ -1682,6 +1686,7 @@ impl_byte_array_message_codec!(StacksBlockId, 32); impl_byte_array_message_codec!(MessageSignature, 65); impl_byte_array_message_codec!(PeerAddress, 16); impl_byte_array_message_codec!(StacksPublicKeyBuffer, 33); +impl_byte_array_message_codec!(Txid, 32); impl_byte_array_serde!(ConsensusHash); @@ -2394,7 +2399,7 @@ pub mod test { ..TestPeerConfig::default() }; config.data_url = - UrlString::try_from(format!("http://localhost:{}", config.http_port).as_str()) + UrlString::try_from(format!("http://127.0.0.1:{}", config.http_port).as_str()) .unwrap(); config } @@ -2407,7 +2412,7 @@ pub mod test { ..TestPeerConfig::default() }; config.data_url = - UrlString::try_from(format!("http://localhost:{}", config.http_port).as_str()) + UrlString::try_from(format!("http://127.0.0.1:{}", config.http_port).as_str()) .unwrap(); config } diff --git a/src/net/p2p.rs b/src/net/p2p.rs index a5a96ba7a6..9b1bad73c8 100644 --- a/src/net/p2p.rs +++ b/src/net/p2p.rs @@ -89,8 +89,11 @@ use crate::types::chainstate::{PoxId, SortitionId, StacksBlockHeader}; #[derive(Debug)] pub enum NetworkRequest { Ban(Vec), - AdvertizeBlocks(BlocksAvailableMap), // announce to all wanting neighbors that we have these blocks - AdvertizeMicroblocks(BlocksAvailableMap), // announce to all wanting neighbors that we have these confirmed microblock streams + AdvertizeBlocks(BlocksAvailableMap, HashMap), // announce to all wanting neighbors that we have these blocks + AdvertizeMicroblocks( + BlocksAvailableMap, + HashMap)>, + ), // announce to all wanting neighbors that we have these confirmed microblock streams Relay(NeighborKey, StacksMessage), Broadcast(Vec, StacksMessageType), } @@ -138,14 +141,22 @@ impl NetworkHandle { } /// Advertize blocks - pub fn advertize_blocks(&mut self, blocks: BlocksAvailableMap) -> Result<(), net_error> { - let req = NetworkRequest::AdvertizeBlocks(blocks); + pub fn advertize_blocks( + &mut self, + blocks: BlocksAvailableMap, + block_data: HashMap, + ) -> Result<(), net_error> { + let req = NetworkRequest::AdvertizeBlocks(blocks, block_data); self.send_request(req) } /// Advertize microblocks - pub fn advertize_microblocks(&mut self, blocks: BlocksAvailableMap) -> Result<(), net_error> { - let req = NetworkRequest::AdvertizeMicroblocks(blocks); + pub fn advertize_microblocks( + &mut self, + microblocks: BlocksAvailableMap, + microblock_data: HashMap)>, + ) -> Result<(), net_error> { + let req = NetworkRequest::AdvertizeMicroblocks(microblocks, microblock_data); self.send_request(req) } @@ -199,12 +210,14 @@ pub enum PeerNetworkWorkState { pub enum MempoolSyncState { /// Picking an outbound peer PickOutboundPeer, - /// Resolving its data URL to a SocketAddr - ResolveURL(UrlString, DNSRequest), - /// Sending the request for mempool transactions - SendQuery(UrlString, SocketAddr), - /// Receiving the mempool response - RecvResponse(usize), + /// Resolving its data URL to a SocketAddr. Contains the data URL, DNS request handle, and + /// mempool page ID + ResolveURL(UrlString, DNSRequest, Txid), + /// Sending the request for mempool transactions. Contains the data URL, resolved socket, and + /// mempool page. + SendQuery(UrlString, SocketAddr, Txid), + /// Receiving the mempool response. Contains the URL, socket address, and event ID + RecvResponse(UrlString, SocketAddr, usize), } pub type PeerMap = HashMap; @@ -287,6 +300,8 @@ pub struct PeerNetwork { pub attachments_downloader: Option, // outstanding request to perform a mempool sync + // * mempool_sync_deadline is when the next mempool sync must start + // * mempool_sync_timeout is when the current mempool sync must stop mempool_state: MempoolSyncState, mempool_sync_deadline: u64, mempool_sync_timeout: u64, @@ -1016,15 +1031,15 @@ impl PeerNetwork { } Ok(()) } - NetworkRequest::AdvertizeBlocks(blocks) => { + NetworkRequest::AdvertizeBlocks(blocks, block_data) => { if !(cfg!(test) && self.connection_opts.disable_block_advertisement) { - self.advertize_blocks(blocks)?; + self.advertize_blocks(blocks, block_data)?; } Ok(()) } - NetworkRequest::AdvertizeMicroblocks(mblocks) => { + NetworkRequest::AdvertizeMicroblocks(mblocks, mblock_data) => { if !(cfg!(test) && self.connection_opts.disable_block_advertisement) { - self.advertize_microblocks(mblocks)?; + self.advertize_microblocks(mblocks, mblock_data)?; } Ok(()) } @@ -2153,7 +2168,7 @@ impl PeerNetwork { // did we run to completion? if let Some(txs) = txs_opt { debug!( - "{:?}: obtained {} transactions from mempool sync", + "{:?}: Mempool sync obtained {} transactions from mempool sync, and done receiving", &self.local_peer, txs.len() ); @@ -2165,8 +2180,19 @@ impl PeerNetwork { return Ok(None); } } - (false, _) => { - return Ok(None); + (false, txs_opt) => { + // did we get some transactions, but have more to get? + if let Some(txs) = txs_opt { + debug!( + "{:?}: Mempool sync obtained {} transactions from mempool sync, but have more", + &self.local_peer, + txs.len() + ); + + return Ok(Some(txs)); + } else { + return Ok(None); + } } } } @@ -2756,8 +2782,8 @@ impl PeerNetwork { } /// Push any blocks and microblock streams that we're holding onto out to our neighbors. - /// Push all but the last arrived Stacks block (the block-push and blocks-available protocols - /// should handle this, and we don't want the network to DDoS itself to death). + /// Start with the most-recently-arrived data, since this node is likely to have already + /// fetched older data via the block-downloader. fn try_push_local_data( &mut self, sortdb: &SortitionDB, @@ -2808,16 +2834,19 @@ impl PeerNetwork { .map(|inv_state| inv_state.block_stats.keys().map(|nk| nk.clone()).collect()) .unwrap_or(vec![]); - if self.antientropy_start_reward_cycle >= self.pox_id.num_inventory_reward_cycles() as u64 { - debug!("AntiEntropy: wrap around back to reward cycle 0"); - self.antientropy_start_reward_cycle = 0; + if self.antientropy_start_reward_cycle == 0 { + debug!( + "AntiEntropy: wrap around back to reward cycle {}", + self.pox_id.num_inventory_reward_cycles().saturating_sub(1) + ); + self.antientropy_start_reward_cycle = + self.pox_id.num_inventory_reward_cycles().saturating_sub(1) as u64; } let reward_cycle_start = self.antientropy_start_reward_cycle; - let reward_cycle_finish = cmp::min( - self.antientropy_start_reward_cycle + self.connection_opts.inv_reward_cycles, - self.pox_id.num_inventory_reward_cycles() as u64, - ); + let reward_cycle_finish = + self.antientropy_start_reward_cycle + .saturating_sub(self.connection_opts.inv_reward_cycles) as u64; self.antientropy_start_reward_cycle = reward_cycle_finish; @@ -2833,7 +2862,8 @@ impl PeerNetwork { reward_cycle_finish ); - for reward_cycle in reward_cycle_start..reward_cycle_finish { + // go from latest to earliest reward cycle + for reward_cycle in (reward_cycle_finish..reward_cycle_start).rev() { let local_blocks_inv = match self.get_local_blocks_inv(sortdb, chainstate, reward_cycle) { Ok(inv) => inv, @@ -3138,6 +3168,7 @@ impl PeerNetwork { fn mempool_sync_pick_outbound_peer( &mut self, dns_client_opt: &mut Option<&mut DNSClient>, + page_id: &Txid, ) -> Result, net_error> { if self.peers.len() == 0 { debug!("No peers connected; cannot do mempool sync"); @@ -3181,7 +3212,7 @@ impl PeerNetwork { } if let Some(url) = mempool_sync_data_url { - self.mempool_sync_begin_resolve_data_url(url, dns_client_opt) + self.mempool_sync_begin_resolve_data_url(url, dns_client_opt, page_id) } else { debug!("No peer has a data URL, so no mempool sync can happen"); Ok(None) @@ -3197,6 +3228,7 @@ impl PeerNetwork { &self, url_str: UrlString, dns_client_opt: &mut Option<&mut DNSClient>, + page_id: &Txid, ) -> Result, net_error> { // start resolving let url = url_str.parse_to_block_url()?; @@ -3210,7 +3242,11 @@ impl PeerNetwork { // bare IP address? if let Some(addr) = PeerNetwork::try_get_url_ip(&url_str)? { - return Ok(Some(MempoolSyncState::SendQuery(url_str, addr))); + return Ok(Some(MempoolSyncState::SendQuery( + url_str, + addr, + page_id.clone(), + ))); } else if let Some(url::Host::Domain(domain)) = url.host() { if let Some(ref mut dns_client) = dns_client_opt { // begin DNS query @@ -3228,6 +3264,7 @@ impl PeerNetwork { return Ok(Some(MempoolSyncState::ResolveURL( url_str, DNSRequest::new(domain.to_string(), port, 0), + page_id.clone(), ))); } else { // can't proceed -- no DNS client @@ -3296,11 +3333,13 @@ impl PeerNetwork { addr: &SocketAddr, mempool: &MemPoolDB, chainstate: &mut StacksChainState, + page_id: Txid, ) -> Result<(bool, Option), net_error> { let sync_data = mempool.make_mempool_sync_data()?; let request = HttpRequestType::MemPoolQuery( HttpRequestMetadata::from_host(PeerHost::from_socketaddr(addr)), sync_data, + Some(page_id), ); let event_id = self.connect_or_send_http_request( @@ -3316,21 +3355,24 @@ impl PeerNetwork { /// Receive the mempool sync response. /// Return Ok(true, ..) if we're done with the mempool sync. /// Return Ok(false, ..) if we have more work to do. - /// Returns transactions if we're done, and we got transactions + /// Returns the page ID of the next request to make, and the list of transactions we got fn mempool_sync_recv_response( &mut self, event_id: usize, - ) -> Result<(bool, Option>), net_error> { - PeerNetwork::with_http(self, |_, http| { + ) -> Result<(bool, Option, Option>), net_error> { + PeerNetwork::with_http(self, |network, http| { match http.get_conversation(event_id) { None => { if http.is_connecting(event_id) { - debug!("Mempool sync event {} is not connected yet", event_id,); - return Ok((false, None)); + debug!( + "{:?}: Mempool sync event {} is not connected yet", + &network.local_peer, event_id + ); + return Ok((false, None, None)); } else { // conversation died - debug!("Mempool sync peer hung up"); - return Ok((true, None)); + debug!("{:?}: Mempool sync peer hung up", &network.local_peer); + return Ok((true, None, None)); } } Some(ref mut convo) => { @@ -3338,18 +3380,22 @@ impl PeerNetwork { None => { // still waiting debug!( - "Mempool sync event {} still waiting for a response", - event_id + "{:?}: Mempool sync event {} still waiting for a response", + &network.local_peer, event_id ); - return Ok((false, None)); + return Ok((false, None, None)); } Some(http_response) => match http_response { - HttpResponseType::MemPoolTxs(_, txs) => { - return Ok((true, Some(txs))); + HttpResponseType::MemPoolTxs(_, page_id_opt, txs) => { + debug!("{:?}: Mempool sync received response for {} txs, next page {:?}", &network.local_peer, txs.len(), &page_id_opt); + return Ok((true, page_id_opt, Some(txs))); } _ => { - warn!("Mempool sync request received {:?}", &http_response); - return Ok((true, None)); + warn!( + "{:?}: Mempool sync request received {:?}", + &network.local_peer, &http_response + ); + return Ok((true, None, None)); } }, } @@ -3369,8 +3415,8 @@ impl PeerNetwork { ) -> Result<(bool, Option>), net_error> { if get_epoch_time_secs() <= self.mempool_sync_deadline { debug!( - "Wait until {} to do a mempool sync", - self.mempool_sync_deadline + "{:?}: Wait until {} to do a mempool sync", + &self.local_peer, self.mempool_sync_deadline ); return Ok((true, None)); } @@ -3381,7 +3427,10 @@ impl PeerNetwork { get_epoch_time_secs() + self.connection_opts.mempool_sync_timeout; } else { if get_epoch_time_secs() > self.mempool_sync_timeout { - debug!("Mempool sync took too long; terminating"); + debug!( + "{:?}: Mempool sync took too long; terminating", + &self.local_peer + ); self.mempool_sync_reset(); return Ok((true, None)); } @@ -3391,12 +3440,15 @@ impl PeerNetwork { // Once we get blocked, return. loop { let cur_state = self.mempool_state.clone(); - debug!("Mempool sync state is {:?}", &cur_state); + debug!( + "{:?}: Mempool sync state is {:?}", + &self.local_peer, &cur_state + ); match cur_state { MempoolSyncState::PickOutboundPeer => { // 1. pick a random outbound conversation. if let Some(next_state) = - self.mempool_sync_pick_outbound_peer(dns_client_opt)? + self.mempool_sync_pick_outbound_peer(dns_client_opt, &Txid([0u8; 32]))? { // success! can advance to either resolve a URL or to send a query self.mempool_state = next_state; @@ -3406,7 +3458,7 @@ impl PeerNetwork { return Ok((true, None)); } } - MempoolSyncState::ResolveURL(ref url_str, ref dns_request) => { + MempoolSyncState::ResolveURL(ref url_str, ref dns_request, ref page_id) => { // 2. resolve its data URL match self.mempool_sync_resolve_data_url( url_str, @@ -3415,7 +3467,8 @@ impl PeerNetwork { )? { (false, Some(addr)) => { // success! advance - self.mempool_state = MempoolSyncState::SendQuery(url_str.clone(), addr); + self.mempool_state = + MempoolSyncState::SendQuery(url_str.clone(), addr, page_id.clone()); } (false, None) => { // try again later @@ -3428,12 +3481,24 @@ impl PeerNetwork { } } } - MempoolSyncState::SendQuery(ref url, ref addr) => { + MempoolSyncState::SendQuery(ref url, ref addr, ref page_id) => { // 3. ask for the remote peer's mempool's novel txs - match self.mempool_sync_send_query(url, addr, mempool, chainstate)? { + debug!( + "{:?}: Mempool sync will query {} for mempool transactions at {}", + &self.local_peer, url, page_id + ); + match self.mempool_sync_send_query( + url, + addr, + mempool, + chainstate, + page_id.clone(), + )? { (false, Some(event_id)) => { // success! advance - self.mempool_state = MempoolSyncState::RecvResponse(event_id); + debug!("{:?}: Mempool sync query {} for mempool transactions at {} on event {}", &self.local_peer, url, page_id, event_id); + self.mempool_state = + MempoolSyncState::RecvResponse(url.clone(), addr.clone(), event_id); } (false, None) => { // try again later @@ -3446,23 +3511,45 @@ impl PeerNetwork { } } } - MempoolSyncState::RecvResponse(ref event_id) => { + MempoolSyncState::RecvResponse(ref url, ref addr, ref event_id) => { match self.mempool_sync_recv_response(*event_id)? { - (true, Some(txs)) => { + (true, next_page_id_opt, Some(txs)) => { + debug!( + "{:?}: Mempool sync received {} transactions; next page is {:?}", + &self.local_peer, + txs.len(), + &next_page_id_opt + ); + // done! got data - self.mempool_sync_reset(); - return Ok((true, Some(txs))); + let ret = match next_page_id_opt { + Some(next_page_id) => { + // get the next page + self.mempool_state = MempoolSyncState::SendQuery( + url.clone(), + addr.clone(), + next_page_id, + ); + false + } + None => { + // done + self.mempool_sync_reset(); + true + } + }; + return Ok((ret, Some(txs))); } - (true, None) => { + (true, _, None) => { // done! did not get data self.mempool_sync_reset(); return Ok((true, None)); } - (false, None) => { + (false, _, None) => { // still receiving; try again later return Ok((false, None)); } - (false, Some(_)) => { + (false, _, Some(_)) => { // should never happen if cfg!(test) { panic!("Reached invalid state in {:?}, aborting...", &cur_state); @@ -4801,7 +4888,13 @@ impl PeerNetwork { Ok(()) } - /// Refresh view of burnchain, if needed + /// Refresh view of burnchain, if needed. + /// If the burnchain view changes, then take the following additional steps: + /// * hint to the inventory sync state-machine to restart, since we potentially have a new + /// block to go fetch + /// * hint to the download state machine to start looking for the new block at the new + /// stable sortition height + /// * hint to the antientropy protocol to reset to the latest reward cycle pub fn refresh_burnchain_view( &mut self, sortdb: &SortitionDB, @@ -4839,6 +4932,12 @@ impl PeerNetwork { false, ); + // set up the antientropy protocol to try pushing the latest block + // (helps if you're a miner who gets temporarily disconnected) + self.antientropy_last_push_ts = get_epoch_time_secs(); + self.antientropy_start_reward_cycle = + self.pox_id.num_inventory_reward_cycles().saturating_sub(1) as u64; + // update cached burnchain view for /v2/info self.chain_view = new_chain_view; self.chain_view_stable_consensus_hash = new_chain_view_stable_consensus_hash; @@ -5802,6 +5901,7 @@ mod test { sortdb, chainstate, mempool, + false, None, None, ) @@ -5819,6 +5919,7 @@ mod test { sortdb, chainstate, mempool, + false, None, None, ) @@ -5856,4 +5957,195 @@ mod test { } }); } + + #[test] + #[ignore] + fn test_mempool_sync_2_peers_paginated() { + with_timeout(600, || { + // peer 1 gets some transactions; verify peer 2 gets them all + let mut peer_1_config = + TestPeerConfig::new("test_mempool_sync_2_peers_paginated", 2214, 2215); + let mut peer_2_config = + TestPeerConfig::new("test_mempool_sync_2_peers_paginated", 2216, 2217); + + peer_1_config.add_neighbor(&peer_2_config.to_neighbor()); + peer_2_config.add_neighbor(&peer_1_config.to_neighbor()); + + peer_1_config.connection_opts.mempool_sync_interval = 1; + peer_2_config.connection_opts.mempool_sync_interval = 1; + + let num_txs = 1024; + let pks: Vec<_> = (0..num_txs).map(|_| StacksPrivateKey::new()).collect(); + let addrs: Vec<_> = pks.iter().map(|pk| to_addr(pk)).collect(); + let initial_balances: Vec<_> = addrs + .iter() + .map(|a| (a.to_account_principal(), 1000000000)) + .collect(); + + peer_1_config.initial_balances = initial_balances.clone(); + peer_2_config.initial_balances = initial_balances.clone(); + + let mut peer_1 = TestPeer::new(peer_1_config); + let mut peer_2 = TestPeer::new(peer_2_config); + + let num_blocks = 10; + let first_stacks_block_height = { + let sn = SortitionDB::get_canonical_burn_chain_tip( + &peer_1.sortdb.as_ref().unwrap().conn(), + ) + .unwrap(); + sn.block_height + 1 + }; + + for i in 0..num_blocks { + let (burn_ops, stacks_block, microblocks) = peer_2.make_default_tenure(); + + peer_1.next_burnchain_block(burn_ops.clone()); + peer_2.next_burnchain_block(burn_ops.clone()); + + peer_1.process_stacks_epoch_at_tip(&stacks_block, µblocks); + peer_2.process_stacks_epoch_at_tip(&stacks_block, µblocks); + } + + let addr = StacksAddress { + version: C32_ADDRESS_VERSION_TESTNET_SINGLESIG, + bytes: Hash160([0xff; 20]), + }; + + // fill peer 1 with lots of transactions + let mut txs = HashMap::new(); + let mut peer_1_mempool = peer_1.mempool.take().unwrap(); + let mut mempool_tx = peer_1_mempool.tx_begin().unwrap(); + for i in 0..num_txs { + let pk = &pks[i]; + let mut tx = StacksTransaction { + version: TransactionVersion::Testnet, + chain_id: 0x80000000, + auth: TransactionAuth::from_p2pkh(&pk).unwrap(), + anchor_mode: TransactionAnchorMode::Any, + post_condition_mode: TransactionPostConditionMode::Allow, + post_conditions: vec![], + payload: TransactionPayload::TokenTransfer( + addr.to_account_principal(), + 123, + TokenTransferMemo([0u8; 34]), + ), + }; + tx.set_tx_fee(1000); + tx.set_origin_nonce(0); + + let mut tx_signer = StacksTransactionSigner::new(&tx); + tx_signer.sign_origin(&pk).unwrap(); + + let tx = tx_signer.get_tx().unwrap(); + + let txid = tx.txid(); + let tx_bytes = tx.serialize_to_vec(); + let origin_addr = tx.origin_address(); + let origin_nonce = tx.get_origin_nonce(); + let sponsor_addr = tx.sponsor_address().unwrap_or(origin_addr.clone()); + let sponsor_nonce = tx.get_sponsor_nonce().unwrap_or(origin_nonce); + let tx_fee = tx.get_tx_fee(); + + txs.insert(tx.txid(), tx.clone()); + + // should succeed + MemPoolDB::try_add_tx( + &mut mempool_tx, + peer_1.chainstate(), + &ConsensusHash([0x1 + (num_blocks as u8); 20]), + &BlockHeaderHash([0x2 + (num_blocks as u8); 32]), + txid.clone(), + tx_bytes, + tx_fee, + num_blocks, + &origin_addr, + origin_nonce, + &sponsor_addr, + sponsor_nonce, + None, + ) + .unwrap(); + + eprintln!("Added {} {}", i, &txid); + } + mempool_tx.commit().unwrap(); + peer_1.mempool = Some(peer_1_mempool); + + let num_burn_blocks = { + let sn = SortitionDB::get_canonical_burn_chain_tip( + peer_1.sortdb.as_ref().unwrap().conn(), + ) + .unwrap(); + sn.block_height + 1 + }; + + let mut round = 0; + let mut peer_1_mempool_txs = 0; + let mut peer_2_mempool_txs = 0; + + while peer_1_mempool_txs < num_txs || peer_2_mempool_txs < num_txs { + if let Ok(mut result) = peer_1.step() { + let lp = peer_1.network.local_peer.clone(); + peer_1 + .with_db_state(|sortdb, chainstate, relayer, mempool| { + relayer.process_network_result( + &lp, + &mut result, + sortdb, + chainstate, + mempool, + false, + None, + None, + ) + }) + .unwrap(); + } + + if let Ok(mut result) = peer_2.step() { + let lp = peer_2.network.local_peer.clone(); + peer_2 + .with_db_state(|sortdb, chainstate, relayer, mempool| { + relayer.process_network_result( + &lp, + &mut result, + sortdb, + chainstate, + mempool, + false, + None, + None, + ) + }) + .unwrap(); + } + + round += 1; + + let mp = peer_1.mempool.take().unwrap(); + peer_1_mempool_txs = MemPoolDB::get_all_txs(mp.conn()).unwrap().len(); + peer_1.mempool.replace(mp); + + let mp = peer_2.mempool.take().unwrap(); + peer_2_mempool_txs = MemPoolDB::get_all_txs(mp.conn()).unwrap().len(); + peer_2.mempool.replace(mp); + + info!( + "Peer 1: {}, Peer 2: {}", + peer_1_mempool_txs, peer_2_mempool_txs + ); + } + + info!("Completed mempool sync in {} step(s)", round); + + let mp = peer_2.mempool.take().unwrap(); + let peer_2_mempool_txs = MemPoolDB::get_all_txs(mp.conn()).unwrap(); + peer_2.mempool.replace(mp); + + for tx in peer_2_mempool_txs { + assert_eq!(&tx.tx, txs.get(&tx.tx.txid()).unwrap()); + } + }); + } } diff --git a/src/net/relay.rs b/src/net/relay.rs index fae8d604b1..e8ee8df0fd 100644 --- a/src/net/relay.rs +++ b/src/net/relay.rs @@ -617,15 +617,15 @@ impl Relayer { } /// Preprocess all our downloaded blocks. - /// Return burn block hashes for the blocks that we got. /// Does not fail on invalid blocks; just logs a warning. - /// Returns the set of consensus hashes for the sortitions that selected these blocks + /// Returns the set of consensus hashes for the sortitions that selected these blocks, and the + /// blocks themselves fn preprocess_downloaded_blocks( sort_ic: &SortitionDBConn, network_result: &mut NetworkResult, chainstate: &mut StacksChainState, - ) -> HashSet { - let mut new_blocks = HashSet::new(); + ) -> HashMap { + let mut new_blocks = HashMap::new(); for (consensus_hash, block, download_time) in network_result.blocks.iter() { match Relayer::process_new_anchored_block( @@ -637,7 +637,7 @@ impl Relayer { ) { Ok(accepted) => { if accepted { - new_blocks.insert((*consensus_hash).clone()); + new_blocks.insert((*consensus_hash).clone(), block.clone()); } } Err(chainstate_error::InvalidStacksBlock(msg)) => { @@ -668,8 +668,8 @@ impl Relayer { sort_ic: &SortitionDBConn, network_result: &mut NetworkResult, chainstate: &mut StacksChainState, - ) -> Result<(HashSet, Vec), net_error> { - let mut new_blocks = HashSet::new(); + ) -> Result<(HashMap, Vec), net_error> { + let mut new_blocks = HashMap::new(); let mut bad_neighbors = vec![]; // process blocks pushed to us. @@ -725,7 +725,7 @@ impl Relayer { "Accepted block {}/{} from {}", &consensus_hash, &bhh, &neighbor_key ); - new_blocks.insert(consensus_hash.clone()); + new_blocks.insert(consensus_hash.clone(), block.clone()); } } Err(chainstate_error::InvalidStacksBlock(msg)) => { @@ -759,8 +759,8 @@ impl Relayer { fn preprocess_downloaded_microblocks( network_result: &mut NetworkResult, chainstate: &mut StacksChainState, - ) -> HashSet { - let mut ret = HashSet::new(); + ) -> HashMap)> { + let mut ret = HashMap::new(); for (consensus_hash, microblock_stream, _download_time) in network_result.confirmed_microblocks.iter() { @@ -788,7 +788,12 @@ impl Relayer { } } - ret.insert((*consensus_hash).clone()); + let index_block_hash = + StacksBlockHeader::make_index_block_hash(consensus_hash, &anchored_block_hash); + ret.insert( + (*consensus_hash).clone(), + (index_block_hash, microblock_stream.clone()), + ); } ret } @@ -904,8 +909,8 @@ impl Relayer { /// Process blocks and microblocks that we recieved, both downloaded (confirmed) and streamed /// (unconfirmed). Returns: - /// * list of consensus hashes that elected the newly-discovered blocks, so we can turn them into BlocksAvailable messages - /// * list of confirmed microblock consensus hashes for newly-discovered microblock streams, so we can turn them into MicroblocksAvailable messages + /// * set of consensus hashes that elected the newly-discovered blocks, and the blocks, so we can turn them into BlocksAvailable / BlocksData messages + /// * set of confirmed microblock consensus hashes for newly-discovered microblock streams, and the streams, so we can turn them into MicroblocksAvailable / MicroblocksData messages /// * list of unconfirmed microblocks that got pushed to us, as well as their relayers (so we can forward them) /// * list of neighbors that served us invalid data (so we can ban them) pub fn process_new_blocks( @@ -915,15 +920,14 @@ impl Relayer { coord_comms: Option<&CoordinatorChannels>, ) -> Result< ( - Vec, - Vec, + HashMap, + HashMap)>, Vec<(Vec, MicroblocksData)>, Vec, ), net_error, > { - let mut new_blocks = HashSet::new(); - let mut new_confirmed_microblocks = HashSet::new(); + let mut new_blocks = HashMap::new(); let mut bad_neighbors = vec![]; { @@ -932,35 +936,48 @@ impl Relayer { // process blocks we downloaded let new_dled_blocks = Relayer::preprocess_downloaded_blocks(&sort_ic, network_result, chainstate); - for new_dled_block in new_dled_blocks.into_iter() { - debug!("Received downloaded block for {}", &new_dled_block); - new_blocks.insert(new_dled_block); + for (new_dled_block_ch, block_data) in new_dled_blocks.into_iter() { + debug!( + "Received downloaded block for {}/{}", + &new_dled_block_ch, + &block_data.block_hash(); + "consensus_hash" => %new_dled_block_ch, + "block_hash" => %block_data.block_hash() + ); + new_blocks.insert(new_dled_block_ch, block_data); } // process blocks pushed to us let (new_pushed_blocks, mut new_bad_neighbors) = Relayer::preprocess_pushed_blocks(&sort_ic, network_result, chainstate)?; - for new_pushed_block in new_pushed_blocks.into_iter() { - debug!("Received p2p-pushed block for {}", &new_pushed_block); - new_blocks.insert(new_pushed_block); + for (new_pushed_block_ch, block_data) in new_pushed_blocks.into_iter() { + debug!( + "Received p2p-pushed block for {}/{}", + &new_pushed_block_ch, + &block_data.block_hash(); + "consensus_hash" => %new_pushed_block_ch, + "block_hash" => %block_data.block_hash() + ); + new_blocks.insert(new_pushed_block_ch, block_data); } bad_neighbors.append(&mut new_bad_neighbors); // process blocks uploaded to us. They've already been stored for block_data in network_result.uploaded_blocks.drain(..) { - for (consensus_hash, _) in block_data.blocks.into_iter() { - debug!("Received http-uploaded block for {}", &consensus_hash); - new_blocks.insert(consensus_hash); + for (consensus_hash, block) in block_data.blocks.into_iter() { + debug!( + "Received http-uploaded block for {}/{}", + &consensus_hash, + block.block_hash() + ); + new_blocks.insert(consensus_hash, block); } } } // process microblocks we downloaded - let mut new_dled_mblocks = + let new_confirmed_microblocks = Relayer::preprocess_downloaded_microblocks(network_result, chainstate); - for new_dled_mblock in new_dled_mblocks.drain() { - new_confirmed_microblocks.insert(new_dled_mblock); - } // process microblocks pushed to us let (new_microblocks, mut new_bad_neighbors) = @@ -983,8 +1000,8 @@ impl Relayer { } Ok(( - new_blocks.into_iter().collect(), - new_confirmed_microblocks.into_iter().collect(), + new_blocks, + new_confirmed_microblocks, new_microblocks, bad_neighbors, )) @@ -1070,8 +1087,12 @@ impl Relayer { Ok(ret) } - pub fn advertize_blocks(&mut self, available: BlocksAvailableMap) -> Result<(), net_error> { - self.p2p.advertize_blocks(available) + pub fn advertize_blocks( + &mut self, + available: BlocksAvailableMap, + blocks: HashMap, + ) -> Result<(), net_error> { + self.p2p.advertize_blocks(available, blocks) } pub fn broadcast_block( @@ -1185,6 +1206,7 @@ impl Relayer { sortdb: &mut SortitionDB, chainstate: &mut StacksChainState, mempool: &mut MemPoolDB, + ibd: bool, coord_comms: Option<&CoordinatorChannels>, event_observer: Option<&dyn MemPoolEventDispatcher>, ) -> Result { @@ -1204,25 +1226,49 @@ impl Relayer { } // have the p2p thread tell our neighbors about newly-discovered blocks - let available = Relayer::load_blocks_available_data(sortdb, new_blocks)?; + let new_block_chs = new_blocks.iter().map(|(ch, _)| ch.clone()).collect(); + let available = Relayer::load_blocks_available_data(sortdb, new_block_chs)?; if available.len() > 0 { - debug!("{:?}: Blocks available: {}", &_local_peer, available.len()); - if let Err(e) = self.p2p.advertize_blocks(available) { - warn!("Failed to advertize new blocks: {:?}", &e); + if !ibd { + debug!("{:?}: Blocks available: {}", &_local_peer, available.len()); + if let Err(e) = self.p2p.advertize_blocks(available, new_blocks) { + warn!("Failed to advertize new blocks: {:?}", &e); + } + } else { + debug!( + "{:?}: Blocks available, but will not advertize since in IBD: {}", + &_local_peer, + available.len() + ); } } // have the p2p thread tell our neighbors about newly-discovered confirmed microblock streams + let new_mblock_chs = new_confirmed_microblocks + .iter() + .map(|(ch, _)| ch.clone()) + .collect(); let mblocks_available = - Relayer::load_blocks_available_data(sortdb, new_confirmed_microblocks)?; + Relayer::load_blocks_available_data(sortdb, new_mblock_chs)?; if mblocks_available.len() > 0 { - debug!( - "{:?}: Confirmed microblock streams available: {}", - &_local_peer, - mblocks_available.len() - ); - if let Err(e) = self.p2p.advertize_microblocks(mblocks_available) { - warn!("Failed to advertize new confirmed microblocks: {:?}", &e); + if !ibd { + debug!( + "{:?}: Confirmed microblock streams available: {}", + &_local_peer, + mblocks_available.len() + ); + if let Err(e) = self + .p2p + .advertize_microblocks(mblocks_available, new_confirmed_microblocks) + { + warn!("Failed to advertize new confirmed microblocks: {:?}", &e); + } + } else { + debug!( + "{:?}: Confirmed microblock streams available, but will not advertize since in IBD: {}", + &_local_peer, + mblocks_available.len() + ); } } @@ -1302,9 +1348,10 @@ impl Relayer { impl PeerNetwork { /// Find out which neighbors need at least one (micro)block from the availability set. - /// For outbound neighbors (i.e. ones we have inv data for), only send (Micro)BlocksAvailable messages - /// for (micro)blocks we have that they don't have. For inbound neighbors (i.e. ones we don't have - /// inv data for), pick a random set and send them the full (Micro)BlocksAvailable message. + /// For outbound neighbors (i.e. ones we have inv data for), send (Micro)BlocksData messages if + /// we can; fall back to (Micro)BlocksAvailable messages if we can't. + /// For inbound neighbors (i.e. ones we don't have inv data for), pick a random set and send them + /// the full (Micro)BlocksAvailable message. fn find_block_recipients( &mut self, available: &BlocksAvailableMap, @@ -1366,7 +1413,7 @@ impl PeerNetwork { fn advertize_to_peer( &mut self, recipient: &NeighborKey, - wanted: &Vec<(ConsensusHash, BurnchainHeaderHash)>, + wanted: &[(ConsensusHash, BurnchainHeaderHash)], mut msg_builder: S, ) -> () where @@ -1403,51 +1450,168 @@ impl PeerNetwork { } } + /// Try to push a block to a peer. + /// Absorb and log errors. + fn push_block_to_peer( + &mut self, + recipient: &NeighborKey, + consensus_hash: ConsensusHash, + block: StacksBlock, + ) -> () { + let blk_hash = block.block_hash(); + let ch = consensus_hash.clone(); + let payload = BlocksData { + blocks: vec![(consensus_hash, block)], + }; + let message = match self.sign_for_peer(recipient, StacksMessageType::Blocks(payload)) { + Ok(m) => m, + Err(e) => { + warn!( + "{:?}: Failed to sign for {:?}: {:?}", + &self.local_peer, recipient, &e + ); + return; + } + }; + + debug!( + "{:?}: Push block {}/{} to {:?}", + &self.local_peer, &ch, &blk_hash, recipient + ); + + // absorb errors + let _ = self.relay_signed_message(recipient, message).map_err(|e| { + warn!( + "{:?}: Failed to push block {}/{} to {:?}: {:?}", + &self.local_peer, &ch, &blk_hash, recipient, &e + ); + e + }); + } + + /// Try to push a confirmed microblock stream to a peer. + /// Absorb and log errors. + fn push_microblocks_to_peer( + &mut self, + recipient: &NeighborKey, + index_block_hash: StacksBlockId, + microblocks: Vec, + ) -> () { + let idx_bhh = index_block_hash.clone(); + let payload = MicroblocksData { + index_anchor_block: index_block_hash, + microblocks: microblocks, + }; + let message = match self.sign_for_peer(recipient, StacksMessageType::Microblocks(payload)) { + Ok(m) => m, + Err(e) => { + warn!( + "{:?}: Failed to sign for {:?}: {:?}", + &self.local_peer, recipient, &e + ); + return; + } + }; + + debug!( + "{:?}: Push microblocks for {} to {:?}", + &self.local_peer, &idx_bhh, recipient + ); + + // absorb errors + let _ = self.relay_signed_message(recipient, message).map_err(|e| { + warn!( + "{:?}: Failed to push microblocks for {} to {:?}: {:?}", + &self.local_peer, &idx_bhh, recipient, &e + ); + e + }); + } + /// Announce blocks that we have to an outbound peer that doesn't have them. - /// Only advertize blocks and microblocks we have that the outbound peer doesn't. - fn advertize_to_outbound_peer( + /// If we were given the block, send the block itself. + /// Otherwise, send a BlocksAvailable. + fn advertize_or_push_blocks_to_outbound_peer( &mut self, recipient: &NeighborKey, available: &BlocksAvailableMap, - microblocks: bool, + blocks: &HashMap, ) -> Result<(), net_error> { - let wanted = PeerNetwork::with_inv_state(self, |_network, inv_state| { - let mut wanted: Vec<(ConsensusHash, BurnchainHeaderHash)> = vec![]; + PeerNetwork::with_inv_state(self, |network, inv_state| { if let Some(stats) = inv_state.block_stats.get(recipient) { for (bhh, (block_height, ch)) in available.iter() { - let has_data = if microblocks { - stats.inv.has_ith_microblock_stream(*block_height) - } else { - stats.inv.has_ith_block(*block_height) - }; - - if !has_data { + if !stats.inv.has_ith_block(*block_height) { test_debug!( - "{:?}: Outbound neighbor {:?} wants {} data for {}", - &_network.local_peer, + "{:?}: Outbound neighbor {:?} wants block data for {}", + &network.local_peer, recipient, - if microblocks { "microblock" } else { "block" }, bhh ); - wanted.push(((*ch).clone(), (*bhh).clone())); + match blocks.get(ch) { + Some(block) => { + network.push_block_to_peer( + recipient, + (*ch).clone(), + (*block).clone(), + ); + } + None => { + network.advertize_to_peer( + recipient, + &[((*ch).clone(), (*bhh).clone())], + |payload| StacksMessageType::BlocksAvailable(payload), + ); + } + } } } } - Ok(wanted) - })?; + Ok(()) + }) + } - if microblocks { - self.advertize_to_peer(recipient, &wanted, |payload| { - StacksMessageType::MicroblocksAvailable(payload) - }); - } else { - self.advertize_to_peer(recipient, &wanted, |payload| { - StacksMessageType::BlocksAvailable(payload) - }); - } + /// Announce microblocks that we have to an outbound peer that doesn't have them. + /// If we were given the microblock stream, send the stream itself. + /// Otherwise, send a MicroblocksAvailable. + fn advertize_or_push_microblocks_to_outbound_peer( + &mut self, + recipient: &NeighborKey, + available: &BlocksAvailableMap, + microblocks: &HashMap)>, + ) -> Result<(), net_error> { + PeerNetwork::with_inv_state(self, |network, inv_state| { + if let Some(stats) = inv_state.block_stats.get(recipient) { + for (bhh, (block_height, ch)) in available.iter() { + if !stats.inv.has_ith_microblock_stream(*block_height) { + test_debug!( + "{:?}: Outbound neighbor {:?} wants microblock data for {}", + &network.local_peer, + recipient, + bhh + ); - Ok(()) + match microblocks.get(ch) { + Some((stacks_block_id, mblocks)) => { + network.push_microblocks_to_peer( + recipient, + stacks_block_id.clone(), + mblocks.clone(), + ); + } + None => { + network.advertize_to_peer( + recipient, + &[((*ch).clone(), (*bhh).clone())], + |payload| StacksMessageType::MicroblocksAvailable(payload), + ); + } + } + } + } + } + Ok(()) + }) } /// Announce blocks that we have to an inbound peer that might not have them. @@ -1473,13 +1637,16 @@ impl PeerNetwork { /// Announce blocks that we have to a subset of inbound and outbound peers. /// * Outbound peers receive announcements for blocks that we know they don't have, based on - /// the inv state we synchronized from them. + /// the inv state we synchronized from them. We send the blocks themselves, if we have them. /// * Inbound peers are chosen uniformly at random to receive a full announcement, since we - /// don't track their inventory state. + /// don't track their inventory state. We send blocks-available messages to them, since they + /// can turn around and ask us for the block data. + /// Return the number of inbound and outbound neighbors that have received it pub fn advertize_blocks( &mut self, availability_data: BlocksAvailableMap, - ) -> Result<(), net_error> { + blocks: HashMap, + ) -> Result<(usize, usize), net_error> { let (mut outbound_recipients, mut inbound_recipients) = self.find_block_recipients(&availability_data)?; debug!( @@ -1490,6 +1657,9 @@ impl PeerNetwork { inbound_recipients.len() ); + let num_inbound = inbound_recipients.len(); + let num_outbound = outbound_recipients.len(); + for recipient in outbound_recipients.drain(..) { debug!( "{:?}: Advertize {} blocks to outbound peer {}", @@ -1497,7 +1667,11 @@ impl PeerNetwork { availability_data.len(), &recipient ); - self.advertize_to_outbound_peer(&recipient, &availability_data, false)?; + self.advertize_or_push_blocks_to_outbound_peer( + &recipient, + &availability_data, + &blocks, + )?; } for recipient in inbound_recipients.drain(..) { debug!( @@ -1510,7 +1684,7 @@ impl PeerNetwork { StacksMessageType::BlocksAvailable(payload) })?; } - Ok(()) + Ok((num_inbound, num_outbound)) } /// Announce confirmed microblocks that we have to a subset of inbound and outbound peers. @@ -1518,14 +1692,19 @@ impl PeerNetwork { /// the inv state we synchronized from them. /// * Inbound peers are chosen uniformly at random to receive a full announcement, since we /// don't track their inventory state. + /// Return the number of inbound and outbound neighbors that have received it pub fn advertize_microblocks( &mut self, availability_data: BlocksAvailableMap, - ) -> Result<(), net_error> { + microblocks: HashMap)>, + ) -> Result<(usize, usize), net_error> { let (mut outbound_recipients, mut inbound_recipients) = self.find_block_recipients(&availability_data)?; debug!("{:?}: Advertize {} confirmed microblock streams to {} inbound peers, {} outbound peers", &self.local_peer, availability_data.len(), outbound_recipients.len(), inbound_recipients.len()); + let num_inbound = inbound_recipients.len(); + let num_outbound = outbound_recipients.len(); + for recipient in outbound_recipients.drain(..) { debug!( "{:?}: Advertize {} confirmed microblock streams to outbound peer {}", @@ -1533,7 +1712,11 @@ impl PeerNetwork { availability_data.len(), &recipient ); - self.advertize_to_outbound_peer(&recipient, &availability_data, true)?; + self.advertize_or_push_microblocks_to_outbound_peer( + &recipient, + &availability_data, + µblocks, + )?; } for recipient in inbound_recipients.drain(..) { debug!( @@ -1546,7 +1729,7 @@ impl PeerNetwork { StacksMessageType::MicroblocksAvailable(payload) })?; } - Ok(()) + Ok((num_inbound, num_outbound)) } /// Update accounting information for relayed messages from a network result. @@ -1998,7 +2181,19 @@ mod test { peer_configs[1].connection_opts.disable_natpunch = true; peer_configs[2].connection_opts.disable_natpunch = true; + // do not push blocks and microblocks; only announce them + peer_configs[0].connection_opts.disable_block_push = true; + peer_configs[1].connection_opts.disable_block_push = true; + peer_configs[2].connection_opts.disable_block_push = true; + + peer_configs[0].connection_opts.disable_microblock_push = true; + peer_configs[1].connection_opts.disable_microblock_push = true; + peer_configs[2].connection_opts.disable_microblock_push = true; + // generous timeouts + peer_configs[0].connection_opts.connect_timeout = 180; + peer_configs[1].connection_opts.connect_timeout = 180; + peer_configs[2].connection_opts.connect_timeout = 180; peer_configs[0].connection_opts.timeout = 180; peer_configs[1].connection_opts.timeout = 180; peer_configs[2].connection_opts.timeout = 180; @@ -2009,8 +2204,6 @@ mod test { peer_configs[0].add_neighbor(&peer_1); peer_configs[1].add_neighbor(&peer_0); - - // peer_configs[1].add_neighbor(&peer_2); peer_configs[2].add_neighbor(&peer_1); }, |num_blocks, ref mut peers| { @@ -2075,7 +2268,37 @@ mod test { }, |ref mut peers| { // make sure peer 2's inv has an entry for peer 1, even - // though it's not doing an inv sync + // though it's not doing an inv sync. This is required for the downloader to + // work, and for (Micro)BlocksAvailable messages to be accepted + let peer_1_nk = peers[1].to_neighbor().addr; + let peer_2_nk = peers[2].to_neighbor().addr; + let bc = peers[1].config.burnchain.clone(); + match peers[2].network.inv_state { + Some(ref mut inv_state) => { + if inv_state.get_stats(&peer_1_nk).is_none() { + test_debug!("initialize inv statistics for peer 1 in peer 2"); + inv_state.add_peer(peer_1_nk.clone(), true); + if let Some(ref mut stats) = inv_state.get_stats_mut(&peer_1_nk) { + stats.scans = 1; + stats.inv.merge_pox_inv(&bc, 0, 6, vec![0xff], false); + stats.inv.merge_blocks_inv( + 0, + 30, + vec![0, 0, 0, 0, 0], + vec![0, 0, 0, 0, 0], + false, + ); + } else { + panic!("Unable to instantiate inv stats for {:?}", &peer_1_nk); + } + } else { + test_debug!("peer 2 has inv state for peer 1"); + } + } + None => { + test_debug!("No inv state for peer 1"); + } + } let tip = SortitionDB::get_canonical_burn_chain_tip( &peers[0].sortdb.as_ref().unwrap().conn(), @@ -2458,7 +2681,10 @@ mod test { } } - fn test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks(outbound_test: bool) { + fn test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks( + outbound_test: bool, + disable_push: bool, + ) { with_timeout(600, move || { let original_blocks_and_microblocks = RefCell::new(vec![]); let blocks_and_microblocks = RefCell::new(vec![]); @@ -2488,6 +2714,14 @@ mod test { peer_configs[0].connection_opts.disable_natpunch = true; peer_configs[1].connection_opts.disable_natpunch = true; + // force usage of blocksavailable/microblocksavailable? + if disable_push { + peer_configs[0].connection_opts.disable_block_push = true; + peer_configs[0].connection_opts.disable_microblock_push = true; + peer_configs[1].connection_opts.disable_block_push = true; + peer_configs[1].connection_opts.disable_microblock_push = true; + } + let peer_0 = peer_configs[0].to_neighbor(); let peer_1 = peer_configs[1].to_neighbor(); @@ -2562,15 +2796,24 @@ mod test { block_data }, |ref mut peers| { - // make sure peer 2's inv has an entry for peer 1, even - // though it's not doing an inv sync + if !disable_push { + for peer in peers.iter_mut() { + // force peers to keep trying to process buffered data + peer.network.burnchain_tip.burn_header_hash = + BurnchainHeaderHash([0u8; 32]); + } + } + + // make sure peer 1's inv has an entry for peer 0, even + // though it's not doing an inv sync. This is required for the downloader to + // work let peer_0_nk = peers[0].to_neighbor().addr; let peer_1_nk = peers[1].to_neighbor().addr; match peers[1].network.inv_state { Some(ref mut inv_state) => { if inv_state.get_stats(&peer_0_nk).is_none() { test_debug!("initialize inv statistics for peer 0 in peer 1"); - inv_state.add_peer(peer_0_nk, true); + inv_state.add_peer(peer_0_nk.clone(), true); } else { test_debug!("peer 1 has inv state for peer 0"); } @@ -2689,15 +2932,33 @@ mod test { #[test] #[ignore] fn test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks_outbound() { - // simulates node 0 pushing blocks to node 1, but node 0 is publicly routable - test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks(true) + // simulates node 0 pushing blocks to node 1, but node 0 is publicly routable. + // nodes rely on blocksavailable/microblocksavailable to discover blocks + test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks(true, true) } #[test] #[ignore] fn test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks_inbound() { // simulates node 0 pushing blocks to node 1, where node 0 is behind a NAT - test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks(false) + // nodes rely on blocksavailable/microblocksavailable to discover blocks + test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks(false, true) + } + + #[test] + #[ignore] + fn test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks_outbound_direct() { + // simulates node 0 pushing blocks to node 1, but node 0 is publicly routable. + // nodes may push blocks and microblocks directly to each other + test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks(true, false) + } + + #[test] + #[ignore] + fn test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks_inbound_direct() { + // simulates node 0 pushing blocks to node 1, where node 0 is behind a NAT + // nodes may push blocks and microblocks directly to each other + test_get_blocks_and_microblocks_2_peers_push_blocks_and_microblocks(false, false) } #[test] @@ -3697,10 +3958,6 @@ mod test { peer_configs[0].connection_opts.antientropy_retry = 1; peer_configs[1].connection_opts.antientropy_retry = 1; - // full rescan by default - peer_configs[0].connection_opts.full_inv_sync_interval = 1; - peer_configs[1].connection_opts.full_inv_sync_interval = 1; - // make peer 0 go slowly peer_configs[0].connection_opts.max_block_push = 2; peer_configs[0].connection_opts.max_microblock_push = 2; diff --git a/src/net/rpc.rs b/src/net/rpc.rs index c324206cdd..5003a9ad88 100644 --- a/src/net/rpc.rs +++ b/src/net/rpc.rs @@ -165,9 +165,10 @@ impl fmt::Display for ConversationHttp { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { write!( f, - "http:id={},request={:?}", + "http:id={},request={:?},peer={:?}", self.conn_id, - self.pending_request.is_some() + self.pending_request.is_some(), + &self.peer_addr ) } } @@ -176,9 +177,10 @@ impl fmt::Debug for ConversationHttp { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { write!( f, - "http:id={},request={:?}", + "http:id={},request={:?},peer={:?}", self.conn_id, - self.pending_request.is_some() + self.pending_request.is_some(), + &self.peer_addr ) } } @@ -2087,14 +2089,23 @@ impl ConversationHttp { chainstate: &StacksChainState, query: MemPoolSyncData, max_txs: u64, - ) -> Result, net_error> { + page_id: Option, + ) -> Result { let response_metadata = HttpResponseMetadata::from(req); let response = HttpResponseType::MemPoolTxStream(response_metadata); let height = chainstate .get_stacks_chain_tip(sortdb)? .map(|blk| blk.height) .unwrap_or(0); - let stream = Some(StreamCursor::new_tx_stream(query, max_txs, height)); + + debug!( + "Begin mempool query"; + "page_id" => %page_id.map(|txid| format!("{}", &txid)).unwrap_or("(none".to_string()), + "block_height" => height, + "max_txs" => max_txs + ); + + let stream = StreamCursor::new_tx_stream(query, max_txs, height, page_id); response.send(http, fd).and_then(|_| Ok(stream)) } @@ -2545,8 +2556,8 @@ impl ConversationHttp { } None } - HttpRequestType::MemPoolQuery(ref _md, ref query) => { - ConversationHttp::handle_mempool_query( + HttpRequestType::MemPoolQuery(ref _md, ref query, ref page_id_opt) => { + Some(ConversationHttp::handle_mempool_query( &mut self.connection.protocol, &mut reply, &req, @@ -2554,7 +2565,8 @@ impl ConversationHttp { chainstate, query.clone(), network.connection_opts.mempool_max_tx_query, - )? + page_id_opt.clone(), + )?) } HttpRequestType::OptionsPreflight(ref _md, ref _path) => { let response_metadata = HttpResponseMetadata::from(&req); @@ -2631,9 +2643,6 @@ impl ConversationHttp { } /// Make progress on outbound requests. - /// Return true if the connection should be kept alive after all messages are drained. - /// If we process a request with "Connection: close", then return false (indicating that the - /// connection should be severed once the conversation is drained) fn send_outbound_responses( &mut self, mempool: &MemPoolDB, @@ -2650,6 +2659,8 @@ impl ConversationHttp { &self, self.reply_streams.len() ); + let _self_str = format!("{}", &self); + match self.reply_streams.front_mut() { Some((ref mut reply, ref mut stream_opt, ref keep_alive)) => { do_keep_alive = *keep_alive; @@ -2662,30 +2673,41 @@ impl ConversationHttp { match stream.stream_to(mempool, chainstate, &mut encoder, STREAM_CHUNK_SIZE) { Ok(nw) => { - test_debug!("streamed {} bytes", nw); + test_debug!("{}: Streamed {} bytes", &_self_str, nw); if nw == 0 { // EOF -- finish chunk and stop sending. if !encoder.corked() { encoder.flush().map_err(|e| { - test_debug!("Write error on encoder flush: {:?}", &e); + test_debug!( + "{}: Write error on encoder flush: {:?}", + &_self_str, + &e + ); net_error::WriteError(e) })?; encoder.cork(); - test_debug!("stream indicates EOF"); + test_debug!("{}: Stream indicates EOF", &_self_str); } // try moving some data to the connection only once we're done // streaming match reply.try_flush() { Ok(res) => { - test_debug!("Streamed reply is drained"); + test_debug!( + "{}: Streamed reply is drained?: {}", + &_self_str, + res + ); drained_handle = res; } Err(e) => { // dead - warn!("Broken HTTP connection: {:?}", &e); + warn!( + "{}: Broken HTTP connection: {:?}", + &_self_str, &e + ); broken = true; } } @@ -2697,7 +2719,10 @@ impl ConversationHttp { // For example, if we're streaming an unconfirmed block or // microblock, the data can get moved to the chunk store out from // under the stream. - warn!("Failed to send to HTTP connection: {:?}", &e); + warn!( + "{}: Failed to send to HTTP connection: {:?}", + &_self_str, &e + ); broken = true; } } @@ -2709,12 +2734,12 @@ impl ConversationHttp { // try moving some data to the connection match reply.try_flush() { Ok(res) => { - test_debug!("Reply is drained"); + test_debug!("{}: Reply is drained", &_self_str); drained_handle = res; } Err(e) => { // dead - warn!("Broken HTTP connection: {:?}", &e); + warn!("{}: Broken HTTP connection: {:?}", &_self_str, &e); broken = true; } } @@ -2741,7 +2766,6 @@ impl ConversationHttp { self.keep_alive = false; } } - Ok(()) } @@ -2894,7 +2918,7 @@ impl ConversationHttp { self.handle_request(req, network, sortdb, chainstate, mempool, handler_args) })?; - debug!("Processed HTTPRequest"; "path" => %path, "processing_time_ms" => start_time.elapsed().as_millis()); + debug!("Processed HTTPRequest"; "path" => %path, "processing_time_ms" => start_time.elapsed().as_millis(), "conn_id" => self.conn_id, "peer_addr" => &self.peer_addr); if let Some(msg) = msg_opt { ret.push(msg); @@ -3212,10 +3236,15 @@ impl ConversationHttp { } /// Make a new request for mempool contents - pub fn new_mempool_query(&self, query: MemPoolSyncData) -> HttpRequestType { + pub fn new_mempool_query( + &self, + query: MemPoolSyncData, + page_id_opt: Option, + ) -> HttpRequestType { HttpRequestType::MemPoolQuery( HttpRequestMetadata::from_host(self.peer_host.clone()), query, + page_id_opt, ) } } @@ -5691,13 +5720,16 @@ mod test { ref mut convo_client, ref mut peer_server, ref mut convo_server| { - convo_client.new_mempool_query(MemPoolSyncData::TxTags([0u8; 32], vec![])) + convo_client.new_mempool_query( + MemPoolSyncData::TxTags([0u8; 32], vec![]), + Some(Txid([0u8; 32])), + ) }, |ref http_request, ref http_response, ref mut peer_client, ref mut peer_server| { let req_md = http_request.metadata().clone(); println!("{:?}", http_response); match http_response { - HttpResponseType::MemPoolTxs(_, txs) => { + HttpResponseType::MemPoolTxs(_, _, txs) => { // got everything assert_eq!(txs.len(), 10); true @@ -5723,17 +5755,20 @@ mod test { ref mut peer_server, ref mut convo_server| { // empty bloom filter - convo_client.new_mempool_query(MemPoolSyncData::BloomFilter(BloomFilter::new( - BLOOM_COUNTER_ERROR_RATE, - MAX_BLOOM_COUNTER_TXS, - BloomNodeHasher::new(&[0u8; 32]), - ))) + convo_client.new_mempool_query( + MemPoolSyncData::BloomFilter(BloomFilter::new( + BLOOM_COUNTER_ERROR_RATE, + MAX_BLOOM_COUNTER_TXS, + BloomNodeHasher::new(&[0u8; 32]), + )), + Some(Txid([0u8; 32])), + ) }, |ref http_request, ref http_response, ref mut peer_client, ref mut peer_server| { let req_md = http_request.metadata().clone(); println!("{:?}", http_response); match http_response { - HttpResponseType::MemPoolTxs(_, txs) => { + HttpResponseType::MemPoolTxs(_, _, txs) => { // got everything assert_eq!(txs.len(), 10); true diff --git a/src/net/server.rs b/src/net/server.rs index bd05dd4969..bdf62bab08 100644 --- a/src/net/server.rs +++ b/src/net/server.rs @@ -549,6 +549,7 @@ impl HttpPeer { if self.connecting.contains_key(event_id) { let (socket, data_url, initial_request_opt, _) = self.connecting.remove(event_id).unwrap(); + debug!("HTTP event {} connected ({:?})", event_id, &data_url); if let Err(_e) = self.register_http( diff --git a/src/util/db.rs b/src/util/db.rs index 740134b8f3..2f07299572 100644 --- a/src/util/db.rs +++ b/src/util/db.rs @@ -264,6 +264,51 @@ macro_rules! impl_byte_array_from_column { }; } +/// Load the path of the database from the connection +#[cfg(test)] +fn get_db_path(conn: &Connection) -> Result { + let sql = "PRAGMA database_list"; + let path: Result, sqlite_error> = + conn.query_row_and_then(sql, NO_PARAMS, |row| row.get(2)); + match path { + Ok(Some(path)) => Ok(path), + Ok(None) => Ok("".to_string()), + Err(e) => Err(Error::SqliteError(e)), + } +} + +/// Generate debug output to be fed into an external script to examine query plans. +/// TODO: it uses mocked arguments, which it assumes are strings. This does not always result in a +/// valid query. +#[cfg(test)] +fn log_sql_eqp(conn: &Connection, sql_query: &str) { + if std::env::var("BLOCKSTACK_DB_TRACE") != Ok("1".to_string()) { + return; + } + + let mut parts = sql_query.clone().split(" "); + let mut full_sql = if let Some(part) = parts.next() { + part.to_string() + } else { + sql_query.to_string() + }; + + while let Some(part) = parts.next() { + if part.starts_with("?") { + full_sql = format!("{} \"mock_arg\"", full_sql.trim()); + } else { + full_sql = format!("{} {}", full_sql.trim(), part.trim()); + } + } + + let path = get_db_path(conn).unwrap_or("ERROR!".to_string()); + let eqp_sql = format!("\"{}\" EXPLAIN QUERY PLAN {}", &path, full_sql.trim()); + debug!("{}", &eqp_sql); +} + +#[cfg(not(test))] +fn log_sql_eqp(_conn: &Connection, _sql_query: &str) {} + /// boilerplate code for querying rows pub fn query_rows(conn: &Connection, sql_query: &str, sql_args: P) -> Result, Error> where @@ -271,6 +316,7 @@ where P::Item: ToSql, T: FromRow, { + log_sql_eqp(conn, sql_query); let mut stmt = conn.prepare(sql_query)?; let result = stmt.query_and_then(sql_args, |row| T::from_row(row))?; @@ -285,6 +331,7 @@ where P::Item: ToSql, T: FromRow, { + log_sql_eqp(conn, sql_query); let query_result = conn.query_row_and_then(sql_query, sql_args, |row| T::from_row(row)); match query_result { Ok(x) => Ok(Some(x)), @@ -305,6 +352,7 @@ where P::Item: ToSql, T: FromRow, { + log_sql_eqp(conn, sql_query); let mut stmt = conn.prepare(sql_query)?; let mut result = stmt.query_and_then(sql_args, |row| T::from_row(row))?; let mut return_value = None; @@ -331,6 +379,7 @@ where T: FromRow, F: FnOnce() -> String, { + log_sql_eqp(conn, sql_query); let mut stmt = conn.prepare(sql_query)?; let mut result = stmt.query_and_then(sql_args, |row| T::from_row(row))?; let mut return_value = None; @@ -355,8 +404,8 @@ where P::Item: ToSql, T: FromColumn, { + log_sql_eqp(conn, sql_query); let mut stmt = conn.prepare(sql_query)?; - let mut rows = stmt.query(sql_args)?; // gather @@ -375,10 +424,9 @@ where P: IntoIterator, P::Item: ToSql, { + log_sql_eqp(conn, sql_query); let mut stmt = conn.prepare(sql_query)?; - let mut rows = stmt.query(sql_args)?; - let mut row_data = vec![]; while let Some(row) = rows.next().map_err(|e| Error::SqliteError(e))? { if row_data.len() > 0 { diff --git a/src/util/retry.rs b/src/util/retry.rs index 915de7a836..677e5b902d 100644 --- a/src/util/retry.rs +++ b/src/util/retry.rs @@ -55,8 +55,8 @@ impl<'a, R: Read> RetryReader<'a, R> { fn read_and_buffer(&mut self, buf: &mut [u8]) -> io::Result { let nr = self.fd.read(buf)?; - self.buf.extend_from_slice(buf); - self.i += buf.len(); + self.buf.extend_from_slice(&buf[0..nr]); + self.i += nr; Ok(nr) } } diff --git a/testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs b/testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs index 9bc21fbaa0..3a5a64f8fa 100644 --- a/testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs +++ b/testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs @@ -67,7 +67,7 @@ const DUST_UTXO_LIMIT: u64 = 5500; pub struct BitcoinRegtestController { config: Config, - indexer_config: BitcoinIndexerConfig, + indexer: BitcoinIndexer, db: Option, burnchain_db: Option, chain_tip: Option, @@ -242,10 +242,17 @@ impl BitcoinRegtestController { } }; + let (_, network_type) = config.burnchain.get_bitcoin_network(); + let indexer_runtime = BitcoinIndexerRuntime::new(network_type); + let burnchain_indexer = BitcoinIndexer { + config: indexer_config.clone(), + runtime: indexer_runtime, + }; + Self { use_coordinator: coordinator_channel, config, - indexer_config, + indexer: burnchain_indexer, db: None, burnchain_db: None, chain_tip: None, @@ -279,10 +286,17 @@ impl BitcoinRegtestController { } }; + let (_, network_type) = config.burnchain.get_bitcoin_network(); + let indexer_runtime = BitcoinIndexerRuntime::new(network_type); + let burnchain_indexer = BitcoinIndexer { + config: indexer_config.clone(), + runtime: indexer_runtime, + }; + Self { use_coordinator: None, config, - indexer_config, + indexer: burnchain_indexer, db: None, burnchain_db: None, chain_tip: None, @@ -321,21 +335,10 @@ impl BitcoinRegtestController { } } - fn setup_indexer_runtime(&self) -> (Burnchain, BitcoinIndexer) { - let (_, network_type) = self.config.burnchain.get_bitcoin_network(); - let indexer_runtime = BitcoinIndexerRuntime::new(network_type); - let burnchain_indexer = BitcoinIndexer { - config: self.indexer_config.clone(), - runtime: indexer_runtime, - }; - (self.get_burnchain(), burnchain_indexer) - } - fn receive_blocks_helium(&mut self) -> BurnchainTip { - let (mut burnchain, mut burnchain_indexer) = self.setup_indexer_runtime(); - + let mut burnchain = self.get_burnchain(); let (block_snapshot, state_transition) = loop { - match burnchain.sync_with_indexer_deprecated(&mut burnchain_indexer) { + match burnchain.sync_with_indexer_deprecated(&mut self.indexer) { Ok(x) => { break x; } @@ -405,13 +408,13 @@ impl BitcoinRegtestController { } }; - let (mut burnchain, mut burnchain_indexer) = self.setup_indexer_runtime(); + let mut burnchain = self.get_burnchain(); let (block_snapshot, burnchain_height, state_transition) = loop { if !self.should_keep_running() { return Err(BurnchainControllerError::CoordinatorClosed); } match burnchain.sync_with_indexer( - &mut burnchain_indexer, + &mut self.indexer, coordinator_comms.clone(), target_block_height_opt, Some(burnchain.pox_constants.reward_cycle_length as u64), @@ -439,7 +442,8 @@ impl BitcoinRegtestController { .expect("Sortition DB error.") .expect("BUG: no data for the canonical chain tip"); - let burnchain_height = burnchain_indexer + let burnchain_height = self + .indexer .get_highest_header_height() .map_err(BurnchainControllerError::IndexerError)?; break (snapshot, burnchain_height, state_transition); @@ -1470,20 +1474,35 @@ impl BurnchainController for BitcoinRegtestController { } } + fn get_headers_height(&self) -> u64 { + let (_, network_id) = self.config.burnchain.get_bitcoin_network(); + let spv_client = SpvClient::new( + &self.config.get_spv_headers_file_path(), + 0, + None, + network_id, + false, + false, + ) + .expect("Unable to open burnchain headers DB"); + spv_client + .get_headers_height() + .expect("Unable to query number of burnchain headers") + } + fn connect_dbs(&mut self) -> Result<(), BurnchainControllerError> { - let (burnchain, burnchain_indexer) = self.setup_indexer_runtime(); + let burnchain = self.get_burnchain(); burnchain.connect_db( - &burnchain_indexer, + &self.indexer, true, - burnchain_indexer.get_first_block_header_hash()?, - burnchain_indexer.get_first_block_header_timestamp()?, + self.indexer.get_first_block_header_hash()?, + self.indexer.get_first_block_header_timestamp()?, )?; Ok(()) } fn get_stacks_epochs(&self) -> Vec { - let (_, indexer) = self.setup_indexer_runtime(); - indexer.get_stacks_epochs() + self.indexer.get_stacks_epochs() } fn start( diff --git a/testnet/stacks-node/src/burnchains/mocknet_controller.rs b/testnet/stacks-node/src/burnchains/mocknet_controller.rs index a5be3e550c..14b9da1c1f 100644 --- a/testnet/stacks-node/src/burnchains/mocknet_controller.rs +++ b/testnet/stacks-node/src/burnchains/mocknet_controller.rs @@ -86,6 +86,15 @@ impl BurnchainController for MocknetController { } } + fn get_headers_height(&self) -> u64 { + match &self.chain_tip { + Some(chain_tip) => chain_tip.block_snapshot.block_height, + None => { + unreachable!(); + } + } + } + fn get_stacks_epochs(&self) -> Vec { match &self.config.burnchain.epochs { Some(epochs) => epochs.clone(), diff --git a/testnet/stacks-node/src/burnchains/mod.rs b/testnet/stacks-node/src/burnchains/mod.rs index dade40ef88..50682fd0e2 100644 --- a/testnet/stacks-node/src/burnchains/mod.rs +++ b/testnet/stacks-node/src/burnchains/mod.rs @@ -51,6 +51,7 @@ pub trait BurnchainController { fn sortdb_ref(&self) -> &SortitionDB; fn sortdb_mut(&mut self) -> &mut SortitionDB; fn get_chain_tip(&self) -> BurnchainTip; + fn get_headers_height(&self) -> u64; /// Invoke connect() on underlying burnchain and sortition databases, to perform any migration /// or instantiation before other callers may use open() fn connect_dbs(&mut self) -> Result<(), Error>; diff --git a/testnet/stacks-node/src/config.rs b/testnet/stacks-node/src/config.rs index 0d9e7eaf66..d80f7212fe 100644 --- a/testnet/stacks-node/src/config.rs +++ b/testnet/stacks-node/src/config.rs @@ -507,6 +507,9 @@ impl Config { subsequent_attempt_time_ms: miner .subsequent_attempt_time_ms .unwrap_or(miner_default_config.subsequent_attempt_time_ms), + microblock_attempt_time_ms: miner + .microblock_attempt_time_ms + .unwrap_or(miner_default_config.microblock_attempt_time_ms), probability_pick_no_estimate_tx: miner .probability_pick_no_estimate_tx .unwrap_or(miner_default_config.probability_pick_no_estimate_tx), @@ -715,9 +718,6 @@ impl Config { inv_sync_interval: opts .inv_sync_interval .unwrap_or_else(|| HELIUM_DEFAULT_CONNECTION_OPTIONS.inv_sync_interval), - full_inv_sync_interval: opts.full_inv_sync_interval.unwrap_or_else(|| { - HELIUM_DEFAULT_CONNECTION_OPTIONS.full_inv_sync_interval - }), inv_reward_cycles: opts.inv_reward_cycles.unwrap_or_else(|| { if burnchain.mode == "mainnet" { HELIUM_DEFAULT_CONNECTION_OPTIONS.inv_reward_cycles @@ -861,9 +861,15 @@ impl Config { self.events_observers.len() > 0 } - pub fn make_block_builder_settings(&self, attempt: u64) -> BlockBuilderSettings { + pub fn make_block_builder_settings( + &self, + attempt: u64, + microblocks: bool, + ) -> BlockBuilderSettings { BlockBuilderSettings { - max_miner_time_ms: if attempt <= 1 { + max_miner_time_ms: if microblocks { + self.miner.microblock_attempt_time_ms + } else if attempt <= 1 { // first attempt to mine a block -- do so right away self.miner.first_attempt_time_ms } else { @@ -872,7 +878,9 @@ impl Config { }, mempool_settings: MemPoolWalkSettings { min_tx_fee: self.miner.min_tx_fee, - max_walk_time_ms: if attempt <= 1 { + max_walk_time_ms: if microblocks { + self.miner.microblock_attempt_time_ms + } else if attempt <= 1 { // first attempt to mine a block -- do so right away self.miner.first_attempt_time_ms } else { @@ -1398,6 +1406,7 @@ pub struct MinerConfig { pub min_tx_fee: u64, pub first_attempt_time_ms: u64, pub subsequent_attempt_time_ms: u64, + pub microblock_attempt_time_ms: u64, pub probability_pick_no_estimate_tx: u8, } @@ -1405,8 +1414,9 @@ impl MinerConfig { pub fn default() -> MinerConfig { MinerConfig { min_tx_fee: 1, - first_attempt_time_ms: 1_000, - subsequent_attempt_time_ms: 60_000, + first_attempt_time_ms: 5_000, + subsequent_attempt_time_ms: 180_000, + microblock_attempt_time_ms: 30_000, probability_pick_no_estimate_tx: 5, } } @@ -1508,6 +1518,7 @@ pub struct MinerConfigFile { pub min_tx_fee: Option, pub first_attempt_time_ms: Option, pub subsequent_attempt_time_ms: Option, + pub microblock_attempt_time_ms: Option, pub probability_pick_no_estimate_tx: Option, } diff --git a/testnet/stacks-node/src/main.rs b/testnet/stacks-node/src/main.rs index 3b110221fb..3ce02b6ba0 100644 --- a/testnet/stacks-node/src/main.rs +++ b/testnet/stacks-node/src/main.rs @@ -38,7 +38,6 @@ pub use self::burnchains::{ pub use self::config::{Config, ConfigFile}; pub use self::event_dispatcher::EventDispatcher; pub use self::keychain::Keychain; -pub use self::neon_node::{InitializedNeonNode, NeonGenesisNode}; pub use self::node::{ChainTip, Node}; pub use self::run_loop::{helium, neon}; pub use self::tenure::Tenure; diff --git a/testnet/stacks-node/src/neon_node.rs b/testnet/stacks-node/src/neon_node.rs index 129d7d7129..6fcd39933c 100644 --- a/testnet/stacks-node/src/neon_node.rs +++ b/testnet/stacks-node/src/neon_node.rs @@ -5,10 +5,7 @@ use std::convert::{TryFrom, TryInto}; use std::default::Default; use std::net::SocketAddr; use std::sync::mpsc::{sync_channel, Receiver, SyncSender, TrySendError}; -use std::sync::{ - atomic::{AtomicBool, Ordering}, - Arc, Mutex, -}; +use std::sync::{atomic::Ordering, Arc, Mutex}; use std::{thread, thread::JoinHandle}; use stacks::burnchains::{Burnchain, BurnchainParameters, Txid}; @@ -22,9 +19,7 @@ use stacks::chainstate::burn::ConsensusHash; use stacks::chainstate::coordinator::comm::CoordinatorChannels; use stacks::chainstate::coordinator::{get_next_recipients, OnChainRewardSetProvider}; use stacks::chainstate::stacks::db::unconfirmed::UnconfirmedTxMap; -use stacks::chainstate::stacks::db::{ - ChainStateBootData, ClarityTx, StacksChainState, MINER_REWARD_MATURITY, -}; +use stacks::chainstate::stacks::db::{StacksChainState, MINER_REWARD_MATURITY}; use stacks::chainstate::stacks::Error as ChainstateError; use stacks::chainstate::stacks::StacksPublicKey; use stacks::chainstate::stacks::{ @@ -63,8 +58,9 @@ use stacks::vm::costs::ExecutionCost; use stacks::{burnchains::BurnchainSigner, chainstate::stacks::db::StacksHeaderInfo}; use crate::burnchains::bitcoin_regtest_controller::BitcoinRegtestController; +use crate::run_loop::neon::Counters; +use crate::run_loop::neon::RunLoop; use crate::run_loop::RegisteredKey; -use crate::syncctl::PoxSyncWatchdogComms; use crate::ChainTip; use super::{BurnchainController, BurnchainTip, Config, EventDispatcher, Keychain}; @@ -96,15 +92,15 @@ enum RelayerDirective { ProcessTenure(ConsensusHash, BurnchainHeaderHash, BlockHeaderHash), RunTenure(RegisteredKey, BlockSnapshot, u128), // (vrf key, chain tip, time of issuance in ms) RegisterKey(BlockSnapshot), - RunMicroblockTenure(u128), // time of issuance in ms + RunMicroblockTenure(BlockSnapshot, u128), // time of issuance in ms Exit, } -pub struct InitializedNeonNode { +pub struct StacksNode { config: Config, relay_channel: SyncSender, + last_sortition: Arc>>, burnchain_signer: BurnchainSigner, - last_burn_block: Option, is_miner: bool, pub atlas_config: AtlasConfig, leader_key_registration_state: LeaderKeyRegistrationState, @@ -112,34 +108,29 @@ pub struct InitializedNeonNode { pub relayer_thread_handle: JoinHandle<()>, } -pub struct NeonGenesisNode { - pub config: Config, - keychain: Keychain, - event_dispatcher: EventDispatcher, - burnchain: Burnchain, -} - -#[cfg(test)] -type BlocksProcessedCounter = std::sync::Arc; - -#[cfg(not(test))] -type BlocksProcessedCounter = (); - #[cfg(test)] -fn bump_processed_counter(blocks_processed: &BlocksProcessedCounter) { - blocks_processed.fetch_add(1, std::sync::atomic::Ordering::SeqCst); -} - -#[cfg(not(test))] -fn bump_processed_counter(_blocks_processed: &BlocksProcessedCounter) {} - -#[cfg(test)] -fn set_processed_counter(blocks_processed: &BlocksProcessedCounter, value: u64) { - blocks_processed.store(value, std::sync::atomic::Ordering::SeqCst); +fn fault_injection_long_tenure() { + // simulated slow block + match std::env::var("STX_TEST_SLOW_TENURE") { + Ok(tenure_str) => match tenure_str.parse::() { + Ok(tenure_time) => { + info!( + "Fault injection: sleeping for {} milliseconds to simulate a long tenure", + tenure_time + ); + stacks::util::sleep_ms(tenure_time); + } + Err(_) => { + error!("Parse error for STX_TEST_SLOW_TENURE"); + panic!(); + } + }, + _ => {} + } } #[cfg(not(test))] -fn set_processed_counter(_blocks_processed: &BlocksProcessedCounter, _value: u64) {} +fn fault_injection_long_tenure() {} enum Error { HeaderNotFoundForChainTip, @@ -445,7 +436,7 @@ fn try_mine_microblock( last_mined: 0, quantity: 0, cost_so_far: cost_so_far, - settings: config.make_block_builder_settings(2), + settings: config.make_block_builder_settings(0, true), }); } Ok(None) => { @@ -517,7 +508,7 @@ fn run_microblock_tenure( mem_pool: &mut MemPoolDB, relayer: &mut Relayer, miner_tip: (ConsensusHash, BlockHeaderHash, Secp256k1PrivateKey), - microblocks_processed: BlocksProcessedCounter, + counters: &Counters, event_dispatcher: &EventDispatcher, ) { // TODO: this is sensitive to poll latency -- can we call this on a fixed @@ -563,7 +554,7 @@ fn run_microblock_tenure( "Mined one microblock: {} seq {} (total processed: {})", µblock_hash, next_microblock.header.sequence, num_mblocks ); - set_processed_counter(µblocks_processed, num_mblocks); + counters.set_microblocks_processed(num_mblocks); let parent_index_block_hash = StacksBlockHeader::make_index_block_hash(parent_consensus_hash, parent_block_hash); @@ -625,19 +616,21 @@ fn recv_unconfirmed_txs( } fn spawn_peer( - is_mainnet: bool, + runloop: &RunLoop, mut this: PeerNetwork, p2p_sock: &SocketAddr, rpc_sock: &SocketAddr, - config: Config, poll_timeout: u64, relay_channel: SyncSender, - mut sync_comms: PoxSyncWatchdogComms, attachments_rx: Receiver>, unconfirmed_txs: Arc>, - event_observer: EventDispatcher, - should_keep_running: Arc, ) -> Result, NetError> { + let config = runloop.config().clone(); + let mut sync_comms = runloop.get_pox_sync_comms(); + let event_dispatcher = runloop.get_event_dispatcher(); + let should_keep_running = runloop.get_termination_switch(); + + let is_mainnet = config.is_mainnet(); let burn_db_path = config.get_burn_db_file_path(); let stacks_chainstate_path = config.get_chainstate_path_str(); let exit_at_block_height = config.burnchain.process_exit_at_block_height; @@ -659,12 +652,14 @@ fn spawn_peer( let server_thread = thread::Builder::new() .name("p2p".to_string()) .spawn(move || { + // create estimators, metric instances for RPC handler let cost_estimator = config .make_cost_estimator() .unwrap_or_else(|| Box::new(UnitEstimator)); let metric = config .make_cost_metric() .unwrap_or_else(|| Box::new(UnitMetric)); + let fee_estimator = config.make_fee_estimator(); let mut mem_pool = MemPoolDB::open( is_mainnet, @@ -675,20 +670,18 @@ fn spawn_peer( ) .expect("Database failure opening mempool"); - // create estimators, metric instances for RPC handler let cost_estimator = config .make_cost_estimator() .unwrap_or_else(|| Box::new(UnitEstimator)); let metric = config .make_cost_metric() .unwrap_or_else(|| Box::new(UnitMetric)); - let fee_estimator = config.make_fee_estimator(); let handler_args = RPCHandlerArgs { exit_at_block_height: exit_at_block_height.as_ref(), genesis_chainstate_hash: Sha256Sum::from_hex(stx_genesis::GENESIS_CHAINSTATE_HASH) .unwrap(), - event_observer: Some(&event_observer), + event_observer: Some(&event_dispatcher), cost_estimator: Some(cost_estimator.as_ref()), cost_metric: Some(metric.as_ref()), fee_estimator: fee_estimator.as_ref().map(|x| x.as_ref()), @@ -767,6 +760,7 @@ fn spawn_peer( if mblock_deadline < get_epoch_time_ms() { debug!("P2P: schedule microblock tenure"); results_with_data.push_back(RelayerDirective::RunMicroblockTenure( + this.burnchain_tip.clone(), get_epoch_time_ms(), )); mblock_deadline = @@ -791,7 +785,9 @@ fn spawn_peer( ); match e { TrySendError::Full(directive) => { - if let RelayerDirective::RunMicroblockTenure(_) = directive { + if let RelayerDirective::RunMicroblockTenure(..) = directive { + // can drop this + } else if let RelayerDirective::RunTenure(..) = directive { // can drop this } else { // don't lose this data -- just try it again @@ -826,23 +822,52 @@ fn spawn_peer( Ok(server_thread) } +fn get_last_sortition(last_sortition: &Arc>>) -> Option { + match last_sortition.lock() { + Ok(sort_opt) => sort_opt.clone(), + Err(_) => { + error!("Sortition mutex poisoned!"); + panic!(); + } + } +} + +fn set_last_sortition( + last_sortition: &mut Arc>>, + block_snapshot: BlockSnapshot, +) { + match last_sortition.lock() { + Ok(mut sortition_opt) => { + sortition_opt.replace(block_snapshot); + } + Err(_) => { + error!("Sortition mutex poisoned!"); + panic!(); + } + }; +} + fn spawn_miner_relayer( - is_mainnet: bool, - chain_id: u32, + runloop: &RunLoop, mut relayer: Relayer, local_peer: LocalPeer, - config: Config, mut keychain: Keychain, - burn_db_path: String, - stacks_chainstate_path: String, relay_channel: Receiver, - event_dispatcher: EventDispatcher, - blocks_processed: BlocksProcessedCounter, - microblocks_processed: BlocksProcessedCounter, - burnchain: Burnchain, + last_sortition: Arc>>, coord_comms: CoordinatorChannels, unconfirmed_txs: Arc>, ) -> Result, NetError> { + let config = runloop.config().clone(); + let event_dispatcher = runloop.get_event_dispatcher(); + let counters = runloop.get_counters(); + let sync_comms = runloop.get_pox_sync_comms(); + let burnchain = runloop.get_burnchain(); + + let is_mainnet = config.is_mainnet(); + let chain_id = config.burnchain.chain_id; + let burn_db_path = config.get_burn_db_file_path(); + let stacks_chainstate_path = config.get_chainstate_path_str(); + // Note: the chainstate coordinator is *the* block processor, it is responsible for writes to // the chainstate -- eventually, no other codepaths should be writing to it. // @@ -886,6 +911,7 @@ fn spawn_miner_relayer( &mut sortdb, &mut chainstate, &mut mem_pool, + sync_comms.get_ibd(), Some(&coord_comms), Some(&event_dispatcher), ) @@ -980,7 +1006,14 @@ fn spawn_miner_relayer( vec![consensus_hash.clone()], ) .expect("Failed to obtain block information for a block we mined."); - if let Err(e) = relayer.advertize_blocks(blocks_available) { + + let block_data = { + let mut bd = HashMap::new(); + bd.insert(consensus_hash.clone(), mined_block.clone()); + bd + }; + + if let Err(e) = relayer.advertize_blocks(blocks_available, block_data) { warn!("Failed to advertise new block: {}", e); } @@ -1028,9 +1061,12 @@ fn spawn_miner_relayer( } } RelayerDirective::RunTenure(registered_key, last_burn_block, issue_timestamp_ms) => { - if last_tenure_issue_time > issue_timestamp_ms { - // coalesce -- stale - continue; + if let Some(cur_sortition) = get_last_sortition(&last_sortition) { + if last_burn_block.sortition_id != cur_sortition.sortition_id { + debug!("Drop stale RunTenure for {}: current sortition is for {}", &last_burn_block.burn_header_hash, &cur_sortition.burn_header_hash); + counters.bump_missed_tenures(); + continue; + } } let burn_header_hash = last_burn_block.burn_header_hash.clone(); @@ -1046,7 +1082,7 @@ fn spawn_miner_relayer( // no burnchain change, so only re-run block tenure every so often in order // to give microblocks a chance to collect if issue_timestamp_ms < last_tenure_issue_time + (config.node.wait_time_for_microblocks as u128) { - debug!("Relayer: will NOT run tenure since issuance is too fresh"); + debug!("Relayer: will NOT run tenure since issuance at {} is too fresh (wait until {} + {} = {})", issue_timestamp_ms / 1000, last_tenure_issue_time / 1000, config.node.wait_time_for_microblocks / 1000, (last_tenure_issue_time + (config.node.wait_time_for_microblocks as u128)) / 1000); continue; } } @@ -1055,6 +1091,7 @@ fn spawn_miner_relayer( burn_tenure_snapshot = burn_chain_sn; if issue_timestamp_ms + (config.node.wait_time_for_microblocks as u128) < get_epoch_time_ms() { // still waiting for microblocks to arrive + debug!("Relayer: will NOT run tenure since still waiting for microblocks to arrive ({} <= {})", (issue_timestamp_ms + (config.node.wait_time_for_microblocks as u128)) / 1000, get_epoch_time_secs()); continue; } debug!("Relayer: burnchain has advanced from {} to {}", &burn_header_hash, &burn_chain_tip); @@ -1067,11 +1104,14 @@ fn spawn_miner_relayer( "last_burn_header_hash" => %burn_header_hash ); + let tenure_begin = get_epoch_time_ms(); + fault_injection_long_tenure(); + let mut last_mined_blocks_vec = last_mined_blocks .remove(&burn_header_hash) .unwrap_or_default(); - let last_mined_block_opt = InitializedNeonNode::relayer_run_tenure( + let last_mined_block_opt = StacksNode::relayer_run_tenure( &config, registered_key, &mut chainstate, @@ -1087,14 +1127,14 @@ fn spawn_miner_relayer( ); if let Some((last_mined_block, microblock_privkey)) = last_mined_block_opt { if last_mined_blocks_vec.len() == 0 { - // (for testing) only bump once per epoch - bump_processed_counter(&blocks_processed); + counters.bump_blocks_processed(); } last_mined_blocks_vec.push((last_mined_block, microblock_privkey)); } last_mined_blocks.insert(burn_header_hash, last_mined_blocks_vec); last_tenure_issue_time = get_epoch_time_ms(); + debug!("Relayer: RunTenure finished at {} (in {}ms)", last_tenure_issue_time, last_tenure_issue_time.saturating_sub(tenure_begin)); } RelayerDirective::RegisterKey(ref last_burn_block) => { rotate_vrf_and_register( @@ -1103,15 +1143,21 @@ fn spawn_miner_relayer( last_burn_block, &mut bitcoin_controller, ); - bump_processed_counter(&blocks_processed); + counters.bump_blocks_processed(); } - RelayerDirective::RunMicroblockTenure(tenure_issue_ms) => { + RelayerDirective::RunMicroblockTenure(burnchain_tip, tenure_issue_ms) => { if last_microblock_tenure_time > tenure_issue_ms { // stale request continue; } + if let Some(cur_sortition) = get_last_sortition(&last_sortition) { + if burnchain_tip.sortition_id != cur_sortition.sortition_id { + debug!("Drop stale RunMicroblockTenure for {}/{}: current sortition is for {} ({})", &burnchain_tip.consensus_hash, &burnchain_tip.winning_stacks_block_hash, &cur_sortition.consensus_hash, &cur_sortition.burn_header_hash); + continue; + } + } - debug!("Relayer: run microblock tenure"); + debug!("Relayer: Run microblock tenure"); // unconfirmed state must be consistent with the chain tip, as must the // microblock mining state. @@ -1124,7 +1170,7 @@ fn spawn_miner_relayer( else { debug!("Relayer: reset microblock miner state"); microblock_miner_state = None; - set_processed_counter(µblocks_processed, 0); + counters.set_microblocks_processed(0); } } @@ -1136,7 +1182,7 @@ fn spawn_miner_relayer( &mut mem_pool, &mut relayer, (ch, bh, mblock_pkey), - microblocks_processed.clone(), + &counters, &event_dispatcher, ); @@ -1146,7 +1192,7 @@ fn spawn_miner_relayer( } else { debug!("Relayer: reset unconfirmed state to 0 microblocks"); - set_processed_counter(µblocks_processed, 0); + counters.set_microblocks_processed(0); microblock_miner_state = None; } } @@ -1165,23 +1211,19 @@ enum LeaderKeyRegistrationState { Active(RegisteredKey), } -/// This node is used for both neon testnet and for mainnet -impl InitializedNeonNode { - fn new( - config: Config, - mut keychain: Keychain, - event_dispatcher: EventDispatcher, +impl StacksNode { + pub fn spawn( + runloop: &RunLoop, last_burn_block: Option, - miner: bool, - blocks_processed: BlocksProcessedCounter, - microblocks_processed: BlocksProcessedCounter, coord_comms: CoordinatorChannels, - sync_comms: PoxSyncWatchdogComms, - burnchain: Burnchain, attachments_rx: Receiver>, - atlas_config: AtlasConfig, - should_keep_running: Arc, - ) -> InitializedNeonNode { + ) -> StacksNode { + let config = runloop.config().clone(); + let miner = runloop.is_miner(); + let burnchain = runloop.get_burnchain(); + let atlas_config = AtlasConfig::default(config.is_mainnet()); + let mut keychain = Keychain::default(config.node.seed.clone()); + // we can call _open_ here rather than _connect_, since connect is first called in // make_genesis_block let sortdb = SortitionDB::open(&config.get_burn_db_file_path(), false) @@ -1305,7 +1347,7 @@ impl InitializedNeonNode { } let atlasdb = - AtlasDB::connect(atlas_config, &config.get_atlas_db_file_path(), true).unwrap(); + AtlasDB::connect(atlas_config.clone(), &config.get_atlas_db_file_path(), true).unwrap(); let local_peer = match PeerDB::get_local_peer(peerdb.conn()) { Ok(local_peer) => local_peer, @@ -1344,6 +1386,9 @@ impl InitializedNeonNode { // setup the relayer channel let (relay_send, relay_recv) = sync_channel(RELAYER_MAX_BUFFER); + let last_burn_block = last_burn_block.map(|x| x.block_snapshot); + let last_sortition = Arc::new(Mutex::new(last_burn_block)); + let burnchain_signer = keychain.get_burnchain_signer(); match monitoring::set_burnchain_signer(burnchain_signer.clone()) { Err(e) => { @@ -1368,52 +1413,38 @@ impl InitializedNeonNode { }; let relayer_thread_handle = spawn_miner_relayer( - config.is_mainnet(), - config.burnchain.chain_id, + runloop, relayer, local_peer, - config.clone(), keychain, - config.get_burn_db_file_path(), - config.get_chainstate_path_str(), relay_recv, - event_dispatcher.clone(), - blocks_processed.clone(), - microblocks_processed.clone(), - burnchain, + last_sortition.clone(), coord_comms, shared_unconfirmed_txs.clone(), ) .expect("Failed to initialize mine/relay thread"); let p2p_thread_handle = spawn_peer( - config.is_mainnet(), + runloop, p2p_net, &p2p_sock, &rpc_sock, - config.clone(), 5000, relay_send.clone(), - sync_comms, attachments_rx, shared_unconfirmed_txs, - event_dispatcher, - should_keep_running, ) .expect("Failed to initialize p2p thread"); info!("Start HTTP server on: {}", &config.node.rpc_bind); info!("Start P2P server on: {}", &config.node.p2p_bind); - let last_burn_block = last_burn_block.map(|x| x.block_snapshot); - let is_miner = miner; - let atlas_config = AtlasConfig::default(config.is_mainnet()); - InitializedNeonNode { + StacksNode { config, relay_channel: relay_send, - last_burn_block, + last_sortition, burnchain_signer, is_miner, atlas_config, @@ -1431,7 +1462,7 @@ impl InitializedNeonNode { return true; } - if let Some(burnchain_tip) = self.last_burn_block.clone() { + if let Some(burnchain_tip) = get_last_sortition(&self.last_sortition) { match self.leader_key_registration_state { LeaderKeyRegistrationState::Active(ref key) => { debug!( @@ -1473,12 +1504,14 @@ impl InitializedNeonNode { return true; } - if let Some(ref snapshot) = &self.last_burn_block { + if let Some(snapshot) = get_last_sortition(&self.last_sortition) { debug!( - "Tenure: Notify sortition! Last snapshot is {}/{} ({})", - &snapshot.consensus_hash, - &snapshot.burn_header_hash, - &snapshot.winning_stacks_block_hash + "Tenure: Notify sortition!"; + "consensus_hash" => %snapshot.consensus_hash, + "burn_block_hash" => %snapshot.burn_header_hash, + "winning_stacks_block_hash" => %snapshot.winning_stacks_block_hash, + "burn_block_height" => &snapshot.block_height, + "sortition_id" => %snapshot.sortition_id ); if snapshot.sortition { return self @@ -1605,7 +1638,7 @@ impl InitializedNeonNode { burn_fee_cap: u64, bitcoin_controller: &mut BitcoinRegtestController, last_mined_blocks: &Vec<&AssembledAnchorBlock>, - event_observer: &EventDispatcher, + event_dispatcher: &EventDispatcher, ) -> Option<(AssembledAnchorBlock, Secp256k1PrivateKey)> { let MiningTenureInformation { mut stacks_parent_header, @@ -1614,7 +1647,10 @@ impl InitializedNeonNode { parent_block_total_burn, parent_winning_vtxindex, coinbase_nonce, - } = if let Some(stacks_tip) = chain_state.get_stacks_chain_tip(burn_db).unwrap() { + } = if let Some(stacks_tip) = chain_state + .get_stacks_chain_tip(burn_db) + .expect("FATAL: could not query chain tip") + { let miner_address = keychain.origin_address(config.is_mainnet()).unwrap(); Self::get_mining_tenure_information( chain_state, @@ -1876,7 +1912,7 @@ impl InitializedNeonNode { &parent_consensus_hash, &stacks_parent_header.anchored_header.block_hash(), &poison_microblock_tx, - Some(event_observer), + Some(event_dispatcher), &stacks_epoch.block_limit, &stacks_epoch.epoch_id, ) { @@ -1897,8 +1933,8 @@ impl InitializedNeonNode { vrf_proof.clone(), mblock_pubkey_hash, &coinbase_tx, - config.make_block_builder_settings((last_mined_blocks.len() + 1) as u64), - Some(event_observer), + config.make_block_builder_settings((last_mined_blocks.len() + 1) as u64, false), + Some(event_dispatcher), ) { Ok(block) => block, Err(ChainstateError::InvalidStacksMicroblock(msg, mblock_header_hash)) => { @@ -1937,8 +1973,8 @@ impl InitializedNeonNode { vrf_proof.clone(), mblock_pubkey_hash, &coinbase_tx, - config.make_block_builder_settings((last_mined_blocks.len() + 1) as u64), - Some(event_observer), + config.make_block_builder_settings((last_mined_blocks.len() + 1) as u64, false), + Some(event_dispatcher), ) { Ok(block) => block, Err(e) => { @@ -2007,19 +2043,57 @@ impl InitializedNeonNode { sunset_burn, burn_block.block_height, ); + + let cur_burn_chain_tip = SortitionDB::get_canonical_burn_chain_tip(burn_db.conn()) + .expect("FATAL: failed to query sortition DB for canonical burn chain tip"); + + // last chance -- confirm that the stacks tip and burnchain tip are unchanged (since it could have taken long + // enough to build this block that another block could have arrived). + if let Some(stacks_tip) = chain_state + .get_stacks_chain_tip(burn_db) + .expect("FATAL: could not query chain tip") + { + if stacks_tip.anchored_block_hash != anchored_block.header.parent_block + || parent_consensus_hash != stacks_tip.consensus_hash + || cur_burn_chain_tip.sortition_id != burn_block.sortition_id + { + debug!( + "Cancel block-commit; chain tip(s) have changed"; + "block_hash" => %anchored_block.block_hash(), + "tx_count" => anchored_block.txs.len(), + "target_height" => %anchored_block.header.total_work.work, + "parent_consensus_hash" => %parent_consensus_hash, + "parent_block_hash" => %anchored_block.header.parent_block, + "parent_microblock_hash" => %anchored_block.header.parent_microblock, + "parent_microblock_seq" => anchored_block.header.parent_microblock_sequence, + "old_tip_burn_block_hash" => %burn_block.burn_header_hash, + "old_tip_burn_block_height" => burn_block.block_height, + "old_tip_burn_block_sortition_id" => %burn_block.sortition_id, + "attempt" => attempt, + "new_stacks_tip_block_hash" => %stacks_tip.anchored_block_hash, + "new_stacks_tip_consensus_hash" => %stacks_tip.consensus_hash, + "new_tip_burn_block_height" => cur_burn_chain_tip.block_height, + "new_tip_burn_block_sortition_id" => %cur_burn_chain_tip.sortition_id, + "new_burn_block_sortition_id" => %cur_burn_chain_tip.sortition_id + ); + return None; + } + } + let mut op_signer = keychain.generate_op_signer(); debug!( - "Submit block-commit for block {} tx-count {} height {} off of {}/{} with microblock parent {} (seq {}) in burn block {} ({}); attempt {}", - &anchored_block.block_hash(), - anchored_block.txs.len(), - anchored_block.header.total_work.work, - &parent_consensus_hash, - &anchored_block.header.parent_block, - &anchored_block.header.parent_microblock, - &anchored_block.header.parent_microblock_sequence, - &burn_block.burn_header_hash, - burn_block.block_height, - attempt + "Submit block-commit"; + "block_hash" => %anchored_block.block_hash(), + "tx_count" => anchored_block.txs.len(), + "target_height" => anchored_block.header.total_work.work, + "parent_consensus_hash" => %parent_consensus_hash, + "parent_block_hash" => %anchored_block.header.parent_block, + "parent_microblock_hash" => %anchored_block.header.parent_microblock, + "parent_microblock_seq" => anchored_block.header.parent_microblock_sequence, + "tip_burn_block_hash" => %burn_block.burn_header_hash, + "tip_burn_block_height" => burn_block.block_height, + "tip_burn_block_sortition_id" => %burn_block.sortition_id, + "attempt" => attempt ); let res = bitcoin_controller.submit_operation(op, &mut op_signer, attempt); @@ -2125,116 +2199,12 @@ impl InitializedNeonNode { // no-op on UserBurnSupport ops are not supported / produced at this point. - self.last_burn_block = Some(block_snapshot); - + set_last_sortition(&mut self.last_sortition, block_snapshot); last_sortitioned_block.map(|x| x.0) } -} - -impl NeonGenesisNode { - /// Instantiate and initialize a new node, given a config - pub fn new( - config: Config, - mut event_dispatcher: EventDispatcher, - burnchain: Burnchain, - boot_block_exec: Box ()>, - ) -> Self { - let keychain = Keychain::default(config.node.seed.clone()); - let initial_balances = config - .initial_balances - .iter() - .map(|e| (e.address.clone(), e.amount)) - .collect(); - - let mut boot_data = - ChainStateBootData::new(&burnchain, initial_balances, Some(boot_block_exec)); - - // do the initial open! - let (_chain_state, receipts) = match StacksChainState::open_and_exec( - config.is_mainnet(), - config.burnchain.chain_id, - &config.get_chainstate_path_str(), - Some(&mut boot_data), - ) { - Ok(res) => res, - Err(err) => panic!( - "Error while opening chain state at path {}: {:?}", - config.get_chainstate_path_str(), - err - ), - }; - event_dispatcher.process_boot_receipts(receipts); - - Self { - keychain, - config, - event_dispatcher, - burnchain, - } - } - - pub fn into_initialized_leader_node( - self, - burnchain_tip: BurnchainTip, - blocks_processed: BlocksProcessedCounter, - microblocks_processed: BlocksProcessedCounter, - coord_comms: CoordinatorChannels, - sync_comms: PoxSyncWatchdogComms, - attachments_rx: Receiver>, - atlas_config: AtlasConfig, - should_keep_running: Arc, - ) -> InitializedNeonNode { - let config = self.config; - let keychain = self.keychain; - let event_dispatcher = self.event_dispatcher; - - InitializedNeonNode::new( - config, - keychain, - event_dispatcher, - Some(burnchain_tip), - true, - blocks_processed, - microblocks_processed, - coord_comms, - sync_comms, - self.burnchain, - attachments_rx, - atlas_config, - should_keep_running, - ) - } - - pub fn into_initialized_node( - self, - burnchain_tip: BurnchainTip, - blocks_processed: BlocksProcessedCounter, - microblocks_processed: BlocksProcessedCounter, - coord_comms: CoordinatorChannels, - sync_comms: PoxSyncWatchdogComms, - attachments_rx: Receiver>, - atlas_config: AtlasConfig, - should_keep_running: Arc, - ) -> InitializedNeonNode { - let config = self.config; - let keychain = self.keychain; - let event_dispatcher = self.event_dispatcher; - - InitializedNeonNode::new( - config, - keychain, - event_dispatcher, - Some(burnchain_tip), - false, - blocks_processed, - microblocks_processed, - coord_comms, - sync_comms, - self.burnchain, - attachments_rx, - atlas_config, - should_keep_running, - ) + pub fn join(self) { + self.relayer_thread_handle.join().unwrap(); + self.p2p_thread_handle.join().unwrap(); } } diff --git a/testnet/stacks-node/src/run_loop/neon.rs b/testnet/stacks-node/src/run_loop/neon.rs index 3636003a4a..503a603812 100644 --- a/testnet/stacks-node/src/run_loop/neon.rs +++ b/testnet/stacks-node/src/run_loop/neon.rs @@ -1,8 +1,16 @@ use std::cmp; use std::sync::atomic::{AtomicBool, Ordering}; + +#[cfg(test)] +use std::sync::atomic::AtomicU64; + use std::sync::mpsc::sync_channel; +use std::sync::mpsc::Receiver; use std::sync::Arc; use std::thread; +use std::thread::JoinHandle; + +use std::collections::HashSet; use stacks::deps::ctrlc as termination; use stacks::deps::ctrlc::SignalId; @@ -16,37 +24,105 @@ use stacks::chainstate::coordinator::{ check_chainstate_db_versions, BlockEventDispatcher, ChainsCoordinator, CoordinatorCommunication, }; use stacks::chainstate::stacks::db::{ChainStateBootData, StacksChainState}; -use stacks::net::atlas::{AtlasConfig, Attachment}; +use stacks::net::atlas::{AtlasConfig, Attachment, AttachmentInstance}; use stx_genesis::GenesisData; use crate::monitoring::start_serving_monitoring_metrics; +use crate::neon_node::StacksNode; use crate::node::use_test_genesis_chainstate; -use crate::syncctl::PoxSyncWatchdog; +use crate::syncctl::{PoxSyncWatchdog, PoxSyncWatchdogComms}; use crate::{ node::{get_account_balances, get_account_lockups, get_names, get_namespaces}, BitcoinRegtestController, BurnchainController, Config, EventDispatcher, Keychain, - NeonGenesisNode, }; use super::RunLoopCallbacks; use libc; pub const STDERR: i32 = 2; -/// Coordinating a node running in neon mode. #[cfg(test)] -pub struct RunLoop { - config: Config, - pub callbacks: RunLoopCallbacks, - blocks_processed: std::sync::Arc, - microblocks_processed: std::sync::Arc, - coordinator_channels: Option<(CoordinatorReceivers, CoordinatorChannels)>, -} +pub type RunLoopCounter = Arc; #[cfg(not(test))] +pub type RunLoopCounter = (); + +#[derive(Clone)] +pub struct Counters { + pub blocks_processed: RunLoopCounter, + pub microblocks_processed: RunLoopCounter, + pub missed_tenures: RunLoopCounter, + pub cancelled_commits: RunLoopCounter, +} + +impl Counters { + #[cfg(test)] + pub fn new() -> Counters { + Counters { + blocks_processed: RunLoopCounter::new(AtomicU64::new(0)), + microblocks_processed: RunLoopCounter::new(AtomicU64::new(0)), + missed_tenures: RunLoopCounter::new(AtomicU64::new(0)), + cancelled_commits: RunLoopCounter::new(AtomicU64::new(0)), + } + } + + #[cfg(not(test))] + pub fn new() -> Counters { + Counters { + blocks_processed: (), + microblocks_processed: (), + missed_tenures: (), + cancelled_commits: (), + } + } + + #[cfg(test)] + fn inc(ctr: &RunLoopCounter) { + ctr.fetch_add(1, Ordering::SeqCst); + } + + #[cfg(not(test))] + fn inc(_ctr: &RunLoopCounter) {} + + #[cfg(test)] + fn set(ctr: &RunLoopCounter, value: u64) { + ctr.store(value, Ordering::SeqCst); + } + + #[cfg(not(test))] + fn set(_ctr: &RunLoopCounter, _value: u64) {} + + pub fn bump_blocks_processed(&self) { + Counters::inc(&self.blocks_processed); + } + + pub fn bump_microblocks_processed(&self) { + Counters::inc(&self.microblocks_processed); + } + + pub fn bump_missed_tenures(&self) { + Counters::inc(&self.missed_tenures); + } + + pub fn bump_cancelled_commits(&self) { + Counters::inc(&self.cancelled_commits); + } + + pub fn set_microblocks_processed(&self, value: u64) { + Counters::set(&self.microblocks_processed, value) + } +} + +/// Coordinating a node running in neon mode. pub struct RunLoop { config: Config, pub callbacks: RunLoopCallbacks, + counters: Counters, coordinator_channels: Option<(CoordinatorReceivers, CoordinatorChannels)>, + should_keep_running: Arc, + event_dispatcher: EventDispatcher, + pox_watchdog: Option, // can't be instantiated until .start() is called + is_miner: Option, // not known until .start() is called + burnchain: Option, // not known until .start() is called } /// Write to stderr in an async-safe manner. @@ -69,25 +145,25 @@ fn async_safe_write_stderr(msg: &str) { impl RunLoop { /// Sets up a runloop and node, given a config. - #[cfg(not(test))] pub fn new(config: Config) -> Self { let channels = CoordinatorCommunication::instantiate(); - Self { - config, - coordinator_channels: Some(channels), - callbacks: RunLoopCallbacks::new(), + let should_keep_running = Arc::new(AtomicBool::new(true)); + + let mut event_dispatcher = EventDispatcher::new(); + for observer in config.events_observers.iter() { + event_dispatcher.register_observer(observer, should_keep_running.clone()); } - } - #[cfg(test)] - pub fn new(config: Config) -> Self { - let channels = CoordinatorCommunication::instantiate(); Self { config, coordinator_channels: Some(channels), callbacks: RunLoopCallbacks::new(), - blocks_processed: std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0)), - microblocks_processed: std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0)), + counters: Counters::new(), + should_keep_running: should_keep_running, + event_dispatcher, + pox_watchdog: None, + is_miner: None, + burnchain: None, } } @@ -95,46 +171,65 @@ impl RunLoop { self.coordinator_channels.as_ref().map(|x| x.1.clone()) } - #[cfg(test)] - pub fn get_blocks_processed_arc(&self) -> std::sync::Arc { - self.blocks_processed.clone() + pub fn get_blocks_processed_arc(&self) -> RunLoopCounter { + self.counters.blocks_processed.clone() } - #[cfg(not(test))] - fn get_blocks_processed_arc(&self) {} + pub fn get_microblocks_processed_arc(&self) -> RunLoopCounter { + self.counters.microblocks_processed.clone() + } - #[cfg(test)] - pub fn get_microblocks_processed_arc(&self) -> std::sync::Arc { - self.microblocks_processed.clone() + pub fn get_missed_tenures_arc(&self) -> RunLoopCounter { + self.counters.missed_tenures.clone() } - #[cfg(not(test))] - fn get_microblocks_processed_arc(&self) {} + pub fn get_cancelled_commits_arc(&self) -> RunLoopCounter { + self.counters.cancelled_commits.clone() + } - #[cfg(test)] - fn bump_blocks_processed(&self) { - self.blocks_processed - .fetch_add(1, std::sync::atomic::Ordering::SeqCst); + pub fn get_counters(&self) -> Counters { + self.counters.clone() } - #[cfg(not(test))] - fn bump_blocks_processed(&self) {} + pub fn config(&self) -> &Config { + &self.config + } - /// Starts the testnet runloop. - /// - /// This function will block by looping infinitely. - /// It will start the burnchain (separate thread), set-up a channel in - /// charge of coordinating the new blocks coming from the burnchain and - /// the nodes, taking turns on tenures. - pub fn start(&mut self, burnchain_opt: Option, mut mine_start: u64) { - let (coordinator_receivers, coordinator_senders) = self - .coordinator_channels - .take() - .expect("Run loop already started, can only start once after initialization."); + pub fn get_event_dispatcher(&self) -> EventDispatcher { + self.event_dispatcher.clone() + } - let should_keep_running = Arc::new(AtomicBool::new(true)); - let keep_running_writer = should_keep_running.clone(); + pub fn is_miner(&self) -> bool { + self.is_miner.unwrap_or(false) + } + + pub fn get_pox_sync_comms(&self) -> PoxSyncWatchdogComms { + self.pox_watchdog + .as_ref() + .expect("FATAL: tried to get PoX watchdog before calling .start()") + .make_comms_handle() + } + + pub fn get_termination_switch(&self) -> Arc { + self.should_keep_running.clone() + } + + pub fn get_burnchain(&self) -> Burnchain { + self.burnchain + .clone() + .expect("FATAL: tried to get runloop burnchain before calling .start()") + } + + pub fn get_pox_watchdog(&mut self) -> &mut PoxSyncWatchdog { + self.pox_watchdog + .as_mut() + .expect("FATAL: tried to get PoX watchdog before calling .start()") + } + /// Set up termination handler. Have a signal set the `should_keep_running` atomic bool to + /// false. Panics of called more than once. + fn setup_termination_handler(&self) { + let keep_running_writer = self.should_keep_running.clone(); let install = termination::set_handler(move |sig_id| match sig_id { SignalId::Bus => { let msg = "Caught SIGBUS; crashing immediately and dumping core\n"; @@ -157,30 +252,12 @@ impl RunLoop { panic!("FATAL: error setting termination handler - {}", e); } } + } - // Initialize and start the burnchain. - let mut burnchain = BitcoinRegtestController::with_burnchain( - self.config.clone(), - Some(coordinator_senders.clone()), - burnchain_opt, - Some(should_keep_running.clone()), - ); - - let pox_constants = burnchain.get_pox_constants(); - let epochs = burnchain.get_stacks_epochs(); - if !check_chainstate_db_versions( - &epochs, - &self.config.get_burn_db_file_path(), - &self.config.get_chainstate_path_str(), - ) - .expect("FATAL: unable to query filesystem or databases for version information") - { - panic!( - "FATAL: chainstate database(s) are not compatible with the current system epoch" - ); - } - - let is_miner = if self.config.node.miner { + /// Determine if we're the miner. + /// If there's a network error, then assume that we're not a miner. + fn check_is_miner(&mut self, burnchain: &mut BitcoinRegtestController) -> bool { + if self.config.node.miner { let keychain = Keychain::default(self.config.node.seed.clone()); let node_address = Keychain::address_from_burnchain_signer( &keychain.get_burnchain_signer(), @@ -191,7 +268,7 @@ impl RunLoop { BitcoinAddressType::PublicKeyHash, &node_address.to_bytes(), ) - .unwrap(); + .expect("FATAL: unable to determine Bitcoin address for miner"); info!("Miner node: checking UTXOs at address: {}", btc_addr); match burnchain.create_wallet_if_dne() { @@ -216,28 +293,60 @@ impl RunLoop { } else { info!("Will run as a Follower node"); false - }; + } + } - let burnchain_config = burnchain.get_burnchain(); - let mut target_burnchain_block_height = 1.max(burnchain_config.first_block_height); + /// Instantiate the burnchain client and databases. + /// Panics on failure. + fn instantiate_burnchain_state( + &mut self, + burnchain_opt: Option, + coordinator_senders: CoordinatorChannels, + ) -> BitcoinRegtestController { + // Initialize and start the burnchain. + let mut burnchain = BitcoinRegtestController::with_burnchain( + self.config.clone(), + Some(coordinator_senders), + burnchain_opt, + Some(self.should_keep_running.clone()), + ); - info!("Start syncing Bitcoin headers, feel free to grab a cup of coffee, this can take a while"); - match burnchain.start(Some(target_burnchain_block_height)) { - Ok(_) => {} - Err(e) => { - error!("Burnchain controller stopped: {}", e); - return; - } - }; + let epochs = burnchain.get_stacks_epochs(); + if !check_chainstate_db_versions( + &epochs, + &self.config.get_burn_db_file_path(), + &self.config.get_chainstate_path_str(), + ) + .expect("FATAL: unable to query filesystem or databases for version information") + { + error!( + "FATAL: chainstate database(s) are not compatible with the current system epoch" + ); + panic!(); + } // Invoke connect() to perform any db instantiation early if let Err(e) = burnchain.connect_dbs() { error!("Failed to connect to burnchain databases: {}", e); - return; + panic!(); }; - let mainnet = self.config.is_mainnet(); - let chainid = self.config.burnchain.chain_id; + // TODO (hack) instantiate the sortdb in the burnchain + let _ = burnchain.sortdb_mut(); + burnchain + } + + /// Instantiate the Stacks chain state and start the chains coordinator thread. + /// Returns the coordinator thread handle, and the receiving end of the coordinator's atlas + /// attachment channel. + fn spawn_chains_coordinator( + &mut self, + burnchain_config: &Burnchain, + coordinator_receivers: CoordinatorReceivers, + ) -> (JoinHandle<()>, Receiver>) { + let use_test_genesis_data = use_test_genesis_chainstate(&self.config); + + // load up genesis balances let initial_balances = self .config .initial_balances @@ -245,15 +354,8 @@ impl RunLoop { .map(|e| (e.address.clone(), e.amount)) .collect(); - // setup dispatcher - let mut event_dispatcher = EventDispatcher::new(); - for observer in self.config.events_observers.iter() { - event_dispatcher.register_observer(observer, should_keep_running.clone()); - } - - let use_test_genesis_data = use_test_genesis_chainstate(&self.config); - - let mut atlas_config = AtlasConfig::default(false); + // load up genesis Atlas attachments + let mut atlas_config = AtlasConfig::default(self.config.is_mainnet()); let genesis_attachments = GenesisData::new(use_test_genesis_data) .read_name_zonefiles() .into_iter() @@ -261,20 +363,14 @@ impl RunLoop { .collect(); atlas_config.genesis_attachments = Some(genesis_attachments); - let mut coordinator_dispatcher = event_dispatcher.clone(); - - let chainstate_path = self.config.get_chainstate_path_str(); - let coordinator_burnchain_config = burnchain_config.clone(); - - let (attachments_tx, attachments_rx) = sync_channel(1); - + // instantiate chainstate let mut boot_data = ChainStateBootData { initial_balances, post_flight_callback: None, - first_burnchain_block_hash: coordinator_burnchain_config.first_block_hash, - first_burnchain_block_height: coordinator_burnchain_config.first_block_height as u32, - first_burnchain_block_timestamp: coordinator_burnchain_config.first_block_timestamp, - pox_constants: coordinator_burnchain_config.pox_constants.clone(), + first_burnchain_block_hash: burnchain_config.first_block_hash, + first_burnchain_block_height: burnchain_config.first_block_height as u32, + first_burnchain_block_timestamp: burnchain_config.first_block_timestamp, + pox_constants: burnchain_config.pox_constants.clone(), get_bulk_initial_lockups: Some(Box::new(move || { get_account_lockups(use_test_genesis_data) })), @@ -288,17 +384,20 @@ impl RunLoop { }; let (chain_state_db, receipts) = StacksChainState::open_and_exec( - mainnet, - chainid, - &chainstate_path, + self.config.is_mainnet(), + self.config.burnchain.chain_id, + &self.config.get_chainstate_path_str(), Some(&mut boot_data), ) .unwrap(); - coordinator_dispatcher.dispatch_boot_receipts(receipts); + self.event_dispatcher.dispatch_boot_receipts(receipts); - let atlas_config = AtlasConfig::default(mainnet); - let moved_atlas_config = atlas_config.clone(); + // NOTE: re-instantiate AtlasConfig so we don't have to keep the genesis attachments around + let moved_atlas_config = AtlasConfig::default(self.config.is_mainnet()); let moved_config = self.config.clone(); + let moved_burnchain_config = burnchain_config.clone(); + let mut coordinator_dispatcher = self.event_dispatcher.clone(); + let (attachments_tx, attachments_rx) = sync_channel(1); let coordinator_thread_handle = thread::Builder::new() .name("chains-coordinator".to_string()) @@ -308,7 +407,7 @@ impl RunLoop { ChainsCoordinator::run( chain_state_db, - coordinator_burnchain_config, + moved_burnchain_config, attachments_tx, &mut coordinator_dispatcher, coordinator_receivers, @@ -317,64 +416,43 @@ impl RunLoop { fee_estimator.as_deref_mut(), ); }) - .unwrap(); - - // We announce a new burn block so that the chains coordinator - // can resume prior work and handle eventual unprocessed sortitions - // stored during a previous session. - coordinator_senders.announce_new_burn_block(); + .expect("FATAL: failed to start chains coordinator thread"); - let mut burnchain_tip = burnchain - .wait_for_sortitions(None) - .expect("Unable to get burnchain tip"); + (coordinator_thread_handle, attachments_rx) + } - let chainstate_path = self.config.get_chainstate_path_str(); - let mut pox_watchdog = PoxSyncWatchdog::new( - mainnet, - chainid, - chainstate_path, + /// Instantiate the PoX watchdog + fn instantiate_pox_watchdog(&mut self) { + let pox_watchdog = PoxSyncWatchdog::new( + self.config.is_mainnet(), + self.config.burnchain.chain_id, + self.config.get_chainstate_path_str(), self.config.burnchain.poll_time_secs, self.config.connection_options.timeout, self.config.node.pox_sync_sample_secs, self.config.node.pox_sync_sample_secs == 0, - should_keep_running.clone(), + self.should_keep_running.clone(), ) - .unwrap(); + .expect("FATAL: failed to instantiate PoX sync watchdog"); + self.pox_watchdog = Some(pox_watchdog); + } - // setup genesis - let node = NeonGenesisNode::new( - self.config.clone(), - event_dispatcher, - burnchain_config.clone(), - Box::new(|_| {}), - ); - let mut node = if is_miner { - node.into_initialized_leader_node( - burnchain_tip.clone(), - self.get_blocks_processed_arc(), - self.get_microblocks_processed_arc(), - coordinator_senders.clone(), - pox_watchdog.make_comms_handle(), - attachments_rx, - atlas_config, - should_keep_running.clone(), - ) - } else { - node.into_initialized_node( - burnchain_tip.clone(), - self.get_blocks_processed_arc(), - self.get_microblocks_processed_arc(), - coordinator_senders.clone(), - pox_watchdog.make_comms_handle(), - attachments_rx, - atlas_config, - should_keep_running.clone(), - ) - }; + /// Start Prometheus logging + fn start_prometheus(&mut self) { + let prometheus_bind = self.config.node.prometheus_bind.clone(); + if let Some(prometheus_bind) = prometheus_bind { + thread::Builder::new() + .name("prometheus".to_string()) + .spawn(move || { + start_serving_monitoring_metrics(prometheus_bind); + }) + .unwrap(); + } + } - // TODO (hack) instantiate the sortdb in the burnchain - let sortdb = burnchain.sortdb_mut(); - let mut block_height = { + /// Get the sortition DB's highest block height + fn get_sortition_db_height(sortdb: &SortitionDB, burnchain_config: &Burnchain) -> u64 { + let sortition_db_height = { let (stacks_ch, _) = SortitionDB::get_canonical_stacks_chain_tip_hash(sortdb.conn()) .expect("BUG: failed to load canonical stacks chain tip hash"); @@ -394,156 +472,229 @@ impl RunLoop { } } }; + sortition_db_height + } - // Start the runloop - trace!("Begin run loop"); - self.bump_blocks_processed(); + /// Starts the node runloop. + /// + /// This function will block by looping infinitely. + /// It will start the burnchain (separate thread), set-up a channel in + /// charge of coordinating the new blocks coming from the burnchain and + /// the nodes, taking turns on tenures. + pub fn start(&mut self, burnchain_opt: Option, mut mine_start: u64) { + let (coordinator_receivers, coordinator_senders) = self + .coordinator_channels + .take() + .expect("Run loop already started, can only start once after initialization."); - let prometheus_bind = self.config.node.prometheus_bind.clone(); - if let Some(prometheus_bind) = prometheus_bind { - thread::Builder::new() - .name("prometheus".to_string()) - .spawn(move || { - start_serving_monitoring_metrics(prometheus_bind); - }) - .unwrap(); - } + self.setup_termination_handler(); + let mut burnchain = + self.instantiate_burnchain_state(burnchain_opt, coordinator_senders.clone()); + let burnchain_config = burnchain.get_burnchain(); + self.burnchain = Some(burnchain_config.clone()); + + let is_miner = self.check_is_miner(&mut burnchain); + self.is_miner = Some(is_miner); + + info!("Start syncing Bitcoin headers, feel free to grab a cup of coffee, this can take a while"); + + let mut target_burnchain_block_height = 1.max(burnchain_config.first_block_height + 1); + match burnchain.start(Some(target_burnchain_block_height)) { + Ok(_) => {} + Err(e) => { + error!("Burnchain controller stopped: {}", e); + return; + } + }; + + // have headers; boot up the chains coordinator and instantiate the chain state + let (coordinator_thread_handle, attachments_rx) = + self.spawn_chains_coordinator(&burnchain_config, coordinator_receivers); + self.instantiate_pox_watchdog(); + + // We announce a new burn block so that the chains coordinator + // can resume prior work and handle eventual unprocessed sortitions + // stored during a previous session. + coordinator_senders.announce_new_burn_block(); + + // Wait for some sortitions! + let mut burnchain_tip = burnchain + .wait_for_sortitions(None) + .expect("Unable to get burnchain tip"); + + // Boot up the p2p network and relayer, and figure out how many sortitions we have so far + // (it could be non-zero if the node is resuming from chainstate) + let mut node = StacksNode::spawn( + self, + Some(burnchain_tip.clone()), + coordinator_senders.clone(), + attachments_rx, + ); + let sortdb = burnchain.sortdb_mut(); + let mut sortition_db_height = RunLoop::get_sortition_db_height(&sortdb, &burnchain_config); - let mut burnchain_height = block_height; + // Start the runloop + debug!("Begin run loop"); + self.start_prometheus(); + self.counters.bump_blocks_processed(); + + let mut burnchain_height = sortition_db_height; let mut num_sortitions_in_last_cycle = 1; - let mut learned_burnchain_height = false; // prepare to fetch the first reward cycle! - target_burnchain_block_height = burnchain_height + pox_constants.reward_cycle_length as u64; + target_burnchain_block_height = burnchain_config.reward_cycle_to_block_height( + burnchain_config + .block_height_to_reward_cycle(burnchain_height) + .expect("BUG: block height is not in a reward cycle") + + 1, + ); debug!( "Begin main runloop starting a burnchain block {}", - block_height + sortition_db_height ); - let mut last_block_height = 0; + let mut last_tenure_sortition_height = 0; loop { - // Orchestrating graceful termination - if !should_keep_running.load(Ordering::SeqCst) { + if !self.should_keep_running.load(Ordering::SeqCst) { // The p2p thread relies on the same atomic_bool, it will // discontinue its execution after completing its ongoing runloop epoch. info!("Terminating p2p process"); info!("Terminating relayer"); info!("Terminating chains-coordinator"); - coordinator_senders.stop_chains_coordinator(); + coordinator_senders.stop_chains_coordinator(); coordinator_thread_handle.join().unwrap(); - node.relayer_thread_handle.join().unwrap(); - node.p2p_thread_handle.join().unwrap(); + node.join(); info!("Exiting stacks-node"); break; } + let remote_chain_height = burnchain.get_headers_height(); + // wait for the p2p state-machine to do at least one pass - debug!("Wait until we reach steady-state before processing more burnchain blocks..."); + debug!("Wait until Stacks block downloads reach a quiescent state before processing more burnchain blocks"; "remote_chain_height" => remote_chain_height, "local_chain_height" => burnchain_height); - // wait until it's okay to process the next sortitions - let ibd = match pox_watchdog.pox_sync_wait( + // wait until it's okay to process the next reward cycle's sortitions + let ibd = match self.get_pox_watchdog().pox_sync_wait( &burnchain_config, &burnchain_tip, - if learned_burnchain_height { - Some(burnchain_height) - } else { - None - }, + Some(remote_chain_height), num_sortitions_in_last_cycle, ) { Ok(ibd) => ibd, Err(e) => { - debug!("Pox sync wait routine aborted: {:?}", e); + debug!("PoX sync wait routine aborted: {:?}", e); continue; } }; - // will recalculate this - num_sortitions_in_last_cycle = 0; - let (next_burnchain_tip, next_burnchain_height) = - match burnchain.sync(Some(target_burnchain_block_height)) { - Ok(x) => x, - Err(e) => { - warn!("Burnchain controller stopped: {}", e); - continue; - } - }; + // will recalculate this in the following loop + num_sortitions_in_last_cycle = 0; - target_burnchain_block_height = cmp::min( - next_burnchain_height, - target_burnchain_block_height + pox_constants.reward_cycle_length as u64, - ); + // Download each burnchain block and process their sortitions. This, in turn, will + // cause the node's p2p and relayer threads to go fetch and download Stacks blocks and + // process them. This loop runs for one reward cycle, so that the next pass of the + // runloop will cause the PoX sync watchdog to wait until it believes that the node has + // obtained all the Stacks blocks it can. + while burnchain_height <= target_burnchain_block_height { + if !self.should_keep_running.load(Ordering::SeqCst) { + break; + } - // *now* we know the burnchain height - learned_burnchain_height = true; - burnchain_tip = next_burnchain_tip; - burnchain_height = next_burnchain_height; + let (next_burnchain_tip, tip_burnchain_height) = + match burnchain.sync(Some(burnchain_height + 1)) { + Ok(x) => x, + Err(e) => { + warn!("Burnchain controller stopped: {}", e); + continue; + } + }; - let sortition_tip = &burnchain_tip.block_snapshot.sortition_id; - let next_height = burnchain_tip.block_snapshot.block_height; + // *now* we know the burnchain height + burnchain_tip = next_burnchain_tip; + burnchain_height = cmp::min(burnchain_height + 1, tip_burnchain_height); - if next_height != last_block_height { - info!( - "Downloaded burnchain blocks up to height {}; new target height is {}; next_height = {}, block_height = {}", - next_burnchain_height, target_burnchain_block_height, next_height, block_height - ); - } + let sortition_tip = &burnchain_tip.block_snapshot.sortition_id; + let next_sortition_height = burnchain_tip.block_snapshot.block_height; - if next_height > block_height { - debug!( - "New burnchain block height {} > {}", - next_height, block_height - ); + if next_sortition_height != last_tenure_sortition_height { + info!( + "Downloaded burnchain blocks up to height {}; target height is {}; next_sortition_height = {}, sortition_db_height = {}", + burnchain_height, target_burnchain_block_height, next_sortition_height, sortition_db_height + ); + } - let mut sort_count = 0; + if next_sortition_height > sortition_db_height { + debug!( + "New burnchain block height {} > {}", + next_sortition_height, sortition_db_height + ); - // first, let's process all blocks in (block_height, next_height] - for block_to_process in (block_height + 1)..(next_height + 1) { - let block = { - let ic = burnchain.sortdb_ref().index_conn(); - SortitionDB::get_ancestor_snapshot(&ic, block_to_process, sortition_tip) - .unwrap() - .expect("Failed to find block in fork processed by burnchain indexer") - }; - if block.sortition { - sort_count += 1; + let mut sort_count = 0; + + // first, let's process all blocks in (sortition_db_height, next_sortition_height] + for block_to_process in (sortition_db_height + 1)..(next_sortition_height + 1) { + let block = { + let ic = burnchain.sortdb_ref().index_conn(); + SortitionDB::get_ancestor_snapshot(&ic, block_to_process, sortition_tip) + .unwrap() + .expect( + "Failed to find block in fork processed by burnchain indexer", + ) + }; + if block.sortition { + sort_count += 1; + } + + let sortition_id = &block.sortition_id; + + // Have the node process the new block, that can include, or not, a sortition. + node.process_burnchain_state(burnchain.sortdb_mut(), sortition_id, ibd); + + // Now, tell the relayer to check if it won a sortition during this block, + // and, if so, to process and advertize the block. This is basically a + // no-op during boot-up. + // + // _this will block if the relayer's buffer is full_ + if !node.relayer_sortition_notify() { + // relayer hung up, exit. + error!("Block relayer and miner hung up, exiting."); + return; + } } - let sortition_id = &block.sortition_id; - - // Have the node process the new block, that can include, or not, a sortition. - node.process_burnchain_state(burnchain.sortdb_mut(), sortition_id, ibd); + num_sortitions_in_last_cycle = sort_count; + debug!( + "Synchronized burnchain up to block height {} from {} (chain tip height is {}); {} sortitions", + next_sortition_height, sortition_db_height, burnchain_height, num_sortitions_in_last_cycle; + ); - // Now, tell the relayer to check if it won a sortition during this block, - // and, if so, to process and advertize the block - // - // _this will block if the relayer's buffer is full_ - if !node.relayer_sortition_notify() { - // relayer hung up, exit. - error!("Block relayer and miner hung up, exiting."); - return; - } + sortition_db_height = next_sortition_height; + } else if ibd { + // drive block processing after we reach the burnchain tip. + // we may have downloaded all the blocks already, + // so we can't rely on the relayer alone to + // drive it. + coordinator_senders.announce_new_stacks_block(); } - num_sortitions_in_last_cycle = sort_count; - debug!( - "Synchronized burnchain up to block height {} from {} (chain tip height is {}); {} sortitions", - next_height, block_height, burnchain_height, num_sortitions_in_last_cycle; - ); - - block_height = next_height; - } else if ibd { - // drive block processing after we reach the burnchain tip. - // we may have downloaded all the blocks already, - // so we can't rely on the relayer alone to - // drive it. - coordinator_senders.announce_new_stacks_block(); + if burnchain_height == target_burnchain_block_height + || burnchain_height == tip_burnchain_height + { + break; + } } - if block_height >= burnchain_height && !ibd { + target_burnchain_block_height = burnchain_config.reward_cycle_to_block_height( + burnchain_config + .block_height_to_reward_cycle(burnchain_height) + .expect("BUG: block height is not in a reward cycle") + + 1, + ); + + if sortition_db_height >= burnchain_height && !ibd { let canonical_stacks_tip_height = SortitionDB::get_canonical_burn_chain_tip(burnchain.sortdb_ref().conn()) .map(|snapshot| snapshot.canonical_stacks_tip_height) @@ -560,12 +711,12 @@ impl RunLoop { mine_start = 0; // at tip, and not downloading. proceed to mine. - if last_block_height != block_height { + if last_tenure_sortition_height != sortition_db_height { info!( "Synchronized full burnchain up to height {}. Proceeding to mine blocks", - block_height + sortition_db_height ); - last_block_height = block_height; + last_tenure_sortition_height = sortition_db_height; } if !node.relayer_issue_tenure() { // relayer hung up, exit. diff --git a/testnet/stacks-node/src/tests/neon_integrations.rs b/testnet/stacks-node/src/tests/neon_integrations.rs index 204af87713..58d4d4cdb0 100644 --- a/testnet/stacks-node/src/tests/neon_integrations.rs +++ b/testnet/stacks-node/src/tests/neon_integrations.rs @@ -15,15 +15,14 @@ use stacks::burnchains::bitcoin::address::{BitcoinAddress, BitcoinAddressType}; use stacks::burnchains::bitcoin::BitcoinNetworkType; use stacks::burnchains::Txid; use stacks::chainstate::burn::operations::{BlockstackOperationType, PreStxOp, TransferStxOp}; -use stacks::chainstate::stacks::TokenTransferMemo; use stacks::clarity::vm_execute as execute; use stacks::codec::StacksMessageCodec; use stacks::core; use stacks::core::CHAIN_ID_TESTNET; use stacks::net::atlas::{AtlasConfig, AtlasDB, MAX_ATTACHMENT_INV_PAGES_PER_REQUEST}; use stacks::net::{ - AccountEntryResponse, ContractSrcResponse, FeeRateEstimateRequestBody, GetAttachmentResponse, - GetAttachmentsInvResponse, PostTransactionRequestBody, RPCPeerInfoData, + AccountEntryResponse, ContractSrcResponse, GetAttachmentResponse, GetAttachmentsInvResponse, + PostTransactionRequestBody, RPCPeerInfoData, }; use stacks::types::chainstate::{ BlockHeaderHash, BurnchainHeaderHash, StacksAddress, StacksBlockHeader, StacksBlockId, @@ -1452,7 +1451,8 @@ fn bitcoind_forking_test() { btc_regtest_controller.invalidate_block(&burn_header_hash_to_fork); btc_regtest_controller.build_next_block(5); - thread::sleep(Duration::from_secs(5)); + thread::sleep(Duration::from_secs(50)); + eprintln!("Wait for block off of shallow fork"); next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); let account = get_account(&http_origin, &miner_account); @@ -1471,7 +1471,8 @@ fn bitcoind_forking_test() { btc_regtest_controller.invalidate_block(&burn_header_hash_to_fork); btc_regtest_controller.build_next_block(10); - thread::sleep(Duration::from_secs(5)); + thread::sleep(Duration::from_secs(50)); + eprintln!("Wait for block off of deep fork"); next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); let account = get_account(&http_origin, &miner_account); @@ -1483,8 +1484,9 @@ fn bitcoind_forking_test() { let account = get_account(&http_origin, &miner_account); assert_eq!(account.balance, 0); // but we're able to keep on mining - assert_eq!(account.nonce, 3); + assert!(account.nonce >= 3); + eprintln!("End of test"); channel.stop_chains_coordinator(); } @@ -1611,8 +1613,9 @@ fn microblock_integration_test() { }); conf.node.mine_microblocks = true; - conf.node.wait_time_for_microblocks = 10_000; conf.node.microblock_frequency = 1_000; + conf.miner.microblock_attempt_time_ms = 1_000; + conf.node.wait_time_for_microblocks = 0; test_observer::spawn(); @@ -1680,14 +1683,18 @@ fn microblock_integration_test() { // now let's mine a couple blocks, and then check the sender's nonce. // this one wakes up our node, so that it'll mine a microblock _and_ an anchor block. next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); + sleep_ms(10_000); + // this one will contain the sortition from above anchor block, // which *should* have also confirmed the microblock. info!("Wait for second block"); next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); + sleep_ms(10_000); // I guess let's push another block for good measure? info!("Wait for third block"); next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); + sleep_ms(10_000); info!("Test microblock"); @@ -2431,7 +2438,8 @@ fn size_check_integration_test() { conf.node.mine_microblocks = true; conf.node.wait_time_for_microblocks = 5000; - conf.node.microblock_frequency = 1000; + conf.node.microblock_frequency = 5000; + conf.miner.microblock_attempt_time_ms = 120_000; conf.miner.min_tx_fee = 1; conf.miner.first_attempt_time_ms = i64::max_value() as u64; @@ -2608,6 +2616,7 @@ fn size_overflow_unconfirmed_microblocks_integration_test() { conf.node.mine_microblocks = true; conf.node.wait_time_for_microblocks = 5_000; conf.node.microblock_frequency = 5_000; + conf.miner.microblock_attempt_time_ms = 120_000; conf.miner.min_tx_fee = 1; conf.miner.first_attempt_time_ms = i64::max_value() as u64; @@ -2802,6 +2811,7 @@ fn size_overflow_unconfirmed_stream_microblocks_integration_test() { conf.node.mine_microblocks = true; conf.node.wait_time_for_microblocks = 1000; conf.node.microblock_frequency = 1000; + conf.miner.microblock_attempt_time_ms = 120_000; conf.node.max_microblocks = 65536; conf.burnchain.max_rbf = 1000000; @@ -2992,6 +3002,7 @@ fn size_overflow_unconfirmed_invalid_stream_microblocks_integration_test() { conf.node.mine_microblocks = true; conf.node.wait_time_for_microblocks = 5_000; conf.node.microblock_frequency = 1_000; + conf.miner.microblock_attempt_time_ms = 120_000; conf.node.max_microblocks = 65536; conf.burnchain.max_rbf = 1000000; @@ -3260,6 +3271,7 @@ fn runtime_overflow_unconfirmed_microblocks_integration_test() { conf.node.mine_microblocks = true; conf.node.wait_time_for_microblocks = 0; conf.node.microblock_frequency = 15000; + conf.miner.microblock_attempt_time_ms = 120_000; conf.miner.min_tx_fee = 1; conf.miner.first_attempt_time_ms = i64::max_value() as u64; @@ -3865,7 +3877,7 @@ fn mining_events_integration_test() { let mb_tx = make_contract_publish_microblock_only(&spender_sk_2, 0, 620000, "small", &small_contract); - let (mut conf, miner_account) = neon_integration_test_conf(); + let (mut conf, _) = neon_integration_test_conf(); conf.initial_balances.push(InitialBalance { address: addr.clone().into(), @@ -4031,7 +4043,7 @@ fn mining_events_integration_test() { // dupe contract error event match &third_block_tx_events[2] { - TransactionEvent::ProcessingError(TransactionErrorEvent { txid, error }) => { + TransactionEvent::ProcessingError(TransactionErrorEvent { txid: _, error }) => { assert_eq!( error, "Duplicate contract 'ST3WM51TCWMJYGZS1QFMC28DH5YP86782YGR113C1.small'" @@ -6598,3 +6610,73 @@ fn use_latest_tip_integration_test() { ) .is_ok()); } + +#[test] +#[ignore] +fn test_flash_block_skip_tenure() { + if env::var("BITCOIND_TEST") != Ok("1".into()) { + return; + } + + let (mut conf, miner_account) = neon_integration_test_conf(); + conf.miner.microblock_attempt_time_ms = 5_000; + conf.node.wait_time_for_microblocks = 0; + + let mut btcd_controller = BitcoinCoreController::new(conf.clone()); + btcd_controller + .start_bitcoind() + .map_err(|_e| ()) + .expect("Failed starting bitcoind"); + + let mut btc_regtest_controller = BitcoinRegtestController::new(conf.clone(), None); + let http_origin = format!("http://{}", &conf.node.rpc_bind); + + btc_regtest_controller.bootstrap_chain(201); + + eprintln!("Chain bootstrapped..."); + + let mut run_loop = neon::RunLoop::new(conf); + let blocks_processed = run_loop.get_blocks_processed_arc(); + let missed_tenures = run_loop.get_missed_tenures_arc(); + + let channel = run_loop.get_coordinator_channel().unwrap(); + + thread::spawn(move || run_loop.start(None, 0)); + + // give the run loop some time to start up! + wait_for_runloop(&blocks_processed); + + // first block wakes up the run loop + next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); + + // first block will hold our VRF registration + next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); + + // second block will be the first mined Stacks block + next_block_and_wait(&mut btc_regtest_controller, &blocks_processed); + + // fault injection: force tenures to take 11 seconds + std::env::set_var("STX_TEST_SLOW_TENURE".to_string(), "11000".to_string()); + + for i in 0..10 { + // build one bitcoin block every 10 seconds + eprintln!("Build bitcoin block +{}", i); + btc_regtest_controller.build_next_block(1); + sleep_ms(10000); + } + + // at least one tenure was skipped + let num_skipped = missed_tenures.load(Ordering::SeqCst); + eprintln!("Skipped {} tenures", &num_skipped); + assert!(num_skipped > 1); + + // let's query the miner's account nonce: + + eprintln!("Miner account: {}", miner_account); + + let account = get_account(&http_origin, &miner_account); + assert_eq!(account.balance, 0); + assert_eq!(account.nonce, 2); + + channel.stop_chains_coordinator(); +}