feat: add optional tracing instrumentation

Cargo.toml

@@ -8,6 +8,7 @@ members = [
     "crates/esplora",
     "crates/bitcoind_rpc",
     "crates/testenv",
+    "crates/common",
     "examples/example_cli",
     "examples/example_electrum",
     "examples/example_esplora",

ci/pin-msrv.sh

@@ -29,6 +29,7 @@ cargo update -p base64ct --precise "1.6.0"
 cargo update -p minreq --precise "2.13.2"
 cargo update -p tracing-core --precise "0.1.33"
 cargo update -p [email protected] --precise "1.0.1"
+cargo update -p tracing-attributes --precise "0.1.28"
 cargo update -p rayon --precise "1.10.0"
 cargo update -p rayon-core --precise "1.12.1"
 cargo update -p [email protected] --precise "0.5.10"

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.1", default-features = false }
+bdk_common = { path = "../common" }
 
 [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"]
+log = ["bdk_common/log"]
 
 [[example]]
 name = "filter_iter"

crates/bitcoind_rpc/src/lib.rs

@@ -14,6 +14,10 @@
 #[macro_use]
 extern crate alloc;
 
+#[allow(unused_imports)]
+#[macro_use]
+extern crate bdk_common;
+
 use alloc::sync::Arc;
 use bdk_core::collections::{HashMap, HashSet};
 use bdk_core::{BlockId, CheckPoint};
@@ -124,6 +128,12 @@ where
     pub fn mempool_at(&mut self, sync_time: u64) -> Result<MempoolEvent, bitcoincore_rpc::Error> {
         let client = &*self.client;
 
+        log_trace!(
+            start_height = self.start_height,
+            sync_time = sync_time,
+            "enter mempool_at"
+        );
+
         let mut rpc_tip_height;
         let mut rpc_tip_hash;
         let mut rpc_mempool;
@@ -164,6 +174,13 @@ where
             ..Default::default()
         };
 
+        log_trace!(
+            rpc_mempool_count = rpc_mempool_txids.len(),
+            rpc_height = rpc_tip_height,
+            rpc_block_hash = %rpc_tip_hash,
+            "fetched raw mempool"
+        );
+
         let at_tip =
             rpc_tip_height == self.last_cp.height() as u64 && rpc_tip_hash == self.last_cp.hash();
 
@@ -200,11 +217,21 @@ where
 
     /// Emit the next block height and block (if any).
     pub fn next_block(&mut self) -> Result<Option<BlockEvent<Block>>, bitcoincore_rpc::Error> {
+        log_trace!(
+            last_block_height = self.last_block.as_ref().map(|r| r.height),
+            "enter next_block"
+        );
+
         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.mempool_snapshot.remove(&tx.compute_txid());
             }
+            log_trace!(
+                block_height = checkpoint.height(),
+                tx_count = block.txdata.len(),
+                "emit block"
+            );
             return Ok(Some(BlockEvent { block, checkpoint }));
         }
         Ok(None)
@@ -279,6 +306,12 @@ where
     C: Deref,
     C::Target: RpcApi,
 {
+    log_trace!(
+        last_block_height = emitter.last_block.as_ref().map(|r| r.height),
+        start_height = emitter.start_height,
+        "enter poll_once"
+    );
+
     let client = &*emitter.client;
 
     if let Some(last_res) = &emitter.last_block {
@@ -287,21 +320,31 @@ 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 {
+                log_trace!("block not in best chain");
                 return Ok(PollResponse::BlockNotInBestChain);
             }
             next_hash
         } else {
             match last_res.nextblockhash {
-                None => return Ok(PollResponse::NoMoreBlocks),
+                None => {
+                    log_trace!("no more blocks");
+                    return Ok(PollResponse::NoMoreBlocks);
+                }
                 Some(next_hash) => next_hash,
             }
         };
 
         let res = client.get_block_info(&next_hash)?;
         if res.confirmations < 0 {
+            log_trace!("block not in best chain");
             return Ok(PollResponse::BlockNotInBestChain);
         }
 
+        log_trace!(
+            height = res.height,
+            hash   = %res.hash,
+            "agreement found"
+        );
         return Ok(PollResponse::Block(res));
     }
 
@@ -321,6 +364,11 @@ where
         };
 
         // agreement point found
+        log_trace!(
+            "poll(): PollResponse::AgreementFound, height={}, hash={}",
+            res.height,
+            res.hash
+        );
         return Ok(PollResponse::AgreementFound(res, cp));
     }
 

crates/common/Cargo.toml

@@ -0,0 +1,17 @@
+[package]
+name = "bdk_common"
+version = "0.1.0"
+edition = "2021"
+rust-version = "1.63"
+homepage = "https://bitcoindevkit.org"
+repository = "https://github.com/bitcoindevkit/bdk"
+description = "Shared utilities and macros for BDK chain sources."
+license = "MIT OR Apache-2.0"
+readme = "README.md"
+publish = false
+
+[dependencies]
+tracing = { version = "0.1", optional = true }
+
+[features]
+log = ["tracing"]

crates/common/README.md

@@ -0,0 +1,11 @@
+# BDK Common
+
+`bdk_common` is an **internal-only** crate providing zero-overhead, feature-gated logging macros for
+all BDK chain-sync crates. Enabling the single `log` feature pulls in `tracing = "0.1"`. When it’s
+off, the macros compile to no-ops and there’s no runtime or dependency impact.
+
+## Features
+
+- **`log`** (off by default)
+  – Re-exports `tracing` and enables logging.
+  – When disabled, `log_trace!`, `log_debug!`, `log_info!`, `log_warn!`, `log_error!`, and `log_span!` expand to nothing.

crates/common/src/lib.rs

@@ -0,0 +1,5 @@
+#[cfg(feature = "log")]
+pub use tracing;
+
+#[macro_use]
+mod log;

crates/common/src/log.rs

@@ -0,0 +1,99 @@
+/// Trace-level logging. Expands to `tracing::trace!()` when the `log` feature is enabled,
+/// otherwise into a no-op.
+#[cfg(feature = "log")]
+#[macro_export]
+macro_rules! log_trace {
+    ($($tt:tt)*) => {
+        $crate::tracing::trace!($($tt)*);
+    };
+}
+#[cfg(not(feature = "log"))]
+#[macro_export]
+macro_rules! log_trace {
+    ($($tt:tt)*) => {};
+}
+
+/// Trace-level span. Expands to `tracing::trace_span!()` when the `log` feature is enabled,
+/// otherwise to a dummy no-op span whose `.entered()` does nothing.
+#[cfg(feature = "log")]
+#[macro_export]
+macro_rules! log_span {
+    ( $($tts:tt)* ) => {
+        $crate::tracing::trace_span!($($tts)*)
+    };
+}
+#[cfg(not(feature = "log"))]
+#[macro_export]
+macro_rules! log_span {
+    ( $($tts:tt)* ) => {{
+        struct NoopSpan;
+        impl NoopSpan {
+            #[allow(dead_code)]
+            pub fn entered(self) -> NoopEntered {
+                NoopEntered
+            }
+        }
+        struct NoopEntered;
+        NoopSpan
+    }};
+}
+
+/// Debug-level logging. Expands to `tracing::debug!()` when the `log` feature is enabled,
+/// otherwise into a no-op.
+#[cfg(feature = "log")]
+#[macro_export]
+macro_rules! log_debug {
+    ($($tt:tt)*) => {
+        $crate::tracing::debug!($($tt)*);
+    };
+}
+#[cfg(not(feature = "log"))]
+#[macro_export]
+macro_rules! log_debug {
+    ($($tt:tt)*) => {};
+}
+
+/// Info-level logging. Expands to `tracing::info!()` when the `log` feature is enabled,
+/// otherwise into a no-op.
+#[cfg(feature = "log")]
+#[macro_export]
+macro_rules! log_info {
+    ($($tt:tt)*) => {
+        $crate::tracing::info!($($tt)*);
+    };
+}
+#[cfg(not(feature = "log"))]
+#[macro_export]
+macro_rules! log_info {
+    ($($tt:tt)*) => {};
+}
+
+/// Warn-level logging. Expands to `tracing::warn!()` when the `log` feature is enabled,
+/// otherwise into a no-op.
+#[cfg(feature = "log")]
+#[macro_export]
+macro_rules! log_warn {
+    ($($tt:tt)*) => {
+        $crate::tracing::warn!($($tt)*);
+    };
+}
+#[cfg(not(feature = "log"))]
+#[macro_export]
+macro_rules! log_warn {
+    ($($tt:tt)*) => {};
+}
+
+/// Error-level logging. Expands to `tracing::error!()` when the `log` feature is enabled,
+/// otherwise into a no-op.
+#[cfg(feature = "log")]
+#[macro_export]
+macro_rules! log_error {
+    ($($tt:tt)*) => {
+        $crate::tracing::error!($($tt)*);
+    };
+}
+#[cfg(not(feature = "log"))]
+#[macro_export]
+macro_rules! log_error {
+    ($($tt:tt)*) => {};
+}

crates/electrum/Cargo.toml

@@ -14,6 +14,7 @@ workspace = true
 
 [dependencies]
 bdk_core = { path = "../core", version = "0.6.1" }
+bdk_common = { path = "../common" }
 electrum-client = { version = "0.24.0", features = [ "proxy" ], default-features = false }
 
 [dev-dependencies]
@@ -26,6 +27,7 @@ default = ["use-rustls"]
 use-rustls = ["electrum-client/use-rustls"]
 use-rustls-ring = ["electrum-client/use-rustls-ring"]
 use-openssl = ["electrum-client/use-openssl"]
+log = ["bdk_common/log"]
 
 [[test]]
 name = "test_electrum"