feat: add optional tracing instrumentation

Author: LagginTimes

crates/bitcoind_rpc/Cargo.toml

@@ -19,6 +19,7 @@ workspace = true
 bitcoin = { version = "0.32.0", default-features = false }
 bitcoincore-rpc = { version = "0.19.0" }
 bdk_core = { path = "../core", version = "0.6.0", default-features = false }
+tracing = { version = "0.1", optional = true }
 
 [dev-dependencies]
 bdk_bitcoind_rpc = { path = "." }
@@ -29,6 +30,7 @@ bdk_chain = { path = "../chain" }
 default = ["std"]
 std = ["bitcoin/std", "bdk_core/std"]
 serde = ["bitcoin/serde", "bdk_core/serde"]
+tracing-logs = ["tracing"]
 
 [[example]]
 name = "filter_iter"

crates/bitcoind_rpc/src/lib.rs

@@ -14,6 +14,9 @@ use bitcoin::{Block, BlockHash, Transaction, Txid};
 use bitcoincore_rpc::{bitcoincore_rpc_json, RpcApi};
 use std::{collections::HashSet, ops::Deref};
 
+#[cfg(feature = "tracing-logs")]
+use tracing::trace;
+
 pub mod bip158;
 
 pub use bitcoincore_rpc;
@@ -115,6 +118,13 @@ where
     pub fn mempool(&mut self) -> Result<MempoolEvent, bitcoincore_rpc::Error> {
         let client = &*self.client;
 
+        #[cfg(feature = "tracing-logs")]
+        trace!(
+            "mempool(): entering, start_height={}, last_mempool_tip={:?}",
+            self.start_height,
+            self.last_mempool_tip
+        );
+
         // This is the emitted tip height during the last mempool emission.
         let prev_mempool_tip = self
             .last_mempool_tip
@@ -125,6 +135,12 @@ where
         // Loop to make sure that the fetched mempool content and the fetched tip are consistent
         // with one another.
         let (raw_mempool, raw_mempool_txids, rpc_height, rpc_block_hash) = loop {
+            #[cfg(feature = "tracing-logs")]
+            trace!(
+                "mempool(): checking consistency loop, prev_mempool_tip={}",
+                prev_mempool_tip
+            );
+
             // Determine if height and hash matches the best block from the RPC. Evictions are
             // deferred if we are not at the best block.
             let height = client.get_block_count()?;
@@ -140,9 +156,25 @@ where
             }
         };
 
+        #[cfg(feature = "tracing-logs")]
+        trace!(
+            "mempool(): fetched raw_mempool ({} entries), rpc_height={}, rpc_block_hash={}",
+            raw_mempool.len(),
+            rpc_height,
+            rpc_block_hash
+        );
+
         let at_tip =
             rpc_height == self.last_cp.height() as u64 && rpc_block_hash == self.last_cp.hash();
 
+        #[cfg(feature = "tracing-logs")]
+        trace!(
+            "mempool(): at_tip={} (last_cp.height={} vs rpc_height={})",
+            at_tip,
+            self.last_cp.height(),
+            rpc_height
+        );
+
         // If at tip, any expected txid missing from raw mempool is considered evicted;
         // if not at tip, we don't evict anything.
         let evicted_txids: HashSet<Txid> = if at_tip {
@@ -166,6 +198,14 @@ where
             .filter_map({
                 let latest_time = &mut latest_time;
                 move |(txid, tx_entry)| -> Option<Result<_, bitcoincore_rpc::Error>> {
+                    #[cfg(feature = "tracing-logs")]
+                    trace!(
+                        "mempool(): considering txid={}, time={}, prev_time={}",
+                        txid,
+                        tx_entry.time,
+                        prev_mempool_time
+                    );
+
                     let tx_time = tx_entry.time as usize;
                     if tx_time > *latest_time {
                         *latest_time = tx_time;
@@ -206,6 +246,14 @@ where
                 .extend(new_txs.iter().map(|(tx, _)| tx.compute_txid()));
         }
 
+        #[cfg(feature = "tracing-logs")]
+        trace!(
+            "mempool(): emitting {} new_txs, {} evicted_txids, latest_update_time={}",
+            new_txs.len(),
+            evicted_txids.len(),
+            latest_time
+        );
+
         Ok(MempoolEvent {
             new_txs,
             evicted_txids,
@@ -215,11 +263,23 @@ where
 
     /// Emit the next block height and block (if any).
     pub fn next_block(&mut self) -> Result<Option<BlockEvent<Block>>, bitcoincore_rpc::Error> {
+        #[cfg(feature = "tracing-logs")]
+        trace!(
+            "next_block(): entering, last_block={:?}",
+            self.last_block.as_ref().map(|r| r.height)
+        );
+
         if let Some((checkpoint, block)) = poll(self, move |hash, client| client.get_block(hash))? {
             // Stop tracking unconfirmed transactions that have been confirmed in this block.
             for tx in &block.txdata {
                 self.expected_mempool_txids.remove(&tx.compute_txid());
             }
+            #[cfg(feature = "tracing-logs")]
+            trace!(
+                "next_block(): emitting block at height={}, txcount={}",
+                checkpoint.height(),
+                block.txdata.len()
+            );
             return Ok(Some(BlockEvent { block, checkpoint }));
         }
         Ok(None)
@@ -313,6 +373,13 @@ where
     C: Deref,
     C::Target: RpcApi,
 {
+    #[cfg(feature = "tracing-logs")]
+    trace!(
+        "poll_once(): last_block={:?}, start_height={}",
+        emitter.last_block.as_ref().map(|r| r.height),
+        emitter.start_height
+    );
+
     let client = &*emitter.client;
 
     if let Some(last_res) = &emitter.last_block {
@@ -321,21 +388,36 @@ where
             let next_hash = client.get_block_hash(emitter.start_height as _)?;
             // make sure last emission is still in best chain
             if client.get_block_hash(last_res.height as _)? != last_res.hash {
+                #[cfg(feature = "tracing-logs")]
+                trace!("poll_once(): returning BlockNotInBestChain");
+
                 return Ok(PollResponse::BlockNotInBestChain);
             }
             next_hash
         } else {
             match last_res.nextblockhash {
-                None => return Ok(PollResponse::NoMoreBlocks),
+                None => {
+                    #[cfg(feature = "tracing-logs")]
+                    trace!("poll_once(): returning NoMoreBlocks");
+                    return Ok(PollResponse::NoMoreBlocks);
+                }
                 Some(next_hash) => next_hash,
             }
         };
 
         let res = client.get_block_info(&next_hash)?;
         if res.confirmations < 0 {
+            #[cfg(feature = "tracing-logs")]
+            trace!("poll_once(): returning BlockNotInBestChain");
             return Ok(PollResponse::BlockNotInBestChain);
         }
 
+        #[cfg(feature = "tracing-logs")]
+        trace!(
+            "poll(): PollResponse::Block, height={}, hash={}",
+            res.height,
+            res.hash
+        );
         return Ok(PollResponse::Block(res));
     }
 
@@ -355,6 +437,12 @@ where
         };
 
         // agreement point found
+        #[cfg(feature = "tracing-logs")]
+        trace!(
+            "poll(): PollResponse::AgreementFound, height={}, hash={}",
+            res.height,
+            res.hash
+        );
         return Ok(PollResponse::AgreementFound(res, cp));
     }
 

crates/electrum/Cargo.toml

@@ -16,6 +16,7 @@ workspace = true
 bdk_core = { path = "../core", version = "0.6.0" }
 electrum-client = { version = "0.23.1", features = [ "proxy" ], default-features = false }
 serde_json = "1.0"
+tracing = { version = "0.1", optional = true }
 
 [dev-dependencies]
 bdk_testenv = { path = "../testenv" }
@@ -27,6 +28,7 @@ default = ["use-rustls"]
 use-rustls = ["electrum-client/use-rustls"]
 use-rustls-ring = ["electrum-client/use-rustls-ring"]
 use-openssl = ["electrum-client/use-openssl"]
+tracing-logs = ["tracing"]
 
 [[test]]
 name = "test_electrum"

crates/electrum/src/bdk_electrum_client.rs

@@ -9,6 +9,9 @@ use bdk_core::{
 use electrum_client::{ElectrumApi, Error, HeaderNotification};
 use std::sync::{Arc, Mutex};
 
+#[cfg(feature = "tracing-logs")]
+use tracing::{debug, trace};
+
 /// We include a chain suffix of a certain length for the purpose of robustness.
 const CHAIN_SUFFIX_LENGTH: u32 = 8;
 
@@ -55,11 +58,16 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
         let tx_cache = self.tx_cache.lock().unwrap();
 
         if let Some(tx) = tx_cache.get(&txid) {
+            #[cfg(feature = "tracing-logs")]
+            trace!(%txid, "hit tx cache");
             return Ok(Arc::clone(tx));
         }
 
         drop(tx_cache);
 
+        #[cfg(feature = "tracing-logs")]
+        trace!(%txid, "missed tx cache, fetching from electrum");
+
         let tx = Arc::new(self.inner.transaction_get(&txid)?);
 
         self.tx_cache.lock().unwrap().insert(txid, Arc::clone(&tx));
@@ -104,6 +112,9 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
         let mut request: FullScanRequest<K> = request.into();
         let start_time = request.start_time();
 
+        #[cfg(feature = "tracing-logs")]
+        trace!("starting full_scan");
+
         let tip_and_latest_blocks = match request.chain_tip() {
             Some(chain_tip) => Some(fetch_tip_and_latest_blocks(&self.inner, chain_tip)?),
             None => None,
@@ -187,6 +198,9 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
         let mut request: SyncRequest<I> = request.into();
         let start_time = request.start_time();
 
+        #[cfg(feature = "tracing-logs")]
+        trace!("starting sync");
+
         let tip_and_latest_blocks = match request.chain_tip() {
             Some(chain_tip) => Some(fetch_tip_and_latest_blocks(&self.inner, chain_tip)?),
             None => None,
@@ -266,10 +280,18 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
             let spks = (0..batch_size)
                 .map_while(|_| spks_with_expected_txids.next())
                 .collect::<Vec<_>>();
+            #[cfg(feature = "tracing-logs")]
+            trace!(batch_size = spks.len(), "fetching script history batch");
+
             if spks.is_empty() {
+                #[cfg(feature = "tracing-logs")]
+                trace!("no script pubkeys left to scan in batch");
                 return Ok(last_active_index);
             }
 
+            #[cfg(feature = "tracing-logs")]
+            trace!("spk has tx history");
+
             let spk_histories = self
                 .inner
                 .batch_script_get_history(spks.iter().map(|(_, s)| s.spk.as_script()))?;
@@ -278,7 +300,15 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
                 if spk_history.is_empty() {
                     match unused_spk_count.checked_add(1) {
                         Some(i) if i < stop_gap => unused_spk_count = i,
-                        _ => return Ok(last_active_index),
+                        _ => {
+                            #[cfg(feature = "tracing-logs")]
+                            trace!(
+                                unused_spk_count,
+                                stop_gap,
+                                "gap limit reached, stopping scan for keychain"
+                            );
+                            return Ok(last_active_index);
+                        }
                     };
                 } else {
                     last_active_index = Some(spk_index);
@@ -360,10 +390,14 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
 
                     if !has_residing && res.tx_hash == outpoint.txid {
                         has_residing = true;
+                        #[cfg(feature = "tracing-logs")]
+                        trace!(%outpoint, "tx resides at outpoint, fetched and processed");
                         tx_update.txs.push(Arc::clone(&tx));
                         match res.height.try_into() {
                             // Returned heights 0 & -1 are reserved for unconfirmed txs.
                             Ok(height) if height > 0 => {
+                                #[cfg(feature = "tracing-logs")]
+                                trace!(%res.tx_hash, height, "added anchor from outpoint resolution");
                                 pending_anchors.push((res.tx_hash, height));
                             }
                             _ => {
@@ -379,13 +413,18 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
                             .input
                             .iter()
                             .any(|txin| txin.previous_output == outpoint);
-                        if !has_spending {
+                        if has_spending {
+                            #[cfg(feature = "tracing-logs")]
+                            trace!(%outpoint, spending_txid = %res.tx_hash, "found tx spending from outpoint");
+                        } else {
                             continue;
                         }
                         tx_update.txs.push(Arc::clone(&res_tx));
                         match res.height.try_into() {
                             // Returned heights 0 & -1 are reserved for unconfirmed txs.
                             Ok(height) if height > 0 => {
+                                #[cfg(feature = "tracing-logs")]
+                                trace!(%res.tx_hash, height, "added anchor from outpoint resolution");
                                 pending_anchors.push((res.tx_hash, height));
                             }
                             _ => {
@@ -420,9 +459,13 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
                         .expect("tx must have an output")
                         .clone();
                     txs.push((txid, tx));
+                    #[cfg(feature = "tracing-logs")]
+                    trace!(%txid, "fetched tx for txid, checking confirmation status");
                     scripts.push(spk);
                 }
                 Err(electrum_client::Error::Protocol(_)) => {
+                    #[cfg(feature = "tracing-logs")]
+                    debug!(%txid, "electrum protocol error, skipping txid");
                     continue;
                 }
                 Err(e) => return Err(e),
@@ -440,6 +483,8 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
                 match res.height.try_into() {
                     // Returned heights 0 & -1 are reserved for unconfirmed txs.
                     Ok(height) if height > 0 => {
+                        #[cfg(feature = "tracing-logs")]
+                        trace!(%res.tx_hash, height, "anchor candidate found via txid history");
                         pending_anchors.push((tx.0, height));
                     }
                     _ => {
@@ -499,8 +544,12 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
                 let h = height as u32;
                 let hash = height_to_hash[&h];
                 if let Some(anchor) = anchor_cache.get(&(txid, hash)) {
+                    #[cfg(feature = "tracing-logs")]
+                    trace!(%txid, height, "anchor cache hit");
                     results.push((txid, *anchor));
                 } else {
+                    #[cfg(feature = "tracing-logs")]
+                    trace!(%txid, height, "anchor cache miss, will fetch merkle proof");
                     to_fetch.push((txid, height, hash));
                 }
             }
@@ -533,6 +582,8 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
             let mut valid =
                 electrum_client::utils::validate_merkle_proof(&txid, &header.merkle_root, &proof);
             if !valid {
+                #[cfg(feature = "tracing-logs")]
+                debug!(%txid, height, "merkle validation failed, refetching header and retrying");
                 header = self.inner.block_header(height)?;
                 self.block_header_cache
                     .lock()
@@ -543,6 +594,10 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
                     &header.merkle_root,
                     &proof,
                 );
+                if valid {
+                    #[cfg(feature = "tracing-logs")]
+                    trace!(%txid, height, "merkle proof validated after retry");
+                }
             }
 
             // Build and cache the anchor if merkle proof is valid.
@@ -558,6 +613,8 @@ impl<E: ElectrumApi> BdkElectrumClient<E> {
                     .lock()
                     .unwrap()
                     .insert((txid, hash), anchor);
+                #[cfg(feature = "tracing-logs")]
+                trace!(%txid, height, %hash, "inserted anchor");
                 results.push((txid, anchor));
             }
         }