Tracing PoC

lightning-background-processor/Cargo.toml

@@ -28,6 +28,7 @@ lightning = { version = "0.2.0", path = "../lightning", default-features = false
 lightning-rapid-gossip-sync = { version = "0.2.0", path = "../lightning-rapid-gossip-sync", default-features = false }
 lightning-liquidity = { version = "0.2.0", path = "../lightning-liquidity", default-features = false }
 possiblyrandom = { version = "0.2", path = "../possiblyrandom", default-features = false }
+tracing = "0.1.41"
 
 [dev-dependencies]
 tokio = { version = "1.35", features = [ "macros", "rt", "rt-multi-thread", "sync", "time" ] }

lightning-liquidity/Cargo.toml

@@ -33,6 +33,7 @@ chrono = { version = "0.4", default-features = false, features = ["serde", "allo
 serde = { version = "1.0", default-features = false, features = ["derive", "alloc"] }
 serde_json = { version = "1.0", default-features = false, features = ["alloc"] }
 backtrace = { version = "0.3", optional = true }
+tracing = "0.1.41"
 
 [dev-dependencies]
 lightning = { version = "0.2.0", path = "../lightning", default-features = false, features = ["_test_utils"] }

lightning-macros/src/lib.rs

@@ -25,7 +25,7 @@ use proc_macro::{Delimiter, Group, TokenStream, TokenTree};
 use proc_macro2::TokenStream as TokenStream2;
 use quote::quote;
 use syn::spanned::Spanned;
-use syn::{parse, ImplItemFn, Token};
+use syn::{parse, Attribute, FnArg, ImplItem, ImplItemFn, ItemImpl, Meta, Token, Visibility};
 use syn::{parse_macro_input, Item};
 
 fn add_async_method(mut parsed: ImplItemFn) -> TokenStream {
@@ -400,3 +400,30 @@ pub fn xtest_inventory(_input: TokenStream) -> TokenStream {
 
 	TokenStream::from(expanded)
 }
+
+/// Auto-enters the parent span.
+#[proc_macro_attribute]
+pub fn auto_span_methods(_attr: TokenStream, item: TokenStream) -> TokenStream {
+	let mut input = parse_macro_input!(item as ItemImpl);
+
+	for item in input.items.iter_mut() {
+		if let ImplItem::Fn(method) = item {
+			// Skip the method that sets the node_span
+			if method.sig.ident == "set_node_id" {
+				continue;
+			}
+
+			if let Some(FnArg::Receiver(_)) = method.sig.inputs.first() {
+				let block = &method.block;
+				let method_name = method.sig.ident.to_string();
+				method.block = syn::parse_quote!({
+					let _node_span = enter_instance_span(self.node_id.clone()).map(|s|(s.entered(), InSpanGuard{}));
+					let _method_span = tracing::span!(tracing::Level::INFO, #method_name).entered();
+					#block
+				});
+			}
+		}
+	}
+
+	TokenStream::from(quote!(#input))
+}

lightning-rapid-gossip-sync/Cargo.toml

@@ -19,6 +19,7 @@ lightning = { version = "0.2.0", path = "../lightning", default-features = false
 bitcoin = { version = "0.32.2", default-features = false }
 bitcoin_hashes = { version = "0.14.0", default-features = false }
 bitcoin-io = { version = "0.1.2", default-features = false }
+tracing = "0.1.41"
 
 [target.'cfg(ldk_bench)'.dependencies]
 criterion = { version = "0.4", optional = true, default-features = false }

lightning/Cargo.toml

@@ -50,6 +50,9 @@ backtrace = { version = "0.3", optional = true }
 
 libm = { version = "0.2", default-features = false }
 inventory = { version = "0.3", optional = true  }
+tracing = "0.1.41"
+tracing-subscriber = "0.3.20"
+tracing-tree = "0.4.1"
 
 [dev-dependencies]
 regex = "1.5.6"

lightning/src/ln/channel.rs

@@ -13496,6 +13496,8 @@ where
 		};
 		let keys = self.funding.get_holder_pubkeys();
 
+		log_trace!(_logger, "Channel opened");
+
 		Some(msgs::OpenChannel {
 			common_fields: msgs::CommonOpenChannelFields {
 				chain_hash,

lightning/src/ln/channelmanager.rs

@@ -31,6 +31,7 @@ use bitcoin::hashes::{Hash, HashEngine, HmacEngine};
 use bitcoin::secp256k1::Secp256k1;
 use bitcoin::secp256k1::{PublicKey, SecretKey};
 use bitcoin::{secp256k1, Sequence, SignedAmount};
+use tracing::Span;
 
 use crate::blinded_path::message::{
 	AsyncPaymentsContext, BlindedMessagePath, MessageForwardNode, OffersContext,
@@ -1889,6 +1890,57 @@ where
 	}
 }
 
+thread_local! {
+	static CURRENT_INSTANCE: RefCell<Option<String>> = RefCell::new(None);
+	static CURRENT_SPAN: RefCell<Option<Span>> = RefCell::new(None);
+	static IN_SPAN: RefCell<bool> = RefCell::new(false);
+}
+
+struct InSpanGuard {}
+
+impl Drop for InSpanGuard {
+	fn drop(&mut self) {
+		IN_SPAN.with(|in_span| {
+			*in_span.borrow_mut() = false;
+		});
+	}
+}
+
+fn enter_instance_span(name: String) -> Option<tracing::span::Span> {
+	// return None is IN_SPAN
+	if IN_SPAN.with(|in_span| *in_span.borrow()) {
+		return None;
+	}
+
+	// set IN_SPAN to true
+	IN_SPAN.with(|in_span| {
+		*in_span.borrow_mut() = true;
+	});
+
+	let mut span_to_enter: Option<Span> = None;
+
+	CURRENT_INSTANCE.with(|current_name| {
+		let mut current_name = current_name.borrow_mut();
+
+		if current_name.as_deref() != Some(&name) {
+			// Start a new span and store it
+			let span = tracing::info_span!("node", name);
+			CURRENT_SPAN.with(|s| *s.borrow_mut() = Some(span.clone())); // clone is cheap
+			*current_name = Some(name);
+			span_to_enter = Some(span);
+		} else {
+			// Reuse existing span
+			CURRENT_SPAN.with(|s| {
+				if let Some(span) = s.borrow().as_ref() {
+					span_to_enter = Some(span.clone());
+				}
+			});
+		}
+	});
+
+	span_to_enter
+}
+
 /// A lightning node's channel state machine and payment management logic, which facilitates
 /// sending, forwarding, and receiving payments through lightning channels.
 ///
@@ -2927,6 +2979,8 @@ pub struct ChannelManager<
 	signer_provider: SP,
 
 	logger: L,
+
+	node_id: String,
 }
 
 /// Chain-related parameters used to construct a new `ChannelManager`.
@@ -3926,6 +3980,7 @@ macro_rules! process_events_body {
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -4043,9 +4098,15 @@ where
 
 			#[cfg(feature = "_test_utils")]
 			testing_dnssec_proof_offer_resolution_override: Mutex::new(new_hash_map()),
+
+			node_id : "?".to_string(),
 		}
 	}
 
+	pub fn set_node_id(&mut self, id: String) {
+		self.node_id = id;
+	}
+
 	/// Gets the current [`UserConfig`] which controls some global behavior and includes the
 	/// default configuration applied to all new channels.
 	pub fn get_current_config(&self) -> UserConfig {
@@ -12814,6 +12875,7 @@ macro_rules! create_refund_builder { ($self: ident, $builder: ty) => {
 	}
 } }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -13669,6 +13731,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14010,6 +14073,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14045,6 +14109,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14106,6 +14171,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14606,6 +14672,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -15181,6 +15248,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -15400,6 +15468,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -15670,6 +15739,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -16185,6 +16255,7 @@ impl_writeable_tlv_based!(PendingInboundPayment, {
 	(8, min_value_msat, required),
 });
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -18122,6 +18193,7 @@ where
 
 			#[cfg(feature = "_test_utils")]
 			testing_dnssec_proof_offer_resolution_override: Mutex::new(new_hash_map()),
+			node_id: "?".to_string(),
 		};
 
 		let mut processed_claims: HashSet<Vec<MPPClaimHTLCSource>> = new_hash_set();

lightning/src/ln/functional_test_utils.rs

@@ -4572,7 +4572,7 @@ pub fn create_node_chanmgrs<'a, 'b>(
 		let network = Network::Testnet;
 		let genesis_block = bitcoin::constants::genesis_block(network);
 		let params = ChainParameters { network, best_block: BestBlock::from_network(network) };
-		let node = ChannelManager::new(
+		let mut node = ChannelManager::new(
 			cfgs[i].fee_estimator,
 			&cfgs[i].chain_monitor,
 			cfgs[i].tx_broadcaster,
@@ -4590,6 +4590,11 @@ pub fn create_node_chanmgrs<'a, 'b>(
 			params,
 			genesis_block.header.time,
 		);
+
+		// Here we give the node its id. This is used by the auto_span_methods proc macro to enter the span in every pub
+		// fn.
+		node.set_node_id(format!("{}", i));
+
 		chanmgrs.push(node);
 	}
 

lightning/src/ln/payment_tests.rs

@@ -46,13 +46,18 @@ use crate::types::features::{Bolt11InvoiceFeatures, ChannelTypeFeatures};
 use crate::types::payment::{PaymentHash, PaymentPreimage, PaymentSecret};
 use crate::types::string::UntrustedString;
 use crate::util::errors::APIError;
+use crate::util::logger::TracingToLogger;
 use crate::util::ser::Writeable;
-use crate::util::test_utils;
+use crate::util::test_utils::{self, HighlightLayer, TestTracerLayer};
+
+use tracing_subscriber::fmt::format::FmtSpan;
+use tracing_subscriber::{fmt, prelude::*, Registry};
 
 use bitcoin::hashes::sha256::Hash as Sha256;
 use bitcoin::hashes::Hash;
 use bitcoin::network::Network;
 use bitcoin::secp256k1::{Secp256k1, SecretKey};
+use tracing_tree::HierarchicalLayer;
 
 use crate::prelude::*;
 
@@ -61,6 +66,7 @@ use crate::ln::functional_test_utils::*;
 use crate::routing::gossip::NodeId;
 
 use core::cmp::Ordering;
+use std::sync::Arc;
 #[cfg(feature = "std")]
 use std::thread;
 
@@ -428,11 +434,24 @@ fn mpp_receive_timeout() {
 
 #[test]
 fn test_keysend_payments() {
+	let layer = HierarchicalLayer::new(3) // indent by 2 spaces
+		.with_ansi(true)
+		.with_targets(true)
+		.with_deferred_spans(true);
+	let subscriber = Registry::default().with(HighlightLayer).with(layer);
+	tracing::subscriber::set_global_default(subscriber).unwrap();
+
+	// tracing_subscriber::fmt()
+	// 	.with_max_level(tracing::Level::TRACE)
+	// 	.with_span_events(FmtSpan::FULL)
+	// 	.init();
+
 	do_test_keysend_payments(false);
-	do_test_keysend_payments(true);
+	// do_test_keysend_payments(true);
 }
 
 fn do_test_keysend_payments(public_node: bool) {
+	let span = tracing::info_span!("node setup").entered();
 	let chanmon_cfgs = create_chanmon_cfgs(2);
 	let node_cfgs = create_node_cfgs(2, &chanmon_cfgs);
 	let node_chanmgrs = create_node_chanmgrs(2, &node_cfgs, &[None, None]);
@@ -446,19 +465,26 @@ fn do_test_keysend_payments(public_node: bool) {
 	} else {
 		create_chan_between_nodes(&nodes[0], &nodes[1]);
 	}
+
+	drop(span);
+
 	let route_params = RouteParameters::from_payment_params_and_value(
 		PaymentParameters::for_keysend(node_b_id, 40, false),
 		10000,
 	);
 
 	{
+		let _span = tracing::info_span!("initiate payment").entered();
+
 		let preimage = Some(PaymentPreimage([42; 32]));
 		let onion = RecipientOnionFields::spontaneous_empty();
 		let retry = Retry::Attempts(1);
 		let id = PaymentId([42; 32]);
 		nodes[0].node.send_spontaneous_payment(preimage, onion, id, route_params, retry).unwrap();
 	}
 
+	let _span = tracing::info_span!("propagate htlc and claim payment").entered();
+
 	check_added_monitors!(nodes[0], 1);
 	let send_event = SendEvent::from_node(&nodes[0]);
 	nodes[1].node.handle_update_add_htlc(node_a_id, &send_event.msgs[0]);