Add log spans using thread local storage in std

lightning-macros/src/lib.rs

@@ -20,12 +20,13 @@
 
 extern crate alloc;
 
+use alloc::string::String;
 use alloc::string::ToString;
 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, parse2, Expr, ExprLit, ImplItemFn, Lit, Token};
 use syn::{parse_macro_input, Item};
 
 fn add_async_method(mut parsed: ImplItemFn) -> TokenStream {
@@ -400,3 +401,44 @@ pub fn xtest_inventory(_input: TokenStream) -> TokenStream {
 
 	TokenStream::from(expanded)
 }
+
+/// Adds a logging scope at the top of a method.
+#[proc_macro_attribute]
+pub fn log_scope(attrs: TokenStream, meth: TokenStream) -> TokenStream {
+	let attrs: TokenStream2 = parse_macro_input!(attrs as TokenStream2);
+	let mut name_attr: Option<String> = None;
+	if !attrs.is_empty() {
+		// Expect something like `name = "foo"`
+		let expr: Expr = parse2(attrs.clone()).expect("invalid attribute syntax");
+
+		if let Expr::Assign(assign) = expr {
+			// Check left-hand side is `name`.
+			if let Expr::Path(path) = *assign.left {
+				if path.path.is_ident("name") {
+					if let Expr::Lit(ExprLit { lit: Lit::Str(s), .. }) = *assign.right {
+						name_attr = Some(s.value());
+					}
+				}
+			}
+		}
+	}
+
+	let mut meth = if let Ok(parsed) = parse::<syn::ItemFn>(meth) {
+		parsed
+	} else {
+		return (quote! {
+			compile_error!("log_scope can only be set on methods")
+		})
+		.into();
+	};
+
+	// Use the attribute name if present, otherwise fall back to the function name
+	let name = name_attr.unwrap_or_else(|| meth.sig.ident.to_string());
+
+	let stmt = quote! {
+		let _logging_context = crate::util::logger::LoggerScope::new(#name);
+	};
+
+	meth.block.stmts.insert(0, parse(stmt.into()).unwrap());
+	quote! { #meth }.into()
+}

lightning/src/ln/chanmon_update_fail_tests.rs

@@ -44,8 +44,8 @@ use crate::ln::functional_test_utils::*;
 
 use crate::util::test_utils;
 
-use crate::prelude::*;
 use crate::sync::{Arc, Mutex};
+use crate::{prelude::*, test_scope};
 use bitcoin::hashes::Hash;
 
 fn get_latest_mon_update_id<'a, 'b, 'c>(
@@ -3772,6 +3772,8 @@ fn test_inverted_mon_completion_order() {
 fn do_test_durable_preimages_on_closed_channel(
 	close_chans_before_reload: bool, close_only_a: bool, hold_post_reload_mon_update: bool,
 ) {
+	test_scope!("Setup");
+
 	// Test that we can apply a `ChannelMonitorUpdate` with a payment preimage even if the channel
 	// is force-closed between when we generate the update on reload and when we go to handle the
 	// update or prior to generating the update at all.
@@ -3798,6 +3800,8 @@ fn do_test_durable_preimages_on_closed_channel(
 	let chan_id_ab = create_announced_chan_between_nodes(&nodes, 0, 1).2;
 	let chan_id_bc = create_announced_chan_between_nodes(&nodes, 1, 2).2;
 
+	test_scope!("Route payment");
+
 	// Route a payment from A, through B, to C, then claim it on C. Once we pass B the
 	// `update_fulfill_htlc` we have a monitor update for both of B's channels. We complete the one
 	// on the B<->C channel but leave the A<->B monitor update pending, then reload B.
@@ -3810,6 +3814,8 @@ fn do_test_durable_preimages_on_closed_channel(
 	check_added_monitors(&nodes[2], 1);
 	expect_payment_claimed!(nodes[2], payment_hash, 1_000_000);
 
+	test_scope!("Handle fulfill from C to B");
+
 	chanmon_cfgs[1].persister.set_update_ret(ChannelMonitorUpdateStatus::InProgress);
 	let mut cs_updates = get_htlc_update_msgs(&nodes[2], &node_b_id);
 	nodes[1].node.handle_update_fulfill_htlc(node_c_id, cs_updates.update_fulfill_htlcs.remove(0));
@@ -3822,6 +3828,8 @@ fn do_test_durable_preimages_on_closed_channel(
 	// Now step the Commitment Signed Dance between B and C forward a bit, ensuring we won't get
 	// the preimage when the nodes reconnect, at which point we have to ensure we get it from the
 	// ChannelMonitor.
+	test_scope!("Step commitment_signed from B to C forward");
+
 	nodes[1].node.handle_commitment_signed_batch_test(node_c_id, &cs_updates.commitment_signed);
 	check_added_monitors(&nodes[1], 1);
 	let _ = get_revoke_commit_msgs(&nodes[1], &node_c_id);
@@ -3830,6 +3838,8 @@ fn do_test_durable_preimages_on_closed_channel(
 
 	if close_chans_before_reload {
 		if !close_only_a {
+			test_scope!("Force close B<->C channel");
+
 			chanmon_cfgs[1].persister.set_update_ret(ChannelMonitorUpdateStatus::InProgress);
 			let message = "Channel force-closed".to_owned();
 			nodes[1]
@@ -3842,6 +3852,8 @@ fn do_test_durable_preimages_on_closed_channel(
 			check_closed_event(&nodes[1], 1, reason, &[node_c_id], 100000);
 		}
 
+		test_scope!("Force close A<->B channel");
+
 		chanmon_cfgs[1].persister.set_update_ret(ChannelMonitorUpdateStatus::InProgress);
 		let message = "Channel force-closed".to_owned();
 		nodes[1]
@@ -3854,6 +3866,8 @@ fn do_test_durable_preimages_on_closed_channel(
 		check_closed_event(&nodes[1], 1, reason, &[node_a_id], 100000);
 	}
 
+	test_scope!("Reload");
+
 	// Now reload node B
 	let manager_b = nodes[1].node.encode();
 	reload_node!(nodes[1], &manager_b, &[&mon_ab, &mon_bc], persister, chain_mon, node_b_reload);
@@ -3871,6 +3885,8 @@ fn do_test_durable_preimages_on_closed_channel(
 		}
 	}
 
+	test_scope!("Force close A<->B channel from A");
+
 	let err_msg = "Channel force-closed".to_owned();
 	let reason = ClosureReason::HolderForceClosed {
 		broadcasted_latest_txn: Some(true),
@@ -3889,6 +3905,8 @@ fn do_test_durable_preimages_on_closed_channel(
 
 	// After a timer tick a payment preimage ChannelMonitorUpdate is applied to the A<->B
 	// ChannelMonitor (possible twice), even though the channel has since been closed.
+	test_scope!("Timer tick to apply preimage monitor update");
+
 	check_added_monitors(&nodes[1], 0);
 	let mons_added = if close_chans_before_reload {
 		if !close_only_a {
@@ -3913,6 +3931,8 @@ fn do_test_durable_preimages_on_closed_channel(
 	check_added_monitors(&nodes[1], mons_added);
 
 	// Finally, check that B created a payment preimage transaction and close out the payment.
+	test_scope!("Check preimage txn and complete payment");
+
 	let bs_txn = nodes[1].tx_broadcaster.txn_broadcasted.lock().unwrap().split_off(0);
 	assert_eq!(bs_txn.len(), if close_chans_before_reload && !close_only_a { 2 } else { 1 });
 	let bs_preimage_tx = bs_txn
@@ -3926,6 +3946,7 @@ fn do_test_durable_preimages_on_closed_channel(
 	expect_payment_sent(&nodes[0], payment_preimage, None, true, true);
 
 	if !close_chans_before_reload || close_only_a {
+		test_scope!("Reconnect nodes B and C");
 		// Make sure the B<->C channel is still alive and well by sending a payment over it.
 		let mut reconnect_args = ReconnectArgs::new(&nodes[1], &nodes[2]);
 		reconnect_args.pending_responding_commitment_signed.1 = true;
@@ -3940,6 +3961,7 @@ fn do_test_durable_preimages_on_closed_channel(
 
 	// Once the blocked `ChannelMonitorUpdate` *finally* completes, the pending
 	// `PaymentForwarded` event will finally be released.
+	test_scope!("Complete blocked ChannelMonitorUpdate");
 	let (_, ab_update_id) = get_latest_mon_update_id(&nodes[1], chan_id_ab);
 	nodes[1].chain_monitor.chain_monitor.force_channel_monitor_updated(chan_id_ab, ab_update_id);
 
@@ -3957,6 +3979,8 @@ fn do_test_durable_preimages_on_closed_channel(
 	if !close_chans_before_reload || close_only_a {
 		// Once we call `process_pending_events` the final `ChannelMonitor` for the B<->C channel
 		// will fly, removing the payment preimage from it.
+		test_scope!("Process pending events to complete B<->C monitor update");
+
 		check_added_monitors(&nodes[1], 1);
 		assert!(nodes[1].node.get_and_clear_pending_events().is_empty());
 		send_payment(&nodes[1], &[&nodes[2]], 100_000);