From bfa3edd4925e9e7befd208effc4ba0bd24105b4e Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 16 Dec 2025 11:54:54 +0100 Subject: [PATCH 1/4] Add log spans using thread local storage in std --- lightning-macros/src/lib.rs | 44 +++++++++++++++- lightning/src/util/logger.rs | 84 ++++++++++++++++++++++++++++-- lightning/src/util/macro_logger.rs | 14 +++-- lightning/src/util/test_utils.rs | 23 ++++++++ 4 files changed, 158 insertions(+), 7 deletions(-) diff --git a/lightning-macros/src/lib.rs b/lightning-macros/src/lib.rs index e784acf72fb..81b7f8483db 100644 --- a/lightning-macros/src/lib.rs +++ b/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 = 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::(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() +} diff --git a/lightning/src/util/logger.rs b/lightning/src/util/logger.rs index b49cd32c131..b21310aaeb6 100644 --- a/lightning/src/util/logger.rs +++ b/lightning/src/util/logger.rs @@ -15,6 +15,7 @@ use bitcoin::secp256k1::PublicKey; +use core::cell::RefCell; use core::cmp; use core::fmt; use core::fmt::Display; @@ -130,6 +131,9 @@ pub struct Record<$($args)?> { /// Note that this is only filled in for logs pertaining to a specific payment, and will be /// `None` for logs which are not directly related to a payment. pub payment_hash: Option, + /// The names of the surrounding spans, if any. + #[cfg(feature = "std")] + pub spans: Vec<&'static str>, } impl<$($args)?> Record<$($args)?> { @@ -138,7 +142,10 @@ impl<$($args)?> Record<$($args)?> { /// This is not exported to bindings users as fmt can't be used in C #[inline] pub fn new<$($nonstruct_args)?>( - level: Level, peer_id: Option, channel_id: Option, + level: Level, + #[cfg(feature = "std")] + spans: Vec<&'static str>, + peer_id: Option, channel_id: Option, args: fmt::Arguments<'a>, module_path: &'static str, file: &'static str, line: u32, payment_hash: Option ) -> Record<$($args)?> { @@ -154,6 +161,8 @@ impl<$($args)?> Record<$($args)?> { file, line, payment_hash, + #[cfg(feature = "std")] + spans, } } } @@ -189,7 +198,20 @@ impl<$($args)?> Display for Record<$($args)?> { #[cfg(test)] { - write!(f, " {}", self.args)?; + write!(f, " ")?; + #[cfg(feature = "std")] + if !self.spans.is_empty() { + write!(f, "[")?; + for (i, span) in self.spans.iter().enumerate() { + if i > 0 { + write!(f, "->")?; + } + write!(f, "{}", span)?; + } + write!(f, "] ")?; + } + + write!(f, "{}", self.args)?; let mut open_bracket_written = false; if let Some(peer_id) = self.peer_id { @@ -384,14 +406,70 @@ impl + Clone> fmt::Display fo } } +#[cfg(feature = "std")] +thread_local! { + /// The thread-local stack of loggers. + pub static TLS_LOGGER: RefCell> = const { RefCell::new(Vec::new()) }; +} + +/// A scope which pushes a logger on a thread-local stack for the duration of the scope. +pub struct LoggerScope<'a> { + _marker: core::marker::PhantomData<&'a ()>, +} + +impl<'a> LoggerScope<'a> { + /// Pushes a logger onto the thread-local logger stack. + pub fn new(span: &'static str) -> Self { + #[cfg(feature = "std")] + TLS_LOGGER.with(|cell| { + let mut stack = cell.borrow_mut(); + stack.push(span); + }); + + LoggerScope { _marker: core::marker::PhantomData } + } +} + +impl<'a> Drop for LoggerScope<'a> { + fn drop(&mut self) { + #[cfg(feature = "std")] + TLS_LOGGER.with(|cell| { + let mut stack = cell.borrow_mut(); + stack.pop(); + }); + } +} + #[cfg(test)] mod tests { use crate::ln::types::ChannelId; use crate::sync::Arc; use crate::types::payment::PaymentHash; - use crate::util::logger::{Level, Logger, WithContext}; + use crate::util::logger::{Level, Logger, LoggerScope, WithContext}; use crate::util::test_utils::TestLogger; use bitcoin::secp256k1::{PublicKey, Secp256k1, SecretKey}; + use lightning_macros::log_scope; + + #[test] + fn logger_scope() { + let logger = TestLogger::new(); + let _scope = LoggerScope::new("test_logger_scope"); + log_info!(logger, "Info"); + } + + #[test] + #[log_scope(name = "test_logger_scope_proc_macro")] + fn logger_scope_proc_macro() { + let logger = TestLogger::new(); + log_info!(logger, "Info"); + } + + #[test] + #[log_scope] + fn logger_scope_proc_macro_no_name() { + let logger = TestLogger::new(); + log_info!(logger, "Info"); + } #[test] fn test_level_show() { diff --git a/lightning/src/util/macro_logger.rs b/lightning/src/util/macro_logger.rs index ec9eb14ba38..488431c2425 100644 --- a/lightning/src/util/macro_logger.rs +++ b/lightning/src/util/macro_logger.rs @@ -174,9 +174,17 @@ macro_rules! log_spendable { #[doc(hidden)] #[macro_export] macro_rules! log_given_level { - ($logger: expr, $lvl:expr, $($arg:tt)+) => ( - $logger.log($crate::util::logger::Record::new($lvl, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None)) - ); + ($logger: expr, $lvl:expr, $($arg:tt)+) => {{ + #[cfg(feature = "std")] + let spans = $crate::util::logger::TLS_LOGGER.with(|cell| { + cell.borrow().iter().map(|span| *span).collect() + }); + $logger.log($crate::util::logger::Record::new($lvl, + #[cfg(feature = "std")] + spans, + None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None + )); + }}; } /// Log at the `ERROR` level. diff --git a/lightning/src/util/test_utils.rs b/lightning/src/util/test_utils.rs index 50514e0a894..e32ba3db329 100644 --- a/lightning/src/util/test_utils.rs +++ b/lightning/src/util/test_utils.rs @@ -55,12 +55,15 @@ use crate::util::config::UserConfig; use crate::util::dyn_signer::{ DynKeysInterface, DynKeysInterfaceTrait, DynPhantomKeysInterface, DynSigner, }; +use crate::util::logger::LoggerScope; use crate::util::logger::{Logger, Record}; #[cfg(feature = "std")] use crate::util::mut_global::MutGlobal; use crate::util::persist::{KVStore, KVStoreSync, MonitorName}; use crate::util::ser::{Readable, ReadableArgs, Writeable, Writer}; use crate::util::test_channel_signer::{EnforcementState, TestChannelSigner}; +#[cfg(feature = "std")] +use std::cell::RefCell; use bitcoin::amount::Amount; use bitcoin::block::Block; @@ -1759,6 +1762,26 @@ impl Logger for TestLogger { } } +#[cfg(feature = "std")] +thread_local! { + pub(crate) static THREAD_LOG_SCOPE: RefCell>> = const { RefCell::new(None) }; +} + +/// Sets up a logging scope for the current thread with the given span name. This is useful to split up a long (test) function +/// into multiple scopes for easier log analysis. +#[macro_export] +macro_rules! test_scope { + ($span:expr) => { + #[cfg(feature = "std")] + $crate::util::test_utils::THREAD_LOG_SCOPE.with(|cell| { + // Drop old scope if it exists. + let _ = cell.borrow_mut().take(); + // Create new scope. + *cell.borrow_mut() = Some(crate::util::logger::LoggerScope::new($span)); + }); + }; +} + pub struct TestNodeSigner { node_secret: SecretKey, } From 1d1538a80f6a07b4cbbaf7f690e7adae7163f665 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 16 Dec 2025 12:26:45 +0100 Subject: [PATCH 2/4] Add log_scope to channelmanager --- lightning/src/ln/channelmanager.rs | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs index f2e8fa70e4f..e3177dd1854 100644 --- a/lightning/src/ln/channelmanager.rs +++ b/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 lightning_macros::log_scope; use crate::blinded_path::message::{ AsyncPaymentsContext, BlindedMessagePath, MessageForwardNode, OffersContext, @@ -4280,6 +4281,7 @@ where /// [`ChannelCloseMinimum`]: crate::chain::chaininterface::ConfirmationTarget::ChannelCloseMinimum /// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee /// [`SendShutdown`]: MessageSendEvent::SendShutdown + #[log_scope] pub fn close_channel( &self, channel_id: &ChannelId, counterparty_node_id: &PublicKey, ) -> Result<(), APIError> { @@ -4316,6 +4318,7 @@ where /// [`NonAnchorChannelFee`]: crate::chain::chaininterface::ConfirmationTarget::NonAnchorChannelFee /// [`ChannelHandshakeConfig::commit_upfront_shutdown_pubkey`]: crate::util::config::ChannelHandshakeConfig::commit_upfront_shutdown_pubkey /// [`SendShutdown`]: MessageSendEvent::SendShutdown + #[log_scope] pub fn close_channel_with_feerate_and_script( &self, channel_id: &ChannelId, counterparty_node_id: &PublicKey, target_feerate_sats_per_1000_weight: Option, shutdown_script: Option, @@ -4591,6 +4594,7 @@ where /// /// Fails if `channel_id` is unknown to the manager, or if the `counterparty_node_id` /// isn't the counterparty of the corresponding channel. + #[log_scope] pub fn force_close_broadcasting_latest_txn( &self, channel_id: &ChannelId, counterparty_node_id: &PublicKey, error_message: String, ) -> Result<(), APIError> { @@ -4602,6 +4606,7 @@ where /// /// The provided `error_message` is sent to connected peers for closing channels and should /// be a human-readable description of what went wrong. + #[log_scope] pub fn force_close_all_channels_broadcasting_latest_txn(&self, error_message: String) { for chan in self.list_channels() { let _ = self.force_close_broadcasting_latest_txn( @@ -4881,6 +4886,7 @@ where /// emitted with the new funding output. At this point, a new splice can be negotiated by /// calling `splice_channel` again on this channel. #[rustfmt::skip] + #[log_scope] pub fn splice_channel( &self, channel_id: &ChannelId, counterparty_node_id: &PublicKey, contribution: SpliceContribution, funding_feerate_per_kw: u32, locktime: Option, @@ -5531,6 +5537,7 @@ where /// LDK will not automatically retry this payment, though it may be manually re-sent after an /// [`Event::PaymentFailed`] is generated. #[rustfmt::skip] + #[log_scope] pub fn send_payment_with_route( &self, mut route: Route, payment_hash: PaymentHash, recipient_onion: RecipientOnionFields, payment_id: PaymentId @@ -5591,6 +5598,7 @@ where /// [`UpdateHTLCs`]: MessageSendEvent::UpdateHTLCs /// [`PeerManager::process_events`]: crate::ln::peer_handler::PeerManager::process_events /// [`ChannelMonitorUpdateStatus::InProgress`]: crate::chain::ChannelMonitorUpdateStatus::InProgress + #[log_scope] pub fn send_payment( &self, payment_hash: PaymentHash, recipient_onion: RecipientOnionFields, payment_id: PaymentId, route_params: RouteParameters, retry_strategy: Retry, @@ -5689,6 +5697,7 @@ where /// # Custom Routing Parameters /// Users can customize routing parameters via [`RouteParametersConfig`]. /// To use default settings, call the function with [`RouteParametersConfig::default`]. + #[log_scope] pub fn pay_for_bolt11_invoice( &self, invoice: &Bolt11Invoice, payment_id: PaymentId, amount_msats: Option, route_params_config: RouteParametersConfig, retry_strategy: Retry, @@ -5732,6 +5741,7 @@ where /// whether or not the payment was successful. /// /// [timer tick]: Self::timer_tick_occurred + #[log_scope] pub fn send_payment_for_bolt12_invoice( &self, invoice: &Bolt12Invoice, context: Option<&OffersContext>, ) -> Result<(), Bolt12PaymentError> { @@ -6004,6 +6014,7 @@ where /// [`ChannelManager`], another [`Event::PaymentFailed`] may be generated. /// /// [`Bolt12Invoice`]: crate::offers::invoice::Bolt12Invoice + #[log_scope] pub fn abandon_payment(&self, payment_id: PaymentId) { self.abandon_payment_with_reason(payment_id, PaymentFailureReason::UserAbandoned) } @@ -6030,6 +6041,7 @@ where /// /// [`send_payment`]: Self::send_payment /// [`PaymentParameters::for_keysend`]: crate::routing::router::PaymentParameters::for_keysend + #[log_scope] pub fn send_spontaneous_payment( &self, payment_preimage: Option, recipient_onion: RecipientOnionFields, payment_id: PaymentId, route_params: RouteParameters, retry_strategy: Retry, @@ -6056,6 +6068,7 @@ where /// Send a payment that is probing the given route for liquidity. We calculate the /// [`PaymentHash`] of probes based on a static secret and a random [`PaymentId`], which allows /// us to easily discern them from real payments. + #[log_scope] pub fn send_probe(&self, path: Path) -> Result<(PaymentHash, PaymentId), ProbeSendFailure> { let best_block_height = self.best_block.read().unwrap().height; let _persistence_guard = PersistenceNotifierGuard::notify_on_drop(self); @@ -6082,6 +6095,7 @@ where /// amount to the given `node_id`. /// /// See [`ChannelManager::send_preflight_probes`] for more information. + #[log_scope] pub fn send_spontaneous_preflight_probes( &self, node_id: PublicKey, amount_msat: u64, final_cltv_expiry_delta: u32, liquidity_limit_multiplier: Option, @@ -6108,6 +6122,7 @@ where /// payment. To mitigate this issue, channels with available liquidity less than the required /// amount times the given `liquidity_limit_multiplier` won't be used to send pre-flight /// probes. If `None` is given as `liquidity_limit_multiplier`, it defaults to `3`. + #[log_scope] pub fn send_preflight_probes( &self, route_params: RouteParameters, liquidity_limit_multiplier: Option, ) -> Result, ProbeSendFailure> { @@ -7277,6 +7292,7 @@ where /// /// Users implementing their own background processing logic should call this in irregular, /// randomly-distributed intervals. + #[log_scope] pub fn process_pending_htlc_forwards(&self) { if self .pending_htlc_forwards_processor @@ -8307,6 +8323,7 @@ where /// /// [`ChannelUpdate`]: msgs::ChannelUpdate /// [`ChannelConfig`]: crate::util::config::ChannelConfig + #[log_scope] pub fn timer_tick_occurred(&self) { PersistenceNotifierGuard::optionally_notify(self, || { let mut should_persist = NotifyOption::SkipPersistNoEvents; @@ -8840,6 +8857,7 @@ where /// [`create_inbound_payment`]: Self::create_inbound_payment /// [`create_inbound_payment_for_hash`]: Self::create_inbound_payment_for_hash /// [`claim_funds_with_known_custom_tlvs`]: Self::claim_funds_with_known_custom_tlvs + #[log_scope] pub fn claim_funds(&self, payment_preimage: PaymentPreimage) { self.claim_payment_internal(payment_preimage, false); } @@ -8853,6 +8871,7 @@ where /// claim, otherwise you may unintentionally agree to some protocol you do not understand. /// /// [`claim_funds`]: Self::claim_funds + #[log_scope] pub fn claim_funds_with_known_custom_tlvs(&self, payment_preimage: PaymentPreimage) { self.claim_payment_internal(payment_preimage, true); } @@ -10089,6 +10108,7 @@ This indicates a bug inside LDK. Please report this error at https://github.com/ /// /// [`Event::OpenChannelRequest`]: events::Event::OpenChannelRequest /// [`Event::ChannelClosed::user_channel_id`]: events::Event::ChannelClosed::user_channel_id + #[log_scope] pub fn accept_inbound_channel( &self, temporary_channel_id: &ChannelId, counterparty_node_id: &PublicKey, user_channel_id: u128, config_overrides: Option, @@ -13300,6 +13320,7 @@ where /// [`BlindedMessagePath`]: crate::blinded_path::message::BlindedMessagePath /// [`Bolt12Invoice::payment_paths`]: crate::offers::invoice::Bolt12Invoice::payment_paths /// [Avoiding Duplicate Payments]: #avoiding-duplicate-payments + #[log_scope] pub fn pay_for_offer( &self, offer: &Offer, amount_msats: Option, payment_id: PaymentId, optional_params: OptionalOfferPaymentParams, @@ -13329,6 +13350,7 @@ where /// Pays for an [`Offer`] which was built by resolving a human readable name. It is otherwise /// identical to [`Self::pay_for_offer`]. + #[log_scope] pub fn pay_for_offer_from_hrn( &self, offer: &OfferFromHrn, amount_msats: u64, payment_id: PaymentId, optional_params: OptionalOfferPaymentParams, @@ -13371,6 +13393,7 @@ where /// [`InvoiceRequest`]: crate::offers::invoice_request::InvoiceRequest /// [`Bolt12Invoice`]: crate::offers::invoice::Bolt12Invoice /// [`InvoiceRequest::quantity`]: crate::offers::invoice_request::InvoiceRequest::quantity + #[log_scope] pub fn pay_for_offer_with_quantity( &self, offer: &Offer, amount_msats: Option, payment_id: PaymentId, optional_params: OptionalOfferPaymentParams, quantity: u64, @@ -13532,6 +13555,7 @@ where /// [`PaymentFailureReason::InvoiceRequestRejected`]: crate::events::PaymentFailureReason::InvoiceRequestRejected #[cfg(feature = "dnssec")] #[deprecated(note = "Use bitcoin-payment-instructions and pay_for_offer_from_hrn instead")] + #[log_scope] pub fn pay_for_offer_from_human_readable_name( &self, name: HumanReadableName, amount_msats: u64, payment_id: PaymentId, optional_params: OptionalOfferPaymentParams, dns_resolvers: Vec, @@ -13833,6 +13857,7 @@ where } #[cfg(any(test, feature = "_test_utils"))] + #[log_scope] pub fn get_and_clear_pending_events(&self) -> Vec { let events = core::cell::RefCell::new(Vec::new()); let event_handler = |event: events::Event| Ok(events.borrow_mut().push(event)); From b699c1200186c98cec2be4c08a018d2340825e60 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 16 Dec 2025 16:45:53 +0100 Subject: [PATCH 3/4] Add test logger scope --- lightning/src/ln/chanmon_update_fail_tests.rs | 26 ++++++++++++++++++- 1 file changed, 25 insertions(+), 1 deletion(-) diff --git a/lightning/src/ln/chanmon_update_fail_tests.rs b/lightning/src/ln/chanmon_update_fail_tests.rs index 57f0ca87d45..0c4ebf27cff 100644 --- a/lightning/src/ln/chanmon_update_fail_tests.rs +++ b/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); From c3714c6ec8c72b1fb2c21eb5dead985294e0a9fb Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Thu, 18 Dec 2025 11:22:43 +0100 Subject: [PATCH 4/4] Monitor update logger scopes --- lightning/src/ln/channelmanager.rs | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs index e3177dd1854..871a3bac850 100644 --- a/lightning/src/ln/channelmanager.rs +++ b/lightning/src/ln/channelmanager.rs @@ -3474,6 +3474,8 @@ macro_rules! handle_post_close_monitor_update { $self: ident, $funding_txo: expr, $update: expr, $peer_state_lock: expr, $peer_state: expr, $per_peer_state_lock: expr, $counterparty_node_id: expr, $channel_id: expr ) => {{ + let _scope = crate::util::logger::LoggerScope::new("handle_post_close_monitor_update"); + let (update_completed, all_updates_complete) = handle_new_monitor_update_internal( $self, &mut $peer_state.in_flight_monitor_updates, @@ -3511,6 +3513,10 @@ macro_rules! handle_new_monitor_update_locked_actions_handled_by_caller { ( $self: ident, $funding_txo: expr, $update: expr, $in_flight_monitor_updates: expr, $chan_context: expr ) => {{ + let _scope = crate::util::logger::LoggerScope::new( + "handle_new_monitor_update_locked_actions_handled_by_caller", + ); + let (update_completed, _all_updates_complete) = handle_new_monitor_update_internal( $self, $in_flight_monitor_updates, @@ -3529,6 +3535,8 @@ macro_rules! handle_new_monitor_update { $self: ident, $funding_txo: expr, $update: expr, $peer_state_lock: expr, $peer_state: expr, $per_peer_state_lock: expr, $chan: expr ) => {{ + let _scope = crate::util::logger::LoggerScope::new("handle_new_monitor_update"); + let (update_completed, all_updates_complete) = handle_new_monitor_update_internal( $self, &mut $peer_state.in_flight_monitor_updates,