wip

Author: joostjager

lightning-macros/src/lib.rs

@@ -408,19 +408,18 @@ pub fn auto_span_methods(_attr: TokenStream, item: TokenStream) -> TokenStream {
 
 	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;
-				}
+			// 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
-					});
-				}
+			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 _entered_span = tracing::span!(tracing::Level::INFO, #method_name, node_id = self.node_id).entered();
+					#block
+				});
 			}
 		}
 	}

lightning/Cargo.toml

@@ -52,6 +52,7 @@ 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

@@ -2928,7 +2928,7 @@ pub struct ChannelManager<
 
 	logger: L,
 
-	node_span: tracing::Span,
+	node_id: String,
 }
 
 /// Chain-related parameters used to construct a new `ChannelManager`.
@@ -4047,12 +4047,12 @@ where
 			#[cfg(feature = "_test_utils")]
 			testing_dnssec_proof_offer_resolution_override: Mutex::new(new_hash_map()),
 
-			node_span: tracing::span!(tracing::Level::INFO, "node"),
+			node_id : "?".to_string(),
 		}
 	}
 
 	pub fn set_node_id(&mut self, id: String) {
-		self.node_span = tracing::span!(tracing::Level::INFO, "node", node_id = id);
+		self.node_id = id;
 	}
 
 	/// Gets the current [`UserConfig`] which controls some global behavior and includes the
@@ -4135,8 +4135,6 @@ where
 	/// [`Event::ChannelClosed::channel_id`]: events::Event::ChannelClosed::channel_id
 	#[rustfmt::skip]
 	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) });
 		}
@@ -12825,6 +12823,7 @@ macro_rules! create_refund_builder { ($self: ident, $builder: ty) => {
 	}
 } }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -13680,6 +13679,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14021,6 +14021,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14056,6 +14057,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14117,6 +14119,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -14617,6 +14620,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -15192,6 +15196,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -15411,6 +15416,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -15681,6 +15687,7 @@ where
 	}
 }
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -16196,6 +16203,7 @@ impl_writeable_tlv_based!(PendingInboundPayment, {
 	(8, min_value_msat, required),
 });
 
+#[lightning_macros::auto_span_methods]
 impl<
 		M: Deref,
 		T: Deref,
@@ -18133,7 +18141,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"),
+			node_id: "?".to_string(),
 		};
 
 		let mut processed_claims: HashSet<Vec<MPPClaimHTLCSource>> = new_hash_set();

lightning/src/ln/payment_tests.rs

@@ -51,12 +51,13 @@ use crate::util::ser::Writeable;
 use crate::util::test_utils::{self, TestTracerLayer};
 
 use tracing_subscriber::fmt::format::FmtSpan;
-use tracing_subscriber::{fmt, prelude::*};
+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::*;
 
@@ -433,9 +434,17 @@ fn mpp_receive_timeout() {
 
 #[test]
 fn test_keysend_payments() {
-	// tracing_subscriber::fmt().init();
+	let layer = HierarchicalLayer::new(5) // indent by 2 spaces
+		.with_ansi(true)
+		.with_targets(true)
+		.with_deferred_spans(true);
+	//.with_indent_lines(true);
+
+	let subscriber = Registry::default().with(layer);
+	tracing::subscriber::set_global_default(subscriber).unwrap();
+
 	// tracing_subscriber::fmt()
-	// 	//		.with_span_list(true) // <--- print parent span chain
+	// 	.with_max_level(tracing::Level::TRACE)
 	// 	.with_span_events(FmtSpan::FULL)
 	// 	.init();
 
@@ -444,14 +453,7 @@ fn test_keysend_payments() {
 }
 
 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 span = tracing::info_span!("node setup");
 	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]);
@@ -465,19 +467,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]);