From 80803c78a4579641b604c110e411556588ebdf24 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 10:19:59 +0100 Subject: [PATCH 01/20] bitcoind: handle missing previousblockhash from getblockheader It seems that internally bitcoind might temporarily not have a pprev pointer for a block. This will result in the optional "previousblockhash" field to be null and would previously make us crash. Handle that gracefully. --- src/bitcoin/d/mod.rs | 10 ++++++---- src/bitcoin/mod.rs | 10 +++++----- src/bitcoin/poller/looper.rs | 21 ++++++++++++++------- src/testutils.rs | 2 +- 4 files changed, 26 insertions(+), 17 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index d1427049..d3d29ca5 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -679,12 +679,14 @@ impl BitcoinD { let previous_blockhash = res .get("previousblockhash") .and_then(Json::as_str) - .and_then(|s| bitcoin::BlockHash::from_str(s).ok()) - .expect("Invalid previousblockhash in `getblockheader` response"); + .map(|s| { + bitcoin::BlockHash::from_str(s) + .expect("Invalid previousblockhash in `getblockheader` response") + }); let height = res .get("height") .and_then(Json::as_i64) - .expect("Invalid height in `getblockheader` response: not an u32") + .expect("Invalid height in `getblockheader` response: not an i64") as i32; BlockStats { confirmations, @@ -848,7 +850,7 @@ impl From for GetTxRes { #[derive(Debug, Clone)] pub struct BlockStats { pub confirmations: i32, - pub previous_blockhash: bitcoin::BlockHash, + pub previous_blockhash: Option, pub blockhash: bitcoin::BlockHash, pub height: i32, } diff --git a/src/bitcoin/mod.rs b/src/bitcoin/mod.rs index ae7b2257..9c48ceb3 100644 --- a/src/bitcoin/mod.rs +++ b/src/bitcoin/mod.rs @@ -84,7 +84,7 @@ pub trait BitcoinInterface: Send { ) -> Vec<(bitcoin::OutPoint, bitcoin::Txid, i32, u32)>; /// Get the common ancestor between the Bitcoin backend's tip and the given tip. - fn common_ancestor(&self, tip: &BlockChainTip) -> BlockChainTip; + fn common_ancestor(&self, tip: &BlockChainTip) -> Option; /// Broadcast this transaction to the Bitcoin P2P network fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), BitcoinError>; @@ -260,19 +260,19 @@ impl BitcoinInterface for d::BitcoinD { spent } - fn common_ancestor(&self, tip: &BlockChainTip) -> BlockChainTip { + fn common_ancestor(&self, tip: &BlockChainTip) -> Option { let mut stats = self.get_block_stats(tip.hash); let mut ancestor = *tip; while stats.confirmations == -1 { - stats = self.get_block_stats(stats.previous_blockhash); + stats = self.get_block_stats(stats.previous_blockhash?); ancestor = BlockChainTip { hash: stats.blockhash, height: stats.height, }; } - ancestor + Some(ancestor) } fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), BitcoinError> { @@ -335,7 +335,7 @@ impl BitcoinInterface for sync::Arc> self.lock().unwrap().spent_coins(outpoints) } - fn common_ancestor(&self, tip: &BlockChainTip) -> BlockChainTip { + fn common_ancestor(&self, tip: &BlockChainTip) -> Option { self.lock().unwrap().common_ancestor(tip) } diff --git a/src/bitcoin/poller/looper.rs b/src/bitcoin/poller/looper.rs index 7d39124c..77653a80 100644 --- a/src/bitcoin/poller/looper.rs +++ b/src/bitcoin/poller/looper.rs @@ -150,13 +150,20 @@ fn new_tip(bit: &impl BitcoinInterface, current_tip: &BlockChainTip) -> TipUpdat // block chain re-organisation. Find the common ancestor between our current chain and // the new chain and return that. The caller will take care of rewinding our state. log::info!("Block chain reorganization detected. Looking for common ancestor."); - let common_ancestor = bit.common_ancestor(current_tip); - log::info!( - "Common ancestor found: '{}'. Starting rescan from there. Old tip was '{}'.", - common_ancestor, - current_tip - ); - TipUpdate::Reorged(common_ancestor) + if let Some(common_ancestor) = bit.common_ancestor(current_tip) { + log::info!( + "Common ancestor found: '{}'. Starting rescan from there. Old tip was '{}'.", + common_ancestor, + current_tip + ); + TipUpdate::Reorged(common_ancestor) + } else { + log::error!( + "Failed to get common ancestor for tip '{}'. Starting over.", + current_tip + ); + new_tip(bit, current_tip) + } } fn updates( diff --git a/src/testutils.rs b/src/testutils.rs index eff9da06..6add2785 100644 --- a/src/testutils.rs +++ b/src/testutils.rs @@ -67,7 +67,7 @@ impl BitcoinInterface for DummyBitcoind { Vec::new() } - fn common_ancestor(&self, _: &BlockChainTip) -> BlockChainTip { + fn common_ancestor(&self, _: &BlockChainTip) -> Option { todo!() } From 6323ae0d0fb2726e95a97ceda52b133027297719 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 10:47:56 +0100 Subject: [PATCH 02/20] bitcoind: add time and MTP to BlockStats --- src/bitcoin/d/mod.rs | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index d3d29ca5..f0157b18 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -688,11 +688,23 @@ impl BitcoinD { .and_then(Json::as_i64) .expect("Invalid height in `getblockheader` response: not an i64") as i32; + let time = res + .get("time") + .and_then(Json::as_u64) + .expect("Invalid timestamp in `getblockheader` response: not an u64") + as u32; + let median_time_past = res + .get("mediantime") + .and_then(Json::as_u64) + .expect("Invalid median timestamp in `getblockheader` response: not an u64") + as u32; BlockStats { confirmations, previous_blockhash, height, blockhash, + time, + median_time_past, } } @@ -853,4 +865,6 @@ pub struct BlockStats { pub previous_blockhash: Option, pub blockhash: bitcoin::BlockHash, pub height: i32, + pub time: u32, + pub median_time_past: u32, } From 51ff7d6734db353e0aab65c45d322c45d7e3aa8b Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 10:25:55 +0100 Subject: [PATCH 03/20] bitcoind: a utility to find a block height by block timestamp We are passed a timestamp and we want to know down to what height we should rescan / roll back. That's helpful for it. It was a bit tricky although it's a simple binary search.. So to make sure i got it right i made it a standalone function in a utils/ module to be able to unit test it. See the TODO, it's theoretically not precisely entirely correct. But it's good enough for now. --- src/bitcoin/d/utils.rs | 350 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 350 insertions(+) create mode 100644 src/bitcoin/d/utils.rs diff --git a/src/bitcoin/d/utils.rs b/src/bitcoin/d/utils.rs new file mode 100644 index 00000000..e113d0b1 --- /dev/null +++ b/src/bitcoin/d/utils.rs @@ -0,0 +1,350 @@ +use crate::bitcoin::{d::BlockStats, BlockChainTip}; + +use miniscript::bitcoin; + +// As a standalone function to unit test it. +/// Get the last block of the chain before the given date by performing a binary search. +pub fn block_before_date( + target_timestamp: u32, + chain_tip: BlockChainTip, + mut get_hash: Fh, + mut get_stats: Fs, +) -> Option +where + Fh: FnMut(i32) -> Option, + Fs: FnMut(bitcoin::BlockHash) -> BlockStats, +{ + log::debug!("Looking for the first block before {}", target_timestamp); + + let mut start_height = 0; + let mut end_height = chain_tip.height; + + let genesis_stats = get_stats(get_hash(0).expect("Genesis hash")); + let tip_stats = get_stats(chain_tip.hash); + if !(genesis_stats.time..tip_stats.time).contains(&target_timestamp) { + return None; + } + + while start_height < end_height { + log::debug!("Start: {}, end: {}", start_height, end_height,); + let delta = end_height.checked_sub(start_height).unwrap(); + let current_height = start_height + delta.checked_div(2).unwrap(); + // We want the last block with a timestamp below, not the first with a higher one. + let next_height = current_height.checked_add(1).unwrap(); + let next_stats = get_stats(get_hash(next_height)?); + log::debug!("Current next block: {:?}", next_stats); + + if target_timestamp > next_stats.time { + start_height = next_height; + } else { + assert!(current_height < end_height); + end_height = current_height; + } + } + + // TODO: the timestamps in the chain are not strictly ordered. There could technically be a + // timestamp above the target a bit down this height. I think we would be safe by scanning the + // last 12 blocks and checking their timestamp is below the target. Would we? + log::debug!("Result height: {}", start_height); + Some(BlockChainTip { + height: start_height, + hash: get_hash(start_height)?, + }) +} + +#[cfg(test)] +mod tests { + use super::*; + use std::str::FromStr; + + // The expected number of seconds in average between two blocks. + const EXPECTED_BLOCK_INTERVAL_SECS: u32 = 600; + + // Inefficient dummy implementation of BitcoinD's self.get_block_hash + fn get_hash(chain: &[(BlockChainTip, BlockStats)], height: i32) -> Option { + chain + .iter() + .find(|(tip, _)| tip.height == height) + .map(|(tip, _)| tip.hash) + } + + // Inefficient dummy implementation of BitcoinD's self.get_block_stats + fn get_stats(chain: &[(BlockChainTip, BlockStats)], hash: bitcoin::BlockHash) -> BlockStats { + chain + .iter() + .find(|(tip, _)| tip.hash == hash) + .unwrap() + .1 + .clone() + } + + macro_rules! bh { + ($h_str: literal) => { + bitcoin::BlockHash::from_str($h_str).unwrap() + }; + } + + // Create a dummy BlockStats struct with the given time + fn create_stats(time: u32) -> BlockStats { + // TODO + BlockStats { + height: 0, + confirmations: 0, + previous_blockhash: Some(bh!( + "000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f" + )), + blockhash: bh!("000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f"), + time, + median_time_past: 0, + } + } + + #[test] + fn blk_before_time() { + // A timestamp after the tip's + let dummy_chain = [ + ( + BlockChainTip { + height: 0, + hash: bh!("000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f"), + }, + create_stats(1231006505), + ), + ( + BlockChainTip { + height: 761683, + hash: bh!("0000000000000000000560bb21fbab991fe5f7d9a949eb424f9be3c34a55a54f"), + }, + create_stats(1667558116), + ), + ]; + assert!(block_before_date( + dummy_chain[0].1.time + 1, + dummy_chain[0].0, + |h| get_hash(&dummy_chain, h), + |h| get_stats(&dummy_chain, h), + ) + .is_none()); + + // A timestamp before the genesis + let dummy_chain = [ + ( + BlockChainTip { + height: 0, + hash: bh!("000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f"), + }, + create_stats(1231006505), + ), + ( + BlockChainTip { + height: 761683, + hash: bh!("0000000000000000000560bb21fbab991fe5f7d9a949eb424f9be3c34a55a54f"), + }, + create_stats(1667558116), + ), + ]; + assert!(block_before_date( + dummy_chain[0].1.time - 1, + dummy_chain[0].0, + |h| get_hash(&dummy_chain, h), + |h| get_stats(&dummy_chain, h), + ) + .is_none()); + + // Simulate and detail a full binary search through a dummy chain. + let target_timestamp = 1531006505; + let dummy_chain = [ + // Genesis: will be queried at step 0 (0, 761_683) + ( + BlockChainTip { + height: 0, + hash: bh!("000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f"), + }, + create_stats(1231006505), + ), + // Step 1 (0, 761_683): timestamp too low. + ( + BlockChainTip { + height: 380_842, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19ba3"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 10), + ), + // Step 4 (380_842, 476_052): timestamp too low. + ( + BlockChainTip { + height: 428_448, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19ba4"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 9), + ), + // Step 6 (428_448, 452_250): timestamp too low. + ( + BlockChainTip { + height: 440_350, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19ba5"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 8), + ), + // Step 7 (440_350, 452_250): timestamp too low. + ( + BlockChainTip { + height: 446_301, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19ba6"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 7), + ), + // Step 8 (446_301, 452_250): timestamp too low. + ( + BlockChainTip { + height: 449_276, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19ba7"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 6), + ), + // Step 9 (449_276, 452_250): timestamp too low. + ( + BlockChainTip { + height: 450_764, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19ba8"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 5), + ), + // Step 10 (450_764, 452_250): timestamp too low. + ( + BlockChainTip { + height: 451_508, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19ba9"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 4), + ), + // Step 11 (451_508, 452_250): timestamp too low (and equal to the previous one). + ( + BlockChainTip { + height: 451_880, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bab"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 4), + ), + // Step 12 (451_880, 452_250): timestamp too low. + ( + BlockChainTip { + height: 452_066, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bac"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 3), + ), + // Step 13 (452_066, 452_250): timestamp too low. + ( + BlockChainTip { + height: 452_159, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bad"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS * 2), + ), + // Step 14 (452_159, 452_250): timestamp too low. + ( + BlockChainTip { + height: 452_205, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bae"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS), + ), + // Step 15 (452_205, 452_250): timestamp too low. + ( + BlockChainTip { + height: 452_228, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19baf"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS), + ), + // Step 17 (452_228, 452_239): timestamp too low. + ( + BlockChainTip { + height: 452_234, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb0"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS / 2), + ), + // Step 18 (452_234, 452_239): timestamp too low. + ( + BlockChainTip { + height: 452_237, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb1"), + }, + create_stats(target_timestamp - EXPECTED_BLOCK_INTERVAL_SECS / 4), + ), + // Step 21 (452_237, 452_238): timestamp too low. + ( + BlockChainTip { + height: 452_238, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb2"), + }, + create_stats(target_timestamp - 1), + ), + // Step 20 (452_237, 452_239): timestamp too high (first block at this timestamp). + ( + BlockChainTip { + height: 452_239, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb3"), + }, + create_stats(target_timestamp), + ), + // Step 16 (452_228, 452_250): timestamp too high (timestamp don't necessarily + // increase per block height). + ( + BlockChainTip { + height: 452_240, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb4"), + }, + create_stats(target_timestamp + 1), + ), + // Step 5 (428_448, 476_052): timestamp too high (again equal! That's possible). + ( + BlockChainTip { + height: 452_251, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb5"), + }, + create_stats(target_timestamp), + ), + // Step 3 (380_842, 571_262): timestamp too high (because equal). + ( + BlockChainTip { + height: 476_053, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb6"), + }, + create_stats(target_timestamp), + ), + // Step 2 (380_842, 761_683): timestamp too high. + ( + BlockChainTip { + height: 571_263, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb7"), + }, + create_stats(target_timestamp + EXPECTED_BLOCK_INTERVAL_SECS), + ), + // Tip: will be queried at step 0 + ( + BlockChainTip { + height: 761_683, + hash: bh!("0000000000000000000560bb21fbab991fe5f7d9a949eb424f9be3c34a55a54f"), + }, + create_stats(1667558116), + ), + ]; + assert_eq!( + block_before_date( + target_timestamp, + dummy_chain[dummy_chain.len() - 1].0, + |h| get_hash(&dummy_chain, h), + |h| get_stats(&dummy_chain, h), + ) + .unwrap(), + // Step 21 above + BlockChainTip { + height: 452_238, + hash: bh!("000000000000000005c0655db17fde80f67ff0502a62b7250ed2685619d19bb2"), + } + ); + } +} From 45d601282fd4e722ad8558243c4b8c9c1ad11345 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 17:40:06 +0100 Subject: [PATCH 04/20] bitcoind: only sleep on error if there is >0 retries Don't sleep if we won't retry. --- src/bitcoin/d/mod.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index f0157b18..52fbed1d 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -219,8 +219,10 @@ impl BitcoinD { Some(simple_http::Error::Timeout) | Some(simple_http::Error::SocketError(_)) | Some(simple_http::Error::HttpErrorCode(503)) => { - std::thread::sleep(Duration::from_secs(1)); - log::debug!("Retrying RPC request to bitcoind: attempt #{}", i); + if i <= self.retries { + std::thread::sleep(Duration::from_secs(1)); + log::debug!("Retrying RPC request to bitcoind: attempt #{}", i); + } error = Some(e); } _ => return Err(e), From c32f714a2ed12135f07a2dd77951b15c3f0fcfe5 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 17:40:59 +0100 Subject: [PATCH 05/20] bitcoind: add a 'noreply' client The query we are going to use to rescan, 'importdescriptors' will block until the rescan is finished. Stopping the connection through a timeout immediately after triggering the rescan is a workaround to make it asynchronous. Eventually we should probably use 'rescanblockchain' but then it wouldn't update the timestamps of the descriptors in the watchonly wallet... --- src/bitcoin/d/mod.rs | 43 ++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 40 insertions(+), 3 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index 52fbed1d..f7d74293 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -54,6 +54,20 @@ impl BitcoindError { _ => false, } } + + /// Is it a timeout of any kind? + pub fn is_timeout(&self) -> bool { + match self { + BitcoindError::Server(jsonrpc::Error::Transport(ref e)) => { + match e.downcast_ref::() { + Some(simple_http::Error::Timeout) => true, + Some(simple_http::Error::SocketError(e)) => e.kind() == io::ErrorKind::TimedOut, + _ => false, + } + } + _ => false, + } + } } impl std::fmt::Display for BitcoindError { @@ -116,7 +130,11 @@ impl From for BitcoindError { } pub struct BitcoinD { + /// Client for generalistic calls. node_client: Client, + /// A client that will disregard responses to the queries it makes. + sendonly_client: Client, + /// A client for calls related to the wallet. watchonly_client: Client, watchonly_wallet_path: String, /// How many times we'll retry upon failure to send a request. @@ -183,12 +201,21 @@ impl BitcoinD { .url(&watchonly_url) .map_err(BitcoindError::from)? .timeout(Duration::from_secs(RPC_SOCKET_TIMEOUT)) + .cookie_auth(cookie_string.clone()) + .build(), + ); + let sendonly_client = Client::with_transport( + SimpleHttpTransport::builder() + .url(&watchonly_url) + .map_err(BitcoindError::from)? + .timeout(Duration::from_secs(1)) .cookie_auth(cookie_string) .build(), ); Ok(BitcoinD { node_client, + sendonly_client, watchonly_client, watchonly_wallet_path, retries: 0, @@ -258,9 +285,14 @@ impl BitcoinD { }) } - fn make_node_request(&self, method: &str, params: &[Box]) -> Json { - self.make_request(&self.node_client, method, params) - .expect("We must not fail to make a request for more than a minute") + // Make a request for which you don't expect a response. This is achieved by setting a very low + // timeout on the connection, and will panic on any other error than a timeout. + fn make_noreply_request(&self, method: &str, params: &[Box]) { + if let Err(e) = self.make_request(&self.sendonly_client, method, params) { + if !e.is_timeout() { + panic!("{}", e); + } + } } fn make_fallible_node_request( @@ -271,6 +303,11 @@ impl BitcoinD { self.make_request(&self.node_client, method, params) } + fn make_node_request(&self, method: &str, params: &[Box]) -> Json { + self.make_request(&self.sendonly_client, method, params) + .expect("We must not fail to make a request for more than a minute") + } + fn make_wallet_request( &self, method: &str, From bd4de0b87a0db999ead08de335566df462251ca6 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 17:59:31 +0100 Subject: [PATCH 06/20] bitcoin: interface for rescanning the chain on the Bitcoin backend For now we are given a timestamp and use 'importdescriptors'. It might be better to be passed a height and use 'rescanblockchain' instead. --- src/bitcoin/d/mod.rs | 49 ++++++++++++++++++++++++++++++++++++++++---- src/bitcoin/mod.rs | 48 +++++++++++++++++++++++++++++++++++++++++++ src/testutils.rs | 16 +++++++++++++++ 3 files changed, 109 insertions(+), 4 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index f7d74293..7dea4d14 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -1,7 +1,9 @@ ///! Implementation of the Bitcoin interface using bitcoind. ///! ///! We use the RPC interface and a watchonly descriptor wallet. +mod utils; use crate::{bitcoin::BlockChainTip, config, descriptors::MultipathDescriptor}; +use utils::block_before_date; use std::{collections::HashSet, convert::TryInto, fs, io, str::FromStr, time::Duration}; @@ -391,19 +393,34 @@ impl BitcoinD { } // Import the receive and change descriptors from the multipath descriptor to bitcoind. - fn import_descriptor(&self, desc: &MultipathDescriptor) -> Option { + // An optional timestamp may be given to rescan the chain from this date for this descriptor. + fn import_descriptor( + &self, + desc: &MultipathDescriptor, + timestamp: Option, + ) -> Option { let descriptors = [desc.receive_descriptor(), desc.change_descriptor()] .iter() .map(|desc| { - // TODO: rescan feature will probably need another timestamp than 'now' serde_json::json!({ "desc": desc.to_string(), - "timestamp": "now", + "timestamp": timestamp.map(Json::from).unwrap_or_else(|| "now".into()), "active": false, }) }) .collect(); + // If this will trigger a rescan, do not wait for the response. + if timestamp.is_some() { + // TODO: should we check there was not timeout when writing the request on the + // TcpStream in the SimpleHttpTransport implem? + // NOTE: if the rescan gets aborted through the 'abortrescan' RPC we won't see the + // error and bitcoind will keep the new timestamps for the descriptors as if it had + // successfully rescanned them. + self.make_noreply_request("importdescriptors", ¶ms!(Json::Array(descriptors))); + return None; + } + let res = self.make_wallet_request("importdescriptors", ¶ms!(Json::Array(descriptors))); let all_succeeded = res .as_array() @@ -459,7 +476,7 @@ impl BitcoinD { if let Some(err) = self.create_wallet(self.watchonly_wallet_path.clone()) { return Err(BitcoindError::WalletCreation(err)); } - if let Some(err) = self.import_descriptor(main_descriptor) { + if let Some(err) = self.import_descriptor(main_descriptor, None) { return Err(BitcoindError::DescriptorImport(err)); } @@ -754,6 +771,30 @@ impl BitcoinD { )?; Ok(()) } + + pub fn start_rescan(&self, desc: &MultipathDescriptor, timestamp: u32) { + self.import_descriptor(desc, Some(timestamp)); + } + + /// Get the progress of the ongoing rescan, if there is any. + pub fn rescan_progress(&self) -> Option { + self.make_wallet_request("getwalletinfo", &[]) + .get("scanning") + // If no rescan is ongoing, it will fail cause it would be 'false' + .and_then(Json::as_object) + .and_then(|map| map.get("progress")) + .and_then(Json::as_f64) + } + + /// Get the height and hash of the last block with a timestamp below the given one. + pub fn tip_before_timestamp(&self, timestamp: u32) -> Option { + block_before_date( + timestamp, + self.chain_tip(), + |h| self.get_block_hash(h), + |h| self.get_block_stats(h), + ) + } } // Bitcoind uses a guess for the value of verificationprogress. It will eventually get to // be 1, and we want to be less conservative. diff --git a/src/bitcoin/mod.rs b/src/bitcoin/mod.rs index 9c48ceb3..d54279b6 100644 --- a/src/bitcoin/mod.rs +++ b/src/bitcoin/mod.rs @@ -55,6 +55,9 @@ pub trait BitcoinInterface: Send { /// Get the best block info. fn chain_tip(&self) -> BlockChainTip; + /// Get the timestamp set in the best block's header. + fn tip_time(&self) -> u32; + /// Check whether this former tip is part of the current best chain. fn is_in_chain(&self, tip: &BlockChainTip) -> bool; @@ -88,6 +91,17 @@ pub trait BitcoinInterface: Send { /// Broadcast this transaction to the Bitcoin P2P network fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), BitcoinError>; + + /// Trigger a rescan of the block chain for transactions related to this descriptor since + /// the given date. + fn start_rescan(&self, desc: &descriptors::MultipathDescriptor, timestamp: u32); + + /// Rescan progress percentage. Between 0 and 1. + fn rescan_progress(&self) -> Option; + + /// Get the last block chain tip with a timestamp below this. Timestamp must be a valid block + /// timestamp. + fn block_before_date(&self, timestamp: u32) -> Option; } impl BitcoinInterface for d::BitcoinD { @@ -286,6 +300,24 @@ impl BitcoinInterface for d::BitcoinD { ), } } + + fn start_rescan(&self, desc: &descriptors::MultipathDescriptor, timestamp: u32) { + // FIXME: in theory i think this could potentially fail to actually start the rescan. + self.start_rescan(desc, timestamp); + } + + fn rescan_progress(&self) -> Option { + self.rescan_progress() + } + + fn block_before_date(&self, timestamp: u32) -> Option { + self.tip_before_timestamp(timestamp) + } + + fn tip_time(&self) -> u32 { + let tip = self.chain_tip(); + self.get_block_stats(tip.hash).time + } } // FIXME: do we need to repeat the entire trait implemenation? Isn't there a nicer way? @@ -342,6 +374,22 @@ impl BitcoinInterface for sync::Arc> fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), BitcoinError> { self.lock().unwrap().broadcast_tx(tx) } + + fn start_rescan(&self, desc: &descriptors::MultipathDescriptor, timestamp: u32) { + self.lock().unwrap().start_rescan(desc, timestamp) + } + + fn rescan_progress(&self) -> Option { + self.lock().unwrap().rescan_progress() + } + + fn block_before_date(&self, timestamp: u32) -> Option { + self.lock().unwrap().block_before_date(timestamp) + } + + fn tip_time(&self) -> u32 { + self.lock().unwrap().tip_time() + } } // FIXME: We could avoid this type (and all the conversions entailing allocations) if bitcoind diff --git a/src/testutils.rs b/src/testutils.rs index 6add2785..355e8bc3 100644 --- a/src/testutils.rs +++ b/src/testutils.rs @@ -74,6 +74,22 @@ impl BitcoinInterface for DummyBitcoind { fn broadcast_tx(&self, _: &bitcoin::Transaction) -> Result<(), BitcoinError> { todo!() } + + fn start_rescan(&self, _: &descriptors::MultipathDescriptor, _: u32) { + todo!() + } + + fn rescan_progress(&self) -> Option { + None + } + + fn block_before_date(&self, _: u32) -> Option { + todo!() + } + + fn tip_time(&self) -> u32 { + todo!() + } } pub struct DummyDb { From 7e83bfad55504e758e2380ba76e48ce7f868b837 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 18:16:55 +0100 Subject: [PATCH 07/20] db: the interface to store the state of an ongoing rescan We'll need to store in persistent storage if a rescan was requested by a user, and if so from what date. For the SQLite implementation we introduce a rescan_timestamp to the wallet table. --- src/database/mod.rs | 21 ++++++++++ src/database/sqlite/mod.rs | 77 ++++++++++++++++++++++++++++++++++- src/database/sqlite/schema.rs | 12 +++++- src/testutils.rs | 12 ++++++ 4 files changed, 120 insertions(+), 2 deletions(-) diff --git a/src/database/mod.rs b/src/database/mod.rs index 20795bb1..263f3442 100644 --- a/src/database/mod.rs +++ b/src/database/mod.rs @@ -53,6 +53,15 @@ pub trait DatabaseConnection { fn increment_change_index(&mut self, secp: &secp256k1::Secp256k1); + /// Get the timestamp at which to start rescaning from, if any. + fn rescan_timestamp(&mut self) -> Option; + + /// Set a timestamp at which to start rescaning the block chain from. + fn set_rescan(&mut self, timestamp: u32); + + /// Mark the rescan as complete. + fn complete_rescan(&mut self); + /// Get the derivation index for this address, as well as whether this address is change. fn derivation_index_by_address( &mut self, @@ -134,6 +143,18 @@ impl DatabaseConnection for SqliteConn { self.increment_change_index(secp) } + fn rescan_timestamp(&mut self) -> Option { + self.db_wallet().rescan_timestamp + } + + fn set_rescan(&mut self, timestamp: u32) { + self.set_wallet_rescan_timestamp(timestamp) + } + + fn complete_rescan(&mut self) { + self.complete_wallet_rescan() + } + fn coins(&mut self) -> HashMap { self.coins() .into_iter() diff --git a/src/database/sqlite/mod.rs b/src/database/sqlite/mod.rs index dc15827b..c942eef5 100644 --- a/src/database/sqlite/mod.rs +++ b/src/database/sqlite/mod.rs @@ -21,7 +21,7 @@ use crate::{ descriptors::MultipathDescriptor, }; -use std::{convert::TryInto, fmt, io, path}; +use std::{cmp, convert::TryInto, fmt, io, path}; use miniscript::bitcoin::{ self, consensus::encode, hashes::hex::ToHex, secp256k1, @@ -272,6 +272,43 @@ impl SqliteConn { .expect("Database must be available") } + pub fn set_wallet_rescan_timestamp(&mut self, timestamp: u32) { + db_exec(&mut self.conn, |db_tx| { + // NOTE: this will need to be updated if we ever implement multi-wallet support + db_tx + .execute( + "UPDATE wallets SET rescan_timestamp = (?1)", + rusqlite::params![timestamp], + ) + .map(|_| ()) + }) + .expect("Database must be available") + } + + /// Drop the rescan timestamp, and set it as the wallet creation timestamp if it + /// predates it. + /// + /// # Panics + /// - If called while rescan_timestamp is not set + pub fn complete_wallet_rescan(&mut self) { + let db_wallet = self.db_wallet(); + let new_timestamp = cmp::min( + db_wallet.rescan_timestamp.expect("Must be set"), + db_wallet.timestamp, + ); + + db_exec(&mut self.conn, |db_tx| { + // NOTE: this will need to be updated if we ever implement multi-wallet support + db_tx + .execute( + "UPDATE wallets SET timestamp = (?1), rescan_timestamp = NULL", + rusqlite::params![new_timestamp], + ) + .map(|_| ()) + }) + .expect("Database must be available"); + } + /// Get all the coins from DB. pub fn coins(&mut self) -> Vec { db_query( @@ -998,4 +1035,42 @@ mod tests { fs::remove_dir_all(&tmp_dir).unwrap(); } + + #[test] + fn db_rescan() { + let (tmp_dir, _, _, db) = dummy_db(); + + { + let mut conn = db.connection().unwrap(); + + // At first no rescan is ongoing + let dummy_timestamp = 1_001; + let db_wallet = conn.db_wallet(); + assert!(db_wallet.rescan_timestamp.is_none()); + assert!(db_wallet.timestamp > dummy_timestamp); + + // But if we set one there'll be + conn.set_wallet_rescan_timestamp(dummy_timestamp); + assert_eq!(conn.db_wallet().rescan_timestamp, Some(dummy_timestamp)); + + // Once it's done the rescan timestamp will be erased, and the + // wallet timestamp will be set to the dummy timestamp since it's + // lower. + conn.complete_wallet_rescan(); + let db_wallet = conn.db_wallet(); + assert!(db_wallet.rescan_timestamp.is_none()); + assert_eq!(db_wallet.timestamp, dummy_timestamp); + + // If we rescan from a later timestamp, we'll keep the existing + // wallet timestamp afterward. + conn.set_wallet_rescan_timestamp(dummy_timestamp + 1); + assert_eq!(conn.db_wallet().rescan_timestamp, Some(dummy_timestamp + 1)); + conn.complete_wallet_rescan(); + let db_wallet = conn.db_wallet(); + assert!(db_wallet.rescan_timestamp.is_none()); + assert_eq!(db_wallet.timestamp, dummy_timestamp); + } + + fs::remove_dir_all(&tmp_dir).unwrap(); + } } diff --git a/src/database/sqlite/schema.rs b/src/database/sqlite/schema.rs index 40398df7..a4a51feb 100644 --- a/src/database/sqlite/schema.rs +++ b/src/database/sqlite/schema.rs @@ -22,13 +22,19 @@ CREATE TABLE tip ( /* This stores metadata about our wallet. We only support single wallet for * now (and the foreseeable future). + * + * The 'timestamp' field is the creation date of the wallet. We guarantee to have seen all + * information related to our descriptor(s) that occured after this date. + * The optional 'rescan_timestamp' field is a the timestamp we need to rescan the chain + * for events related to our descriptor(s) from. */ CREATE TABLE wallets ( id INTEGER PRIMARY KEY NOT NULL, timestamp INTEGER NOT NULL, main_descriptor TEXT NOT NULL, deposit_derivation_index INTEGER NOT NULL, - change_derivation_index INTEGER NOT NULL + change_derivation_index INTEGER NOT NULL, + rescan_timestamp INTEGER ); /* Our (U)TxOs. @@ -109,6 +115,7 @@ pub struct DbWallet { pub main_descriptor: MultipathDescriptor, pub deposit_derivation_index: bip32::ChildNumber, pub change_derivation_index: bip32::ChildNumber, + pub rescan_timestamp: Option, } impl TryFrom<&rusqlite::Row<'_>> for DbWallet { @@ -127,12 +134,15 @@ impl TryFrom<&rusqlite::Row<'_>> for DbWallet { let der_idx: u32 = row.get(4)?; let change_derivation_index = bip32::ChildNumber::from(der_idx); + let rescan_timestamp = row.get(5)?; + Ok(DbWallet { id, timestamp, main_descriptor, deposit_derivation_index, change_derivation_index, + rescan_timestamp, }) } } diff --git a/src/testutils.rs b/src/testutils.rs index 355e8bc3..6201f32b 100644 --- a/src/testutils.rs +++ b/src/testutils.rs @@ -266,6 +266,18 @@ impl DatabaseConnection for DummyDbConn { fn rollback_tip(&mut self, _: &BlockChainTip) { todo!() } + + fn rescan_timestamp(&mut self) -> Option { + None + } + + fn set_rescan(&mut self, _: u32) { + todo!() + } + + fn complete_rescan(&mut self) { + todo!() + } } pub struct DummyMinisafe { From 7866ff46cfcf02f75f0d5fd996434ef647940882 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 18:21:09 +0100 Subject: [PATCH 08/20] commands: add a new 'startrescan' command --- doc/API.md | 17 +++++++++++++++++ src/commands/mod.rs | 30 ++++++++++++++++++++++++++++++ src/jsonrpc/api.rs | 18 ++++++++++++++++++ src/jsonrpc/mod.rs | 4 +++- 4 files changed, 68 insertions(+), 1 deletion(-) diff --git a/doc/API.md b/doc/API.md index 75b18a4a..0ab178fe 100644 --- a/doc/API.md +++ b/doc/API.md @@ -13,6 +13,7 @@ Commands must be sent as valid JSONRPC 2.0 requests, ending with a `\n`. | [`listspendtxs`](#listspendtxs) | List all stored Spend transactions | | [`delspendtx`](#delspendtx) | Delete a stored Spend transaction | | [`broadcastspend`](#broadcastspend) | Finalize a stored Spend PSBT, and broadcast it | +| [`startrescan`](#startrescan) | Start rescanning the block chain from a given date | # Reference @@ -199,3 +200,19 @@ This command does not return anything for now. | Field | Type | Description | | -------------- | --------- | ---------------------------------------------------- | + + +### `startrescan` + +#### Request + +| Field | Type | Description | +| ------------ | ------ | ------------------------------------------------------ | +| `timestamp` | int | Date to start rescanning from, as a UNIX timestamp | + +#### Response + +This command does not return anything for now. + +| Field | Type | Description | +| -------------- | --------- | ---------------------------------------------------- | diff --git a/src/commands/mod.rs b/src/commands/mod.rs index 4c189e23..38b93b96 100644 --- a/src/commands/mod.rs +++ b/src/commands/mod.rs @@ -38,6 +38,9 @@ const MAX_FEE: u64 = bitcoin::blockdata::constants::COIN_VALUE; // Assume that paying more than 1000sat/vb in feerate is a bug. const MAX_FEERATE: u64 = bitcoin::blockdata::constants::COIN_VALUE; +// Timestamp in the header of the genesis block. Used for sanity checks. +const MAINNET_GENESIS_TIME: u32 = 1231006505; + #[derive(Debug, Clone, PartialEq, Eq)] pub enum CommandError { NoOutpoint, @@ -56,6 +59,8 @@ pub enum CommandError { // FIXME: when upgrading Miniscript put the actual error there SpendFinalization(String), TxBroadcast(String), + AlreadyRescanning, + InsaneRescanTimestamp(u32), } impl fmt::Display for CommandError { @@ -82,6 +87,11 @@ impl fmt::Display for CommandError { write!(f, "Failed to finalize the spend transaction PSBT: '{}'.", e) } Self::TxBroadcast(e) => write!(f, "Failed to broadcast transaction: '{}'.", e), + Self::AlreadyRescanning => write!( + f, + "There is already a rescan ongoing. Please wait for it to complete first." + ), + Self::InsaneRescanTimestamp(t) => write!(f, "Insane timestamp '{}'.", t), } } } @@ -490,6 +500,26 @@ impl DaemonControl { Err(BitcoinError::Broadcast(e)) => Err(CommandError::TxBroadcast(e)), } } + + /// Trigger a rescan of the block chain for transactions involving our main descriptor between + /// the given date and the current tip. + /// The date must be after the genesis block time and before the current tip blocktime. + pub fn start_rescan(&self, timestamp: u32) -> Result<(), CommandError> { + let mut db_conn = self.db.connection(); + + if db_conn.rescan_timestamp().is_some() { + return Err(CommandError::AlreadyRescanning); + } + if timestamp < MAINNET_GENESIS_TIME || timestamp >= self.bitcoin.tip_time() { + return Err(CommandError::InsaneRescanTimestamp(timestamp)); + } + + self.bitcoin + .start_rescan(&self.config.main_descriptor, timestamp); + db_conn.set_rescan(timestamp); + + Ok(()) + } } #[derive(Debug, Clone, Serialize, Deserialize)] diff --git a/src/jsonrpc/api.rs b/src/jsonrpc/api.rs index 0d034643..6876ab8d 100644 --- a/src/jsonrpc/api.rs +++ b/src/jsonrpc/api.rs @@ -84,6 +84,18 @@ fn broadcast_spend(control: &DaemonControl, params: Params) -> Result Result { + let timestamp: u32 = params + .get(0, "timestamp") + .ok_or_else(|| Error::invalid_params("Missing 'timestamp' parameter."))? + .as_u64() + .and_then(|t| t.try_into().ok()) + .ok_or_else(|| Error::invalid_params("Invalid 'timestamp' parameter."))?; + control.start_rescan(timestamp)?; + + Ok(serde_json::json!({})) +} + /// Handle an incoming JSONRPC2 request. pub fn handle_request(control: &DaemonControl, req: Request) -> Result { let result = match req.method.as_str() { @@ -111,6 +123,12 @@ pub fn handle_request(control: &DaemonControl, req: Request) -> Result serde_json::json!(&control.get_new_address()), "listcoins" => serde_json::json!(&control.list_coins()), "listspendtxs" => serde_json::json!(&control.list_spend()), + "startrescan" => { + let params = req + .params + .ok_or_else(|| Error::invalid_params("Missing 'timestamp' parameter."))?; + start_rescan(control, params)? + } "stop" => serde_json::json!({}), "updatespend" => { let params = req diff --git a/src/jsonrpc/mod.rs b/src/jsonrpc/mod.rs index db721891..595dce33 100644 --- a/src/jsonrpc/mod.rs +++ b/src/jsonrpc/mod.rs @@ -159,7 +159,9 @@ impl From for Error { | commands::CommandError::InvalidOutputValue(..) | commands::CommandError::InsufficientFunds(..) | commands::CommandError::UnknownSpend(..) - | commands::CommandError::SpendFinalization(..) => { + | commands::CommandError::SpendFinalization(..) + | commands::CommandError::InsaneRescanTimestamp(..) + | commands::CommandError::AlreadyRescanning => { Error::new(ErrorCode::InvalidParams, e.to_string()) } commands::CommandError::SanityCheckFailure(_) => { From 073cdd0a89c8688b2cdad73666b71a79d9f81ae1 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 18:21:39 +0100 Subject: [PATCH 09/20] commands: add a 'rescan_progress' field to 'getinfo' We make sure to return a value as long as it was not wiped from database, that's useful in functional tests. --- doc/API.md | 15 ++++++++------- src/commands/mod.rs | 6 ++++++ 2 files changed, 14 insertions(+), 7 deletions(-) diff --git a/doc/API.md b/doc/API.md index 0ab178fe..3863a463 100644 --- a/doc/API.md +++ b/doc/API.md @@ -43,13 +43,14 @@ This command does not take any parameter for now. #### Response -| Field | Type | Description | -| -------------------- | ------- | -------------------------------------------------------------------------------------------- | -| `version` | string | Version following the [SimVer](http://www.simver.org/) format | -| `network` | string | Answer can be `mainnet`, `testnet`, `regtest` | -| `blockheight` | integer | The block height we are synced at. | -| `sync` | float | The synchronization progress as percentage (`0 < sync < 1`) | -| `descriptors` | object | Object with the name of the descriptor as key and the descriptor string as value | +| Field | Type | Description | +| -------------------- | ------- | -------------------------------------------------------------------------------------------------- | +| `version` | string | Version following the [SimVer](http://www.simver.org/) format | +| `network` | string | Answer can be `mainnet`, `testnet`, `regtest` | +| `blockheight` | integer | The block height we are synced at. | +| `sync` | float | The synchronization progress as percentage (`0 < sync < 1`) | +| `descriptors` | object | Object with the name of the descriptor as key and the descriptor string as value | +| `rescan_progress` | float or null | Progress of an ongoing rescan as a percentage (between 0 and 1) if there is any | ### `getnewaddress` diff --git a/src/commands/mod.rs b/src/commands/mod.rs index 38b93b96..9a1d44c2 100644 --- a/src/commands/mod.rs +++ b/src/commands/mod.rs @@ -196,6 +196,9 @@ impl DaemonControl { let mut db_conn = self.db.connection(); let blockheight = db_conn.chain_tip().map(|tip| tip.height).unwrap_or(0); + let rescan_progress = db_conn + .rescan_timestamp() + .map(|_| self.bitcoin.rescan_progress().unwrap_or(1.0)); GetInfoResult { version: VERSION.to_string(), network: self.config.bitcoin_config.network, @@ -204,6 +207,7 @@ impl DaemonControl { descriptors: GetInfoDescriptors { main: self.config.main_descriptor.clone(), }, + rescan_progress, } } @@ -535,6 +539,8 @@ pub struct GetInfoResult { pub blockheight: i32, pub sync: f64, pub descriptors: GetInfoDescriptors, + /// The progress as a percentage (between 0 and 1) of an ongoing rescan if there is any + pub rescan_progress: Option, } #[derive(Debug, Clone, Serialize, Deserialize)] From 925df283a62af32d816bcf2e0b2d20c7f08a3a31 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 18:23:13 +0100 Subject: [PATCH 10/20] bitcoin: check for ongoing rescans in the poller Once the backend is done rescanning, we rollback our state down to the rescan depth in order to scan for transactions from there. --- src/bitcoin/poller/looper.rs | 49 ++++++++++++++++++++++++++++++++++++ 1 file changed, 49 insertions(+) diff --git a/src/bitcoin/poller/looper.rs b/src/bitcoin/poller/looper.rs index 77653a80..8aa14101 100644 --- a/src/bitcoin/poller/looper.rs +++ b/src/bitcoin/poller/looper.rs @@ -212,6 +212,54 @@ fn updates( log::debug!("Updates done."); } +// Check if there is any rescan of the backend ongoing or one that just finished. +fn rescan_check( + bit: &impl BitcoinInterface, + db: &impl DatabaseInterface, + descs: &[descriptors::InheritanceDescriptor], +) { + log::debug!("Checking the state of an ongoing rescan if there is any"); + let mut db_conn = db.connection(); + + // Check if there is an ongoing rescan. If there isn't and we previously asked for a rescan of + // the backend, we treat it as completed. + // Upon completion of the rescan from the given timestamp on the backend, we rollback our state + // down to the height before this timestamp to rescan everything that happened since then. + let rescan_timestamp = db_conn.rescan_timestamp(); + if let Some(progress) = bit.rescan_progress() { + log::info!("Rescan progress: {:.2}%.", progress * 100.0); + if rescan_timestamp.is_none() { + log::warn!("Backend is rescanning but we didn't ask for it."); + } + } else if let Some(timestamp) = rescan_timestamp { + log::info!("Rescan completed on the backend."); + // TODO: we could check if the timestamp of the descriptors in the Bitcoin backend are + // truly at the rescan timestamp, and trigger a rescan otherwise. Note however it would be + // no use for the bitcoind implementation of the backend, since bitcoind will always set + // the timestamp of the descriptors in the wallet first (and therefore consider it as + // rescanned from this height even if it aborts the rescan by being stopped). + let rescan_tip = match bit.block_before_date(timestamp) { + Some(block) => block, + None => { + log::error!( + "Could not retrieve block height for timestamp '{}'", + timestamp + ); + return; + } + }; + db_conn.rollback_tip(&rescan_tip); + db_conn.complete_rescan(); + log::info!( + "Rolling back our internal tip to '{}' to update our internal state with past transactions.", + rescan_tip + ); + updates(bit, db, descs) + } else { + log::debug!("No ongoing rescan."); + } +} + // If the database chain tip is NULL (first startup), initialize it. fn maybe_initialize_tip(bit: &impl BitcoinInterface, db: &impl DatabaseInterface) { let mut db_conn = db.connection(); @@ -269,5 +317,6 @@ pub fn looper( } updates(&bit, &db, &descs); + rescan_check(&bit, &db, &descs); } } From 8a22f5e8c944447572bad60fa7e187058483ed47 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Nov 2022 18:25:33 +0100 Subject: [PATCH 11/20] qa: functional tests for block chain rescans --- tests/test_chain.py | 90 +++++++++++++++++++++++++++++++ tests/test_framework/bitcoind.py | 17 +++--- tests/test_framework/minisafed.py | 15 ++++++ tests/test_rpc.py | 89 ++++++++++++++++++++++++++++++ 4 files changed, 205 insertions(+), 6 deletions(-) diff --git a/tests/test_chain.py b/tests/test_chain.py index 96eb06ca..e23987d8 100644 --- a/tests/test_chain.py +++ b/tests/test_chain.py @@ -1,3 +1,5 @@ +import time + from fixtures import * from test_framework.utils import wait_for, get_txid, spend_coins @@ -166,3 +168,91 @@ def test_reorg_status_recovery(minisafed, bitcoind): new_coin_b = get_coin(minisafed, coin_b["outpoint"]) coin_b["spend_info"]["height"] = initial_height assert new_coin_b == coin_b + + +def test_rescan_edge_cases(minisafed, bitcoind): + """Test some specific cases that could arise when rescanning the chain.""" + initial_tip = bitcoind.rpc.getblockheader(bitcoind.rpc.getbestblockhash()) + + # Some helpers + list_coins = lambda: minisafed.rpc.listcoins()["coins"] + sorted_coins = lambda: sorted(list_coins(), key=lambda c: c["outpoint"]) + wait_synced = lambda: wait_for( + lambda: minisafed.rpc.getinfo()["blockheight"] == bitcoind.rpc.getblockcount() + ) + + def reorg_shift(height, txs): + """Remine the chain from given height, shifting the txs by one block.""" + delta = bitcoind.rpc.getblockcount() - height + 1 + assert delta > 2 + h = bitcoind.rpc.getblockhash(initial_tip["height"]) + bitcoind.rpc.invalidateblock(h) + bitcoind.generate_block(1) + for tx in txs: + bitcoind.rpc.sendrawtransaction(tx) + bitcoind.generate_block(delta - 1, wait_for_mempool=len(txs)) + + # Create 3 coins and spend 2 of them. Keep the transactions in memory to + # rebroadcast them on reorgs. + txs = [] + for _ in range(3): + addr = minisafed.rpc.getnewaddress()["address"] + amount = 0.356 + txid = bitcoind.rpc.sendtoaddress(addr, amount) + txs.append(bitcoind.rpc.gettransaction(txid)["hex"]) + wait_for(lambda: len(list_coins()) == 3) + txs.append(spend_coins(minisafed, bitcoind, list_coins()[:2])) + bitcoind.generate_block(1, wait_for_mempool=4) + wait_synced() + + # Advance the blocktime by >2h in the future for the importdescriptors rescan + added_time = 60 * 60 * 3 + bitcoind.rpc.setmocktime(initial_tip["time"] + added_time) + bitcoind.generate_block(12) + + # Lose our state + coins_before = sorted_coins() + outpoints_before = set(c["outpoint"] for c in coins_before) + bitcoind.generate_block(1) + minisafed.restart_fresh(bitcoind) + assert len(list_coins()) == 0 + + # We can be stopped while we are rescanning + minisafed.rpc.startrescan(initial_tip["time"]) + minisafed.stop() + minisafed.start() + wait_for(lambda: minisafed.rpc.getinfo()["rescan_progress"] is None) + assert coins_before == sorted_coins() + + # Lose our state again + bitcoind.generate_block(1) + minisafed.restart_fresh(bitcoind) + wait_for(lambda: minisafed.rpc.getinfo()["rescan_progress"] is None) + assert len(list_coins()) == 0 + + # There can be a reorg when we start rescanning + reorg_shift(initial_tip["height"], txs) + minisafed.rpc.startrescan(initial_tip["time"]) + wait_synced() + wait_for(lambda: minisafed.rpc.getinfo()["rescan_progress"] is None) + assert len(sorted_coins()) == len(coins_before) + assert all(c["outpoint"] in outpoints_before for c in list_coins()) + + # Advance the blocktime again + bitcoind.rpc.setmocktime(initial_tip["time"] + added_time * 2) + bitcoind.generate_block(12) + + # Lose our state again + bitcoind.generate_block(1) + minisafed.restart_fresh(bitcoind) + wait_synced() + wait_for(lambda: minisafed.rpc.getinfo()["rescan_progress"] is None) + assert len(list_coins()) == 0 + + # We can be rescanning when a reorg happens + minisafed.rpc.startrescan(initial_tip["time"]) + reorg_shift(initial_tip["height"] + 1, txs) + wait_synced() + wait_for(lambda: minisafed.rpc.getinfo()["rescan_progress"] is None) + assert len(sorted_coins()) == len(coins_before) + assert all(c["outpoint"] in outpoints_before for c in list_coins()) diff --git a/tests/test_framework/bitcoind.py b/tests/test_framework/bitcoind.py index 0bb82136..fd1588bf 100644 --- a/tests/test_framework/bitcoind.py +++ b/tests/test_framework/bitcoind.py @@ -8,19 +8,19 @@ from test_framework.utils import TailableProc, wait_for, TIMEOUT, BITCOIND_PATH, class BitcoindRpcInterface: - def __init__(self, data_dir, network, rpc_port): + def __init__(self, data_dir, network, rpc_port, wallet=None): self.cookie_path = os.path.join(data_dir, network, ".cookie") self.rpc_port = rpc_port - self.wallet_name = "minisafed-tests" + self.wallet_name = wallet def __getattr__(self, name): assert not (name.startswith("__") and name.endswith("__")), "Python internals" with open(self.cookie_path) as fd: authpair = fd.read() - service_url = ( - f"http://{authpair}@localhost:{self.rpc_port}/wallet/{self.wallet_name}" - ) + service_url = f"http://{authpair}@localhost:{self.rpc_port}" + if self.wallet_name is not None: + service_url += f"/wallet/{self.wallet_name}" proxy = AuthServiceProxy(service_url, name) def f(*args): @@ -68,7 +68,12 @@ class Bitcoind(TailableProc): for k, v in bitcoind_conf.items(): f.write(f"{k}={v}\n") - self.rpc = BitcoindRpcInterface(bitcoin_dir, "regtest", rpcport) + # An RPC interface with our internal wallet, and an RPC interface with no + # wallet to be able to call 'unloadwallet' on any wallet. + self.rpc = BitcoindRpcInterface( + bitcoin_dir, "regtest", rpcport, wallet="minisafed-tests" + ) + self.node_rpc = BitcoindRpcInterface(bitcoin_dir, "regtest", rpcport) def start(self): TailableProc.start(self) diff --git a/tests/test_framework/minisafed.py b/tests/test_framework/minisafed.py index 085e07e6..8cfc137f 100644 --- a/tests/test_framework/minisafed.py +++ b/tests/test_framework/minisafed.py @@ -1,5 +1,6 @@ import logging import os +import shutil from bip32.utils import coincurve from bip380.descriptors import Descriptor @@ -10,6 +11,7 @@ from test_framework.utils import ( VERBOSE, LOG_LEVEL, MINISAFED_PATH, + wait_for, ) from test_framework.serializations import ( PSBT, @@ -34,6 +36,7 @@ class Minisafed(TailableProc): ): TailableProc.__init__(self, datadir, verbose=VERBOSE) + self.datadir = datadir self.prefix = os.path.split(datadir)[-1] self.owner_hd = owner_hd @@ -145,6 +148,18 @@ class Minisafed(TailableProc): return psbt + def restart_fresh(self, bitcoind): + """Delete the internal state of the wallet and restart.""" + self.stop() + dir_path = os.path.join(self.datadir, "regtest") + shutil.rmtree(dir_path) + wallet_path = os.path.join(dir_path, "minisafed_watchonly_wallet") + bitcoind.node_rpc.unloadwallet(wallet_path) + self.start() + wait_for( + lambda: self.rpc.getinfo()["blockheight"] == bitcoind.rpc.getblockcount() + ) + def start(self): TailableProc.start(self) self.wait_for_logs( diff --git a/tests/test_rpc.py b/tests/test_rpc.py index b8044aeb..2bc0aa73 100644 --- a/tests/test_rpc.py +++ b/tests/test_rpc.py @@ -1,4 +1,8 @@ +import os import pytest +import random +import shutil +import time from fixtures import * from test_framework.serializations import PSBT, PSBT_IN_PARTIAL_SIG @@ -12,6 +16,7 @@ def test_getinfo(minisafed): wait_for(lambda: res["blockheight"] == 101) assert res["sync"] == 1.0 assert "main" in res["descriptors"] + assert res["rescan_progress"] is None def test_getaddress(minisafed): @@ -253,3 +258,87 @@ def test_broadcast_spend(minisafed, bitcoind): # Now we've signed and stored it, the daemon will take care of finalizing # the PSBT before broadcasting the transaction. minisafed.rpc.broadcastspend(txid) + + +def test_start_rescan(minisafed, bitcoind): + """Test we successfully retrieve all our transactions after losing state by rescanning.""" + initial_timestamp = int(time.time()) + + # Some utility functions to DRY + list_coins = lambda: minisafed.rpc.listcoins()["coins"] + unspent_coins = lambda: ( + c for c in minisafed.rpc.listcoins()["coins"] if c["spend_info"] is None + ) + sorted_coins = lambda: sorted(list_coins(), key=lambda c: c["outpoint"]) + + def all_spent(coins): + unspent = set(c["outpoint"] for c in unspent_coins()) + for c in coins: + if c["outpoint"] in unspent: + return False + return True + + # We can rescan from one second before the tip timestamp, that's almost a no-op. + tip_timestamp = bitcoind.rpc.getblockheader(bitcoind.rpc.getbestblockhash())["time"] + minisafed.rpc.startrescan(tip_timestamp - 1) + wait_for(lambda: minisafed.rpc.getinfo()["rescan_progress"] is None) + # We can't rescan from an insane timestamp though. + with pytest.raises(RpcError, match="Insane timestamp.*"): + minisafed.rpc.startrescan(tip_timestamp) + assert minisafed.rpc.getinfo()["rescan_progress"] is None + future_timestamp = tip_timestamp + 60 * 60 + with pytest.raises(RpcError, match="Insane timestamp.*"): + minisafed.rpc.startrescan(future_timestamp) + assert minisafed.rpc.getinfo()["rescan_progress"] is None + prebitcoin_timestamp = 1231006505 - 1 + with pytest.raises(RpcError, match="Insane timestamp."): + minisafed.rpc.startrescan(prebitcoin_timestamp) + assert minisafed.rpc.getinfo()["rescan_progress"] is None + + # First, get some coins + for _ in range(10): + addr = minisafed.rpc.getnewaddress()["address"] + amount = random.randint(1, COIN * 10) / COIN + txid = bitcoind.rpc.sendtoaddress(addr, amount) + bitcoind.generate_block(random.randint(1, 10), wait_for_mempool=txid) + wait_for(lambda: len(list_coins()) == 10) + + # Then simulate some regular activity (spend and receive) + # TODO: instead of having randomness we should lay down all different cases (with or + # without change, single or multiple inputs, sending externally or to self). + for _ in range(5): + addr = minisafed.rpc.getnewaddress()["address"] + amount = random.randint(1, COIN * 10) / COIN + txid = bitcoind.rpc.sendtoaddress(addr, amount) + avail = list(unspent_coins()) + to_spend = random.sample(avail, random.randint(1, len(avail))) + spend_coins(minisafed, bitcoind, to_spend) + bitcoind.generate_block(random.randint(1, 5), wait_for_mempool=2) + wait_for(lambda: all_spent(to_spend)) + wait_for( + lambda: minisafed.rpc.getinfo()["blockheight"] == bitcoind.rpc.getblockcount() + ) + + # Move time forward one day as bitcoind will rescan the last 2 hours of block upon + # importing a descriptor. + now = int(time.time()) + added_time = 60 * 60 * 24 + bitcoind.rpc.setmocktime(now + added_time) + bitcoind.generate_block(10) + + # Now delete the wallet state. When starting up we'll re-create a fresh database + # and watchonly wallet. Those won't be aware of past coins for the configured + # descriptor. + coins_before = sorted_coins() + minisafed.restart_fresh(bitcoind) + assert len(list_coins()) == 0 + + # Once the rescan is done, we must have detected all previous transactions. + minisafed.rpc.startrescan(initial_timestamp) + rescan_progress = minisafed.rpc.getinfo()["rescan_progress"] + assert rescan_progress is None or 0 <= rescan_progress <= 1 + wait_for(lambda: minisafed.rpc.getinfo()["rescan_progress"] is None) + wait_for( + lambda: minisafed.rpc.getinfo()["blockheight"] == bitcoind.rpc.getblockcount() + ) + assert coins_before == sorted_coins() From 4a7fd1af2999622af7e6421c0bea611688150cae Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Sat, 12 Nov 2022 15:38:59 +0100 Subject: [PATCH 12/20] commands: check if the Bitcoin backend is already rescanning This is racy, but good enough for now. --- src/commands/mod.rs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/commands/mod.rs b/src/commands/mod.rs index 9a1d44c2..15323fcb 100644 --- a/src/commands/mod.rs +++ b/src/commands/mod.rs @@ -511,13 +511,16 @@ impl DaemonControl { pub fn start_rescan(&self, timestamp: u32) -> Result<(), CommandError> { let mut db_conn = self.db.connection(); - if db_conn.rescan_timestamp().is_some() { - return Err(CommandError::AlreadyRescanning); - } if timestamp < MAINNET_GENESIS_TIME || timestamp >= self.bitcoin.tip_time() { return Err(CommandError::InsaneRescanTimestamp(timestamp)); } + if db_conn.rescan_timestamp().is_some() || self.bitcoin.rescan_progress().is_some() { + return Err(CommandError::AlreadyRescanning); + } + // TODO: there is a race with the above check for whether the backend is already + // rescanning. This could make us crash with the bitcoind backend if someone triggered a + // rescan of the wallet just after we checked above and did now. self.bitcoin .start_rescan(&self.config.main_descriptor, timestamp); db_conn.set_rescan(timestamp); From ff753fecca5c1c77c44a4627a565e580aefc9446 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 09:07:41 +0100 Subject: [PATCH 13/20] bitcoind: get more info from 'listdescriptors' We'll need the range for the rescan, as a descriptor must be reimported with a range larger than the initial descriptor --- src/bitcoin/d/mod.rs | 31 ++++++++++++++++++++++++++----- 1 file changed, 26 insertions(+), 5 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index 7dea4d14..9c41a84d 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -437,21 +437,31 @@ impl BitcoinD { } } - fn list_descriptors(&self) -> Vec { + fn list_descriptors(&self) -> Vec { self.make_wallet_request("listdescriptors", &[]) .get("descriptors") .and_then(Json::as_array) .expect("Missing or invalid 'descriptors' field in 'listdescriptors' response") .iter() .map(|elem| { - elem.get("desc") + let desc = elem + .get("desc") .and_then(Json::as_str) .expect( "Missing or invalid 'desc' field in 'listdescriptors' response's entries", ) - .to_string() + .to_string(); + let range = elem.get("range").and_then(Json::as_array).map(|a| { + a.iter() + .map(|e| e.as_u64().expect("Invalid range index") as u32) + .collect::>() + .try_into() + .expect("Range is always an array of size 2") + }); + + ListDescEntry { desc, range } }) - .collect::>() + .collect() } /// Create the watchonly wallet on bitcoind, and import it the main descriptor. @@ -535,7 +545,11 @@ impl BitcoinD { // Check our main descriptor is imported in this wallet. let receive_desc = main_descriptor.receive_descriptor(); let change_desc = main_descriptor.change_descriptor(); - let desc_list = self.list_descriptors(); + let desc_list: Vec = self + .list_descriptors() + .into_iter() + .map(|entry| entry.desc) + .collect(); if !desc_list.contains(&receive_desc.to_string()) || !desc_list.contains(&change_desc.to_string()) { @@ -809,6 +823,13 @@ fn roundup_progress(progress: f64) -> f64 { } } +/// An entry in the 'listdescriptors' result. +#[derive(Debug, Clone)] +pub struct ListDescEntry { + pub desc: String, + pub range: Option<[u32; 2]>, +} + /// A 'received' entry in the 'listsinceblock' result. #[derive(Debug, Clone)] pub struct LSBlockEntry { From 9b253e7ea71e3da38922e35a9fdc182e85a15bcd Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 09:09:22 +0100 Subject: [PATCH 14/20] bitcoind: rescan with a range, handle spurious error when rescanning Give the range to 'importdescriptors' when re-importing a descriptor for rescanning. This is because the range must include the range of the descriptor being updated. Secondly, it is possible that the combination of our timeout-to-1s hack and our retry logic trigger an edge case: we would retry after successfully triggering a rescan, and therefore panic on a "a rescan is already ongoing" error. Instead check before starting that we aren't rescanning already, and assume that such an error after triggering the rescan is because we succeeded. That's racy but only reasonably so (as long as we don't crash, which isn't the case here). --- src/bitcoin/d/mod.rs | 96 ++++++++++++++++++++++++++++++++------------ 1 file changed, 70 insertions(+), 26 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index 9c41a84d..0827deb5 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -5,7 +5,7 @@ mod utils; use crate::{bitcoin::BlockChainTip, config, descriptors::MultipathDescriptor}; use utils::block_before_date; -use std::{collections::HashSet, convert::TryInto, fs, io, str::FromStr, time::Duration}; +use std::{cmp, collections::HashSet, convert::TryInto, fs, io, str::FromStr, time::Duration}; use jsonrpc::{ arg, @@ -288,11 +288,21 @@ impl BitcoinD { } // Make a request for which you don't expect a response. This is achieved by setting a very low - // timeout on the connection, and will panic on any other error than a timeout. - fn make_noreply_request(&self, method: &str, params: &[Box]) { - if let Err(e) = self.make_request(&self.sendonly_client, method, params) { - if !e.is_timeout() { - panic!("{}", e); + // timeout on the connection. + fn make_noreply_request( + &self, + method: &str, + params: &[Box], + ) -> Result<(), BitcoindError> { + match self.make_request(&self.sendonly_client, method, params) { + Ok(_) => Ok(()), + Err(e) => { + // A timeout error is expected, as that's our workaround to avoid blocking + if e.is_timeout() { + Ok(()) + } else { + Err(e) + } } } } @@ -393,34 +403,18 @@ impl BitcoinD { } // Import the receive and change descriptors from the multipath descriptor to bitcoind. - // An optional timestamp may be given to rescan the chain from this date for this descriptor. - fn import_descriptor( - &self, - desc: &MultipathDescriptor, - timestamp: Option, - ) -> Option { + fn import_descriptor(&self, desc: &MultipathDescriptor) -> Option { let descriptors = [desc.receive_descriptor(), desc.change_descriptor()] .iter() .map(|desc| { serde_json::json!({ "desc": desc.to_string(), - "timestamp": timestamp.map(Json::from).unwrap_or_else(|| "now".into()), + "timestamp": "now", "active": false, }) }) .collect(); - // If this will trigger a rescan, do not wait for the response. - if timestamp.is_some() { - // TODO: should we check there was not timeout when writing the request on the - // TcpStream in the SimpleHttpTransport implem? - // NOTE: if the rescan gets aborted through the 'abortrescan' RPC we won't see the - // error and bitcoind will keep the new timestamps for the descriptors as if it had - // successfully rescanned them. - self.make_noreply_request("importdescriptors", ¶ms!(Json::Array(descriptors))); - return None; - } - let res = self.make_wallet_request("importdescriptors", ¶ms!(Json::Array(descriptors))); let all_succeeded = res .as_array() @@ -486,7 +480,7 @@ impl BitcoinD { if let Some(err) = self.create_wallet(self.watchonly_wallet_path.clone()) { return Err(BitcoindError::WalletCreation(err)); } - if let Some(err) = self.import_descriptor(main_descriptor, None) { + if let Some(err) = self.import_descriptor(main_descriptor) { return Err(BitcoindError::DescriptorImport(err)); } @@ -787,7 +781,57 @@ impl BitcoinD { } pub fn start_rescan(&self, desc: &MultipathDescriptor, timestamp: u32) { - self.import_descriptor(desc, Some(timestamp)); + // The wallet must not be already rescanning + // FIXME: don't assert, propagate an error instead. + assert!(self.rescan_progress().is_none()); + + // Re-import the receive and change descriptors to the watchonly wallet for the purpose of + // rescanning. + // The range of the newly imported descriptors supposed to update the existing ones must + // have a range inclusive of the existing ones. We always use 0 as the initial index so + // this is just determining the maximum index to use. + let max_range = self + .list_descriptors() + .into_iter() + // 1_000 is bitcoind's default and what we use at initial import. + .fold(1_000, |range, entry| { + cmp::max(range, entry.range.map(|r| r[1]).unwrap_or(0)) + }); + let descriptors = [desc.receive_descriptor(), desc.change_descriptor()] + .iter() + .map(|desc| { + serde_json::json!({ + "desc": desc.to_string(), + "timestamp": timestamp, + "active": false, + "range": max_range, + }) + }) + .collect(); + + // TODO: should we check there was not timeout when writing the request on the + // TcpStream in the SimpleHttpTransport implem? + // NOTE: if the rescan gets aborted through the 'abortrescan' RPC we won't see the + // error and bitcoind will keep the new timestamps for the descriptors as if it had + // successfully rescanned them. + match self.make_noreply_request("importdescriptors", ¶ms!(Json::Array(descriptors))) { + Ok(()) => {} + Err(e) => { + // We checked at the beginning it was not already rescanning. If we get an error + // because of that it's just a spurious error from calling it multiple times in the + // retry logic. + if !e.to_string().contains("is currently rescanning.") { + // However, if it's not an error because we triggered it twice due to a + // flickering connection fail as it shouldn't happen. + // TODO: propagate the error back to the RPC command. There are too many + // reasons this could fail that we shouldn't be crashing for that. + panic!( + "Unexpected error when starting rescan on bitcoind wallet: {}", + e + ); + } + } + } } /// Get the progress of the ongoing rescan, if there is any. From 85cd261fcd50e87ad8c3b6a5443e7e38266ff655 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 09:37:13 +0100 Subject: [PATCH 15/20] bitcoin: remove the BitcoinError enum, use String as error instead It looks like we'd end up only using variants that contain a String, for little benefit. Cut down on complexity for now. --- src/bitcoin/mod.rs | 28 +++++----------------------- src/commands/mod.rs | 9 ++++----- src/testutils.rs | 4 ++-- 3 files changed, 11 insertions(+), 30 deletions(-) diff --git a/src/bitcoin/mod.rs b/src/bitcoin/mod.rs index d54279b6..a6531f34 100644 --- a/src/bitcoin/mod.rs +++ b/src/bitcoin/mod.rs @@ -9,28 +9,10 @@ use crate::{ descriptors, }; -use std::{collections::HashMap, error, fmt, sync}; +use std::{collections::HashMap, fmt, sync}; use miniscript::bitcoin; -/// Error occuring when querying our Bitcoin backend. -#[derive(Debug, Clone, PartialEq, Eq)] -pub enum BitcoinError { - Broadcast(String), -} - -impl fmt::Display for BitcoinError { - fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - match self { - BitcoinError::Broadcast(reason) => { - write!(f, "Failed to broadcast transaction: '{}'", reason) - } - } - } -} - -impl error::Error for BitcoinError {} - /// Information about the best block in the chain #[derive(Debug, Clone, Eq, PartialEq, Copy)] pub struct BlockChainTip { @@ -90,7 +72,7 @@ pub trait BitcoinInterface: Send { fn common_ancestor(&self, tip: &BlockChainTip) -> Option; /// Broadcast this transaction to the Bitcoin P2P network - fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), BitcoinError>; + fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), String>; /// Trigger a rescan of the block chain for transactions related to this descriptor since /// the given date. @@ -289,10 +271,10 @@ impl BitcoinInterface for d::BitcoinD { Some(ancestor) } - fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), BitcoinError> { + fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), String> { match self.broadcast_tx(tx) { Ok(()) => Ok(()), - Err(BitcoindError::Server(e)) => Err(BitcoinError::Broadcast(e.to_string())), + Err(BitcoindError::Server(e)) => Err(e.to_string()), // We assume the Bitcoin backend doesn't fail, so it must be a JSONRPC error. Err(e) => panic!( "Unexpected Bitcoin error when broadcast transaction: '{}'.", @@ -371,7 +353,7 @@ impl BitcoinInterface for sync::Arc> self.lock().unwrap().common_ancestor(tip) } - fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), BitcoinError> { + fn broadcast_tx(&self, tx: &bitcoin::Transaction) -> Result<(), String> { self.lock().unwrap().broadcast_tx(tx) } diff --git a/src/commands/mod.rs b/src/commands/mod.rs index 15323fcb..48762a64 100644 --- a/src/commands/mod.rs +++ b/src/commands/mod.rs @@ -5,7 +5,7 @@ mod utils; use crate::{ - bitcoin::{BitcoinError, BitcoinInterface}, + bitcoin::BitcoinInterface, database::{Coin, DatabaseInterface}, descriptors, DaemonControl, VERSION, }; @@ -499,10 +499,9 @@ impl DaemonControl { // Then, broadcast it (or try to, we never know if we are not going to hit an // error at broadcast time). let final_tx = spend_psbt.extract_tx(); - match self.bitcoin.broadcast_tx(&final_tx) { - Ok(()) => Ok(()), - Err(BitcoinError::Broadcast(e)) => Err(CommandError::TxBroadcast(e)), - } + self.bitcoin + .broadcast_tx(&final_tx) + .map_err(CommandError::TxBroadcast) } /// Trigger a rescan of the block chain for transactions involving our main descriptor between diff --git a/src/testutils.rs b/src/testutils.rs index 6201f32b..3607e25c 100644 --- a/src/testutils.rs +++ b/src/testutils.rs @@ -1,5 +1,5 @@ use crate::{ - bitcoin::{BitcoinError, BitcoinInterface, BlockChainTip, UTxO}, + bitcoin::{BitcoinInterface, BlockChainTip, UTxO}, config::{BitcoinConfig, Config}, database::{Coin, DatabaseConnection, DatabaseInterface, SpendBlock}, descriptors, DaemonHandle, @@ -71,7 +71,7 @@ impl BitcoinInterface for DummyBitcoind { todo!() } - fn broadcast_tx(&self, _: &bitcoin::Transaction) -> Result<(), BitcoinError> { + fn broadcast_tx(&self, _: &bitcoin::Transaction) -> Result<(), String> { todo!() } From 96b634b69c3b059c0711a35bac580ffcbf34af57 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 09:47:43 +0100 Subject: [PATCH 16/20] bitcoind: make the rescan starting interface failible This makes us more robust to races, where we'd crash previously --- src/bitcoin/d/mod.rs | 26 ++++++++++++++++---------- src/bitcoin/mod.rs | 21 +++++++++++++++++---- src/commands/mod.rs | 6 +++++- src/jsonrpc/mod.rs | 3 ++- src/testutils.rs | 2 +- 5 files changed, 41 insertions(+), 17 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index 0827deb5..e56d15f5 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -42,6 +42,7 @@ pub enum BitcoindError { InvalidVersion(u64), NetworkMismatch(String /*config*/, String /*bitcoind*/), MissingDescriptor, + AlreadyRescanning, } impl BitcoindError { @@ -113,6 +114,9 @@ impl std::fmt::Display for BitcoindError { BitcoindError::MissingDescriptor => { write!(f, "The watchonly wallet loaded on bitcoind does not have the main descriptor imported.") } + BitcoindError::AlreadyRescanning => { + write!(f, "A rescan is already ongoing for the watchonly wallet.") + } } } } @@ -780,10 +784,15 @@ impl BitcoinD { Ok(()) } - pub fn start_rescan(&self, desc: &MultipathDescriptor, timestamp: u32) { + pub fn start_rescan( + &self, + desc: &MultipathDescriptor, + timestamp: u32, + ) -> Result<(), BitcoindError> { // The wallet must not be already rescanning - // FIXME: don't assert, propagate an error instead. - assert!(self.rescan_progress().is_none()); + if self.rescan_progress().is_some() { + return Err(BitcoindError::AlreadyRescanning); + } // Re-import the receive and change descriptors to the watchonly wallet for the purpose of // rescanning. @@ -815,7 +824,7 @@ impl BitcoinD { // error and bitcoind will keep the new timestamps for the descriptors as if it had // successfully rescanned them. match self.make_noreply_request("importdescriptors", ¶ms!(Json::Array(descriptors))) { - Ok(()) => {} + Ok(()) => Ok(()), Err(e) => { // We checked at the beginning it was not already rescanning. If we get an error // because of that it's just a spurious error from calling it multiple times in the @@ -823,12 +832,9 @@ impl BitcoinD { if !e.to_string().contains("is currently rescanning.") { // However, if it's not an error because we triggered it twice due to a // flickering connection fail as it shouldn't happen. - // TODO: propagate the error back to the RPC command. There are too many - // reasons this could fail that we shouldn't be crashing for that. - panic!( - "Unexpected error when starting rescan on bitcoind wallet: {}", - e - ); + Err(e) + } else { + Ok(()) } } } diff --git a/src/bitcoin/mod.rs b/src/bitcoin/mod.rs index a6531f34..ae771dcc 100644 --- a/src/bitcoin/mod.rs +++ b/src/bitcoin/mod.rs @@ -76,7 +76,11 @@ pub trait BitcoinInterface: Send { /// Trigger a rescan of the block chain for transactions related to this descriptor since /// the given date. - fn start_rescan(&self, desc: &descriptors::MultipathDescriptor, timestamp: u32); + fn start_rescan( + &self, + desc: &descriptors::MultipathDescriptor, + timestamp: u32, + ) -> Result<(), String>; /// Rescan progress percentage. Between 0 and 1. fn rescan_progress(&self) -> Option; @@ -283,9 +287,14 @@ impl BitcoinInterface for d::BitcoinD { } } - fn start_rescan(&self, desc: &descriptors::MultipathDescriptor, timestamp: u32) { + fn start_rescan( + &self, + desc: &descriptors::MultipathDescriptor, + timestamp: u32, + ) -> Result<(), String> { // FIXME: in theory i think this could potentially fail to actually start the rescan. - self.start_rescan(desc, timestamp); + self.start_rescan(desc, timestamp) + .map_err(|e| e.to_string()) } fn rescan_progress(&self) -> Option { @@ -357,7 +366,11 @@ impl BitcoinInterface for sync::Arc> self.lock().unwrap().broadcast_tx(tx) } - fn start_rescan(&self, desc: &descriptors::MultipathDescriptor, timestamp: u32) { + fn start_rescan( + &self, + desc: &descriptors::MultipathDescriptor, + timestamp: u32, + ) -> Result<(), String> { self.lock().unwrap().start_rescan(desc, timestamp) } diff --git a/src/commands/mod.rs b/src/commands/mod.rs index 48762a64..05e60e53 100644 --- a/src/commands/mod.rs +++ b/src/commands/mod.rs @@ -61,6 +61,8 @@ pub enum CommandError { TxBroadcast(String), AlreadyRescanning, InsaneRescanTimestamp(u32), + /// An error that might occur in the racy rescan triggering logic. + RescanTrigger(String), } impl fmt::Display for CommandError { @@ -92,6 +94,7 @@ impl fmt::Display for CommandError { "There is already a rescan ongoing. Please wait for it to complete first." ), Self::InsaneRescanTimestamp(t) => write!(f, "Insane timestamp '{}'.", t), + Self::RescanTrigger(s) => write!(f, "Error while starting rescan: '{}'", s), } } } @@ -521,7 +524,8 @@ impl DaemonControl { // rescanning. This could make us crash with the bitcoind backend if someone triggered a // rescan of the wallet just after we checked above and did now. self.bitcoin - .start_rescan(&self.config.main_descriptor, timestamp); + .start_rescan(&self.config.main_descriptor, timestamp) + .map_err(CommandError::RescanTrigger)?; db_conn.set_rescan(timestamp); Ok(()) diff --git a/src/jsonrpc/mod.rs b/src/jsonrpc/mod.rs index 595dce33..c0258d9d 100644 --- a/src/jsonrpc/mod.rs +++ b/src/jsonrpc/mod.rs @@ -164,7 +164,8 @@ impl From for Error { | commands::CommandError::AlreadyRescanning => { Error::new(ErrorCode::InvalidParams, e.to_string()) } - commands::CommandError::SanityCheckFailure(_) => { + commands::CommandError::SanityCheckFailure(_) + | commands::CommandError::RescanTrigger(..) => { Error::new(ErrorCode::InternalError, e.to_string()) } commands::CommandError::TxBroadcast(_) => { diff --git a/src/testutils.rs b/src/testutils.rs index 3607e25c..7768cae9 100644 --- a/src/testutils.rs +++ b/src/testutils.rs @@ -75,7 +75,7 @@ impl BitcoinInterface for DummyBitcoind { todo!() } - fn start_rescan(&self, _: &descriptors::MultipathDescriptor, _: u32) { + fn start_rescan(&self, _: &descriptors::MultipathDescriptor, _: u32) -> Result<(), String> { todo!() } From 55cf21fa2aa7a66d998061684630a32cfb972a35 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 09:48:09 +0100 Subject: [PATCH 17/20] qa: unflake the getinfo RPC functional test --- tests/test_rpc.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tests/test_rpc.py b/tests/test_rpc.py index 2bc0aa73..25106ff6 100644 --- a/tests/test_rpc.py +++ b/tests/test_rpc.py @@ -13,7 +13,8 @@ def test_getinfo(minisafed): res = minisafed.rpc.getinfo() assert res["version"] == "0.1" assert res["network"] == "regtest" - wait_for(lambda: res["blockheight"] == 101) + wait_for(lambda: minisafed.rpc.getinfo()["blockheight"] == 101) + res = minisafed.rpc.getinfo() assert res["sync"] == 1.0 assert "main" in res["descriptors"] assert res["rescan_progress"] is None From 3c75e2e944638fdfe7ae6986aee9af83e0e2a532 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 14:07:39 +0100 Subject: [PATCH 18/20] bitcoind: disable retry logic for noreply requests Callers that use this client will have to use a custom retry logic. --- src/bitcoin/d/mod.rs | 44 ++++++++++++++++++++++++++++++-------------- 1 file changed, 30 insertions(+), 14 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index e56d15f5..e5b60803 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -270,25 +270,41 @@ impl BitcoinD { Err(error.expect("Always set if we reach this point")) } + fn try_request(&self, client: &Client, req: jsonrpc::Request) -> Result { + log::trace!("Sending to bitcoind: {:#?}", req); + match client.send_request(req) { + Ok(resp) => { + let res = resp.result().map_err(BitcoindError::Server)?; + log::trace!("Got from bitcoind: {:#?}", res); + + Ok(res) + } + Err(e) => Err(BitcoindError::Server(e)), + } + } + + fn make_request_inner<'a, 'b>( + &self, + client: &Client, + method: &'a str, + params: &'b [Box], + retry: bool, + ) -> Result { + let req = client.build_request(method, params); + if retry { + self.retry(|| self.try_request(client, req.clone())) + } else { + self.try_request(client, req) + } + } + fn make_request<'a, 'b>( &self, client: &Client, method: &'a str, params: &'b [Box], ) -> Result { - self.retry(|| { - let req = client.build_request(method, params); - log::trace!("Sending to bitcoind: {:#?}", req); - match client.send_request(req) { - Ok(resp) => { - let res = resp.result().map_err(BitcoindError::Server)?; - log::trace!("Got from bitcoind: {:#?}", res); - - Ok(res) - } - Err(e) => Err(BitcoindError::Server(e)), - } - }) + self.make_request_inner(client, method, params, true) } // Make a request for which you don't expect a response. This is achieved by setting a very low @@ -298,7 +314,7 @@ impl BitcoinD { method: &str, params: &[Box], ) -> Result<(), BitcoindError> { - match self.make_request(&self.sendonly_client, method, params) { + match self.make_request_inner(&self.sendonly_client, method, params, false) { Ok(_) => Ok(()), Err(e) => { // A timeout error is expected, as that's our workaround to avoid blocking From 337f422283e3392b6cea94df6211fd6c736772ef Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 14:13:48 +0100 Subject: [PATCH 19/20] bitcoind: add the timestamp to the 'listdescriptors' entry --- src/bitcoin/d/mod.rs | 13 ++++++++++++- src/lib.rs | 4 ++-- 2 files changed, 14 insertions(+), 3 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index e5b60803..6adc1832 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -472,8 +472,18 @@ impl BitcoinD { .try_into() .expect("Range is always an array of size 2") }); + let timestamp = elem + .get("timestamp") + .and_then(Json::as_u64) + .expect("A valid timestamp is always present") + .try_into() + .expect("timestamp must fit"); - ListDescEntry { desc, range } + ListDescEntry { + desc, + range, + timestamp, + } }) .collect() } @@ -894,6 +904,7 @@ fn roundup_progress(progress: f64) -> f64 { pub struct ListDescEntry { pub desc: String, pub range: Option<[u32; 2]>, + pub timestamp: u32, } /// A 'received' entry in the 'listsinceblock' result. diff --git a/src/lib.rs b/src/lib.rs index 2bb5247c..2c7d8cc8 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -516,10 +516,10 @@ mod tests { let net_resp = [ "HTTP/1.1 200\n\r\n{\"jsonrpc\":\"2.0\",\"id\":1,\"result\":{\"descriptors\":[{\"desc\":\"".as_bytes(), receive_desc.as_bytes(), - "\"},".as_bytes(), + "\",\"timestamp\":0},".as_bytes(), "{\"desc\":\"".as_bytes(), change_desc.as_bytes(), - "\"}]}}\n".as_bytes(), + "\",\"timestamp\":1}]}}\n".as_bytes(), ] .concat(); let (mut stream, _) = server.accept().unwrap(); From 32f3bdeb16b66878e23ba71a6f2c401c5d1f601a Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Mon, 14 Nov 2022 14:35:57 +0100 Subject: [PATCH 20/20] bitcoind: check the rescan was successful, retry at most 10 times --- src/bitcoin/d/mod.rs | 84 ++++++++++++++++++++++++++++++-------------- 1 file changed, 58 insertions(+), 26 deletions(-) diff --git a/src/bitcoin/d/mod.rs b/src/bitcoin/d/mod.rs index 6adc1832..894b4bb3 100644 --- a/src/bitcoin/d/mod.rs +++ b/src/bitcoin/d/mod.rs @@ -42,7 +42,7 @@ pub enum BitcoindError { InvalidVersion(u64), NetworkMismatch(String /*config*/, String /*bitcoind*/), MissingDescriptor, - AlreadyRescanning, + StartRescan, } impl BitcoindError { @@ -114,8 +114,11 @@ impl std::fmt::Display for BitcoindError { BitcoindError::MissingDescriptor => { write!(f, "The watchonly wallet loaded on bitcoind does not have the main descriptor imported.") } - BitcoindError::AlreadyRescanning => { - write!(f, "A rescan is already ongoing for the watchonly wallet.") + BitcoindError::StartRescan => { + write!( + f, + "Error while triggering the rescan for the bitcoind watchonly wallet." + ) } } } @@ -810,16 +813,30 @@ impl BitcoinD { Ok(()) } + // For the given descriptor strings check if they are imported at this timestamp in the + // watchonly wallet. + fn check_descs_timestamp(&self, descs: &[String], timestamp: u32) -> bool { + let current_descs = self.list_descriptors(); + + for desc in descs { + let present = current_descs + .iter() + .find(|entry| &entry.desc == desc) + .map(|entry| entry.timestamp == timestamp) + .unwrap_or(false); + if !present { + return false; + } + } + + true + } + pub fn start_rescan( &self, desc: &MultipathDescriptor, timestamp: u32, ) -> Result<(), BitcoindError> { - // The wallet must not be already rescanning - if self.rescan_progress().is_some() { - return Err(BitcoindError::AlreadyRescanning); - } - // Re-import the receive and change descriptors to the watchonly wallet for the purpose of // rescanning. // The range of the newly imported descriptors supposed to update the existing ones must @@ -832,11 +849,15 @@ impl BitcoinD { .fold(1_000, |range, entry| { cmp::max(range, entry.range.map(|r| r[1]).unwrap_or(0)) }); - let descriptors = [desc.receive_descriptor(), desc.change_descriptor()] + let desc_str = [ + desc.receive_descriptor().to_string(), + desc.change_descriptor().to_string(), + ]; + let desc_json: Vec = desc_str .iter() - .map(|desc| { + .map(|desc_str| { serde_json::json!({ - "desc": desc.to_string(), + "desc": desc_str, "timestamp": timestamp, "active": false, "range": max_range, @@ -844,24 +865,35 @@ impl BitcoinD { }) .collect(); - // TODO: should we check there was not timeout when writing the request on the - // TcpStream in the SimpleHttpTransport implem? + // Since we don't wait for a response (which would make us block for the entire duration of + // the rescan), we can't know for sure whether it was started successfully. So what we do + // here is retrying a few times (since the noreply_request disables our generalistic retry + // logic) until we notice the descriptors are successfully imported at this timestamp on + // the watchonly wallet. // NOTE: if the rescan gets aborted through the 'abortrescan' RPC we won't see the // error and bitcoind will keep the new timestamps for the descriptors as if it had // successfully rescanned them. - match self.make_noreply_request("importdescriptors", ¶ms!(Json::Array(descriptors))) { - Ok(()) => Ok(()), - Err(e) => { - // We checked at the beginning it was not already rescanning. If we get an error - // because of that it's just a spurious error from calling it multiple times in the - // retry logic. - if !e.to_string().contains("is currently rescanning.") { - // However, if it's not an error because we triggered it twice due to a - // flickering connection fail as it shouldn't happen. - Err(e) - } else { - Ok(()) - } + const NUM_RETRIES: usize = 10; + let mut i = 0; + loop { + if let Err(e) = self.make_noreply_request( + "importdescriptors", + ¶ms!(Json::Array(desc_json.clone())), + ) { + log::error!( + "Error when calling 'importdescriptors' for rescanning: {}", + e + ); + } + + i += 1; + if self.check_descs_timestamp(&desc_str, timestamp) { + return Ok(()); + } else if i >= NUM_RETRIES { + return Err(BitcoindError::StartRescan); + } else { + log::debug!("Sleeping a second before retrying to trigger the rescan"); + std::thread::sleep(Duration::from_secs(1)); } } }