tracing poc

Author: joostjager

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 {
+			if let Visibility::Public(_) = method.vis {
+				// 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;
+					method.block = syn::parse_quote!({
+						let _entered_span = self.node_span.enter();
+						#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,8 @@ 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"
 
 [dev-dependencies]
 regex = "1.5.6"

lightning/src/ln/channelmanager.rs

@@ -2927,6 +2927,8 @@ pub struct ChannelManager<
 	signer_provider: SP,
 
 	logger: L,
+
+	node_span: tracing::Span,
 }
 
 /// Chain-related parameters used to construct a new `ChannelManager`.
@@ -3926,6 +3928,7 @@ macro_rules! process_events_body {
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -4043,9 +4046,15 @@ where
 
 			#[cfg(feature = "_test_utils")]
 			testing_dnssec_proof_offer_resolution_override: Mutex::new(new_hash_map()),
+
+			node_span: tracing::span!(tracing::Level::INFO, "node"),
 		}
 	}
 
+	pub fn set_node_id(&mut self, id: String) {
+		self.node_span = tracing::span!(tracing::Level::INFO, "node", 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 {
@@ -4125,7 +4134,10 @@ where
 	/// [`Event::FundingGenerationReady::temporary_channel_id`]: events::Event::FundingGenerationReady::temporary_channel_id
 	/// [`Event::ChannelClosed::channel_id`]: events::Event::ChannelClosed::channel_id
 	#[rustfmt::skip]
+	// #[tracing::instrument(parent = &self.node_span, skip(self))]
 	pub fn create_channel(&self, their_network_key: PublicKey, channel_value_satoshis: u64, push_msat: u64, user_channel_id: u128, temporary_channel_id: Option<ChannelId>, override_config: Option<UserConfig>) -> Result<ChannelId, APIError> {
+		tracing::info!("create_channel called");
+
 		if channel_value_satoshis < 1000 {
 			return Err(APIError::APIMisuseError { err: format!("Channel value must be at least 1000 satoshis. It was {}", channel_value_satoshis) });
 		}
@@ -18122,6 +18134,7 @@ where
 
 			#[cfg(feature = "_test_utils")]
 			testing_dnssec_proof_offer_resolution_override: Mutex::new(new_hash_map()),
+			node_span: tracing::span!(tracing::Level::INFO, "node"),
 		};
 
 		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,9 @@ pub fn create_node_chanmgrs<'a, 'b>(
 			params,
 			genesis_block.header.time,
 		);
+
+		node.set_node_id(format!("{}", i));
+
 		chanmgrs.push(node);
 	}
 

lightning/src/ln/payment_tests.rs

@@ -46,8 +46,12 @@ 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, TestTracerLayer};
+
+use tracing_subscriber::fmt::format::FmtSpan;
+use tracing_subscriber::{fmt, prelude::*};
 
 use bitcoin::hashes::sha256::Hash as Sha256;
 use bitcoin::hashes::Hash;
@@ -61,6 +65,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 +433,25 @@ fn mpp_receive_timeout() {
 
 #[test]
 fn test_keysend_payments() {
+	// tracing_subscriber::fmt().init();
+	// tracing_subscriber::fmt()
+	// 	//		.with_span_list(true) // <--- print parent span chain
+	// 	.with_span_events(FmtSpan::FULL)
+	// 	.init();
+
 	do_test_keysend_payments(false);
 	do_test_keysend_payments(true);
 }
 
 fn do_test_keysend_payments(public_node: bool) {
+	let layer = TestTracerLayer {};
+	let subscriber = tracing_subscriber::registry().with(layer);
+	let _guard = tracing::subscriber::set_default(subscriber);
+	{
+		let _enter = tracing::info_span!("hello").entered();
+		tracing::info!("Hello from tracing!");
+	}
+
 	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]);

lightning/src/util/logger.rs

@@ -14,6 +14,11 @@
 //! [`Level`] field. Each module may have its own Logger or share one.
 
 use bitcoin::secp256k1::PublicKey;
+use tracing::Event;
+use tracing::Subscriber;
+use tracing_subscriber::layer::Context;
+use tracing_subscriber::registry::LookupSpan;
+use tracing_subscriber::Layer;
 
 use core::cmp;
 use core::fmt;
@@ -261,6 +266,81 @@ impl<T: fmt::Display, I: core::iter::Iterator<Item = T> + Clone> fmt::Display fo
 	}
 }
 
+/// A tracing `Layer` that forwards tracing events to a given `Logger`.
+pub struct TracingToLogger<L: Deref>
+where
+	L::Target: Logger,
+{
+	logger: L,
+}
+
+impl<L: Deref> TracingToLogger<L>
+where
+	L::Target: Logger,
+{
+	pub fn new(logger: L) -> Self {
+		Self { logger }
+	}
+}
+
+impl<S, L> Layer<S> for TracingToLogger<L>
+where
+	S: Subscriber + for<'lookup> LookupSpan<'lookup>,
+	L: Deref + 'static,
+	L::Target: Logger,
+{
+	fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
+		let meta = event.metadata();
+		let level = *meta.level();
+
+		// Extract the "message" field from the event
+		let mut visitor = MessageVisitor::new();
+		event.record(&mut visitor);
+		let message = visitor.message.unwrap_or_else(|| "<no message>".to_string());
+
+		self.logger.log(Record::new(
+			match level {
+				tracing::Level::ERROR => Level::Error,
+				tracing::Level::WARN => Level::Warn,
+				tracing::Level::INFO => Level::Info,
+				tracing::Level::DEBUG => Level::Debug,
+				tracing::Level::TRACE => Level::Trace,
+			},
+			None,
+			None,
+			format_args!("{}", message),
+			meta.module_path().unwrap_or("<unknown>"),
+			meta.file().unwrap_or("<unknown>"),
+			meta.line().unwrap_or(0),
+			None,
+		));
+	}
+}
+
+struct MessageVisitor {
+	message: Option<String>,
+}
+
+impl MessageVisitor {
+	fn new() -> Self {
+		Self { message: None }
+	}
+}
+
+impl tracing::field::Visit for MessageVisitor {
+	fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn fmt::Debug) {
+		if field.name() == "message" {
+			self.message = Some(format!("{:?}", value));
+		}
+	}
+
+	fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
+		if field.name() == "message" {
+			self.message = Some(value.to_string());
+		}
+	}
+}
+
 #[cfg(test)]
 mod tests {
 	use crate::ln::types::ChannelId;

lightning/src/util/macro_logger.rs

@@ -183,39 +183,39 @@ macro_rules! log_given_level {
 #[macro_export]
 macro_rules! log_error {
 	($logger: expr, $($arg:tt)*) => (
-		$crate::log_given_level!($logger, $crate::util::logger::Level::Error, $($arg)*);
+		tracing::error!($($arg)*);
 	)
 }
 
 /// Log at the `WARN` level.
 #[macro_export]
 macro_rules! log_warn {
 	($logger: expr, $($arg:tt)*) => (
-		$crate::log_given_level!($logger, $crate::util::logger::Level::Warn, $($arg)*);
+		tracing::warn!($($arg)*);
 	)
 }
 
 /// Log at the `INFO` level.
 #[macro_export]
 macro_rules! log_info {
 	($logger: expr, $($arg:tt)*) => (
-		$crate::log_given_level!($logger, $crate::util::logger::Level::Info, $($arg)*);
+		tracing::info!($($arg)*);
 	)
 }
 
 /// Log at the `DEBUG` level.
 #[macro_export]
 macro_rules! log_debug {
 	($logger: expr, $($arg:tt)*) => (
-		$crate::log_given_level!($logger, $crate::util::logger::Level::Debug, $($arg)*);
+		tracing::debug!($($arg)*);
 	)
 }
 
 /// Log at the `TRACE` level.
 #[macro_export]
 macro_rules! log_trace {
 	($logger: expr, $($arg:tt)*) => (
-		$crate::log_given_level!($logger, $crate::util::logger::Level::Trace, $($arg)*)
+		tracing::trace!($($arg)*);
 	)
 }