From d7a7cf0b69666c7df5e19c6c1a419b567e959555 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Wed, 3 Dec 2025 12:41:06 +0100 Subject: [PATCH 1/3] Add logging using a thread-local instance --- lightning-macros/src/lib.rs | 46 ++++++++++++++- lightning/src/util/logger.rs | 93 +++++++++++++++++++++++++++++- lightning/src/util/macro_logger.rs | 60 ++++++++++++++++++- 3 files changed, 193 insertions(+), 6 deletions(-) diff --git a/lightning-macros/src/lib.rs b/lightning-macros/src/lib.rs index e784acf72fb..3be99d60dc1 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,46 @@ 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 name = name_attr.unwrap(); + + let mut meth = if let Ok(parsed) = parse::(meth) { + parsed + } else { + return (quote! { + compile_error!("log_scope can only be set on methods") + }) + .into(); + }; + + let init_stmt1 = quote! { + let _logger_wrapper = crate::util::logger::LoggerWrapper(&self.logger); + }; + let init_stmt2 = quote! { + let _logging_context = crate::util::logger::LoggerScope::new(&_logger_wrapper, #name); + }; + + meth.block.stmts.insert(0, parse(init_stmt2.into()).unwrap()); + meth.block.stmts.insert(0, parse(init_stmt1.into()).unwrap()); + quote! { #meth }.into() +} diff --git a/lightning/src/util/logger.rs b/lightning/src/util/logger.rs index b49cd32c131..3252aa11795 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,11 @@ 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. + /// + /// TODO: Use fixed size array to avoid allocations? + pub spans: Vec<&'static str>, } impl<$($args)?> Record<$($args)?> { @@ -138,7 +144,7 @@ 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, 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 +160,7 @@ impl<$($args)?> Record<$($args)?> { file, line, payment_hash, + spans, } } } @@ -189,9 +196,22 @@ impl<$($args)?> Display for Record<$($args)?> { #[cfg(test)] { - write!(f, " {}", self.args)?; + write!(f, " ")?; + 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 { write!(f, " [")?; open_bracket_written = true; @@ -384,15 +404,82 @@ impl + Clone> fmt::Display fo } } +/// A wrapper to allow getting a dyn Logger from a deref type. +/// +/// TODO: Propagate up the dyn Logger type to avoid this wrapper. +pub struct LoggerWrapper<'a, L: Deref>(pub &'a L) +where + L::Target: Logger; + +impl<'a, L: Deref> Logger for LoggerWrapper<'a, L> +where + L::Target: Logger, +{ + fn log(&self, record: Record) { + self.0.log(record) + } +} + +/// A span in the TLS logger stack. +pub struct Span { + /// The Logger instance for this span. + pub logger: &'static dyn Logger, + + /// The name of this span. + pub name: &'static str, +} + +thread_local! { + /// The thread-local stack of loggers. + pub static TLS_LOGGER: RefCell> = 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: std::marker::PhantomData<&'a ()>, +} + +impl<'a> LoggerScope<'a> { + /// Pushes a logger onto the thread-local logger stack. + pub fn new(logger: &'a dyn Logger, span: &'static str) -> Self { + TLS_LOGGER.with(|cell| { + let mut stack = cell.borrow_mut(); + + let logger_ref_static: &'static dyn Logger = + unsafe { std::mem::transmute::<&'a dyn Logger, &'static dyn Logger>(logger) }; + + stack.push(Span { logger: logger_ref_static, name: span }); + }); + + LoggerScope { _marker: std::marker::PhantomData } + } +} + +impl<'a> Drop for LoggerScope<'a> { + fn drop(&mut self) { + 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}; + #[test] + fn logger_scope() { + let logger = TestLogger::new(); + let _scope = LoggerScope::new(&logger, "test_logger_scope"); + log_info!("Info"); + } + #[test] fn test_level_show() { assert_eq!("INFO", Level::Info.to_string()); diff --git a/lightning/src/util/macro_logger.rs b/lightning/src/util/macro_logger.rs index ec9eb14ba38..44246edb42d 100644 --- a/lightning/src/util/macro_logger.rs +++ b/lightning/src/util/macro_logger.rs @@ -174,14 +174,40 @@ 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)+) => {{ + let mut spans = Vec::new(); + $crate::util::logger::TLS_LOGGER.with(|cell| { + spans = cell.borrow().iter().map(|span| span.name).collect() + }); + $logger.log($crate::util::logger::Record::new($lvl, spans, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None)); + }}; +} + +/// Create a new Record and log it. You probably don't want to use this macro directly, +/// but it needs to be exported so `log_trace` etc can use it in external crates. +#[doc(hidden)] +#[macro_export] +macro_rules! log_given_level_ctx { + ($lvl:expr, $($arg:tt)+) => ( + $crate::util::logger::TLS_LOGGER.with(|cell| { + let borrowed = cell.borrow(); + let spans = borrowed.iter().map(|span| span.name).collect(); + if let Some(span) = borrowed.last() { + span.logger.log($crate::util::logger::Record::new($lvl, spans, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None)) + } + }) ); } /// Log at the `ERROR` level. #[macro_export] macro_rules! log_error { + ($fmt: literal) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Error, $fmt); + }; + ($fmt: literal, $($arg:tt)*) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Error, $fmt, $($arg)*); + }; ($logger: expr, $($arg:tt)*) => ( $crate::log_given_level!($logger, $crate::util::logger::Level::Error, $($arg)*); ) @@ -190,6 +216,12 @@ macro_rules! log_error { /// Log at the `WARN` level. #[macro_export] macro_rules! log_warn { + ($fmt: literal) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Warn, $fmt); + }; + ($fmt: literal, $($arg:tt)*) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Warn, $fmt, $($arg)*); + }; ($logger: expr, $($arg:tt)*) => ( $crate::log_given_level!($logger, $crate::util::logger::Level::Warn, $($arg)*); ) @@ -198,6 +230,12 @@ macro_rules! log_warn { /// Log at the `INFO` level. #[macro_export] macro_rules! log_info { + ($fmt: literal) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Info, $fmt); + }; + ($fmt: literal, $($arg:tt)*) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Info, $fmt, $($arg)*); + }; ($logger: expr, $($arg:tt)*) => ( $crate::log_given_level!($logger, $crate::util::logger::Level::Info, $($arg)*); ) @@ -206,6 +244,12 @@ macro_rules! log_info { /// Log at the `DEBUG` level. #[macro_export] macro_rules! log_debug { + ($fmt: literal) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Debug, $fmt); + }; + ($fmt: literal, $($arg:tt)*) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Debug, $fmt, $($arg)*); + }; ($logger: expr, $($arg:tt)*) => ( $crate::log_given_level!($logger, $crate::util::logger::Level::Debug, $($arg)*); ) @@ -214,6 +258,12 @@ macro_rules! log_debug { /// Log at the `TRACE` level. #[macro_export] macro_rules! log_trace { + ($fmt: literal) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Trace, $fmt); + }; + ($fmt: literal, $($arg:tt)*) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Trace, $fmt, $($arg)*); + }; ($logger: expr, $($arg:tt)*) => ( $crate::log_given_level!($logger, $crate::util::logger::Level::Trace, $($arg)*) ) @@ -222,6 +272,12 @@ macro_rules! log_trace { /// Log at the `GOSSIP` level. #[macro_export] macro_rules! log_gossip { + ($fmt: literal) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Gossip, $fmt); + }; + ($fmt: literal, $($arg:tt)*) => { + $crate::log_given_level_ctx!($crate::util::logger::Level::Gossip, $fmt, $($arg)*); + }; ($logger: expr, $($arg:tt)*) => ( $crate::log_given_level!($logger, $crate::util::logger::Level::Gossip, $($arg)*); ) From 7f7467109ada16a465b09472b77b27b79274a673 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Wed, 3 Dec 2025 13:56:36 +0100 Subject: [PATCH 2/3] Use context logging for ChannelMonitor Reduce boiler plate for logging, and allow quick insertion of log statements anywhere without first threading through a logger instance and associated type parameter. --- lightning/src/chain/channelmonitor.rs | 326 ++++++++++++-------------- lightning/src/chain/onchaintx.rs | 98 ++++---- lightning/src/chain/package.rs | 59 ++--- 3 files changed, 228 insertions(+), 255 deletions(-) diff --git a/lightning/src/chain/channelmonitor.rs b/lightning/src/chain/channelmonitor.rs index 10e5049682e..206b3fae309 100644 --- a/lightning/src/chain/channelmonitor.rs +++ b/lightning/src/chain/channelmonitor.rs @@ -66,7 +66,7 @@ use crate::sign::{ use crate::types::features::ChannelTypeFeatures; use crate::types::payment::{PaymentHash, PaymentPreimage}; use crate::util::byte_utils; -use crate::util::logger::{Logger, Record}; +use crate::util::logger::{Logger, LoggerScope, Record}; use crate::util::persist::MonitorName; use crate::util::ser::{ MaybeReadable, Readable, ReadableArgs, RequiredWrapper, UpgradableRequired, Writeable, Writer, @@ -2090,11 +2090,12 @@ impl ChannelMonitor { { let mut inner = self.inner.lock().unwrap(); let logger = WithChannelMonitor::from_impl(logger, &*inner, Some(*payment_hash)); + let _logger_scope = LoggerScope::new(&logger, "provide_payment_preimage_unsafe_legacy"); // Note that we don't pass any MPP claim parts here. This is generally not okay but in this // case is acceptable as we only call this method from `ChannelManager` deserialization in // cases where we are replaying a claim started on a previous version of LDK. inner.provide_payment_preimage( - payment_hash, payment_preimage, &None, broadcaster, fee_estimator, &logger) + payment_hash, payment_preimage, &None, broadcaster, fee_estimator) } /// Updates a ChannelMonitor on the basis of some new information provided by the Channel @@ -2111,7 +2112,8 @@ impl ChannelMonitor { { let mut inner = self.inner.lock().unwrap(); let logger = WithChannelMonitor::from_impl(logger, &*inner, None); - inner.update_monitor(updates, broadcaster, fee_estimator, &logger) + let _logger_scope = LoggerScope::new(&logger, "update_monitor"); + inner.update_monitor(updates, broadcaster, fee_estimator) } /// Gets the update_id from the latest ChannelMonitorUpdate which was applied to this @@ -2366,13 +2368,8 @@ impl ChannelMonitor { let mut inner = self.inner.lock().unwrap(); let fee_estimator = LowerBoundedFeeEstimator::new(&**fee_estimator); let logger = WithChannelMonitor::from_impl(logger, &*inner, None); - - inner.queue_latest_holder_commitment_txn_for_broadcast( - broadcaster, - &fee_estimator, - &logger, - false, - ); + let _logger_scope = LoggerScope::new(&logger, "broadcast_latest_holder_commitment_txn"); + inner.queue_latest_holder_commitment_txn_for_broadcast(broadcaster, &fee_estimator, false); } /// Unsafe test-only version of `broadcast_latest_holder_commitment_txn` used by our test framework @@ -2416,8 +2413,9 @@ impl ChannelMonitor { { let mut inner = self.inner.lock().unwrap(); let logger = WithChannelMonitor::from_impl(logger, &*inner, None); + let _logger_scope = LoggerScope::new(&logger, "block_connected"); inner.block_connected( - header, txdata, height, broadcaster, fee_estimator, &logger) + header, txdata, height, broadcaster, fee_estimator) } /// Determines if the disconnected block contained any transactions of interest and updates @@ -2431,7 +2429,8 @@ impl ChannelMonitor { { let mut inner = self.inner.lock().unwrap(); let logger = WithChannelMonitor::from_impl(logger, &*inner, None); - inner.blocks_disconnected(fork_point, broadcaster, fee_estimator, &logger) + let _logger_scope = LoggerScope::new(&logger, "blocks_disconnected"); + inner.blocks_disconnected(fork_point, broadcaster, fee_estimator) } /// Processes transactions confirmed in a block with the given header and height, returning new @@ -2459,8 +2458,9 @@ impl ChannelMonitor { let bounded_fee_estimator = LowerBoundedFeeEstimator::new(fee_estimator); let mut inner = self.inner.lock().unwrap(); let logger = WithChannelMonitor::from_impl(logger, &*inner, None); + let _logger_scope = LoggerScope::new(&logger, "transactions_confirmed"); inner.transactions_confirmed( - header, txdata, height, broadcaster, &bounded_fee_estimator, &logger) + header, txdata, height, broadcaster, &bounded_fee_estimator) } /// Processes a transaction that was reorganized out of the chain. @@ -2513,8 +2513,9 @@ impl ChannelMonitor { let bounded_fee_estimator = LowerBoundedFeeEstimator::new(fee_estimator); let mut inner = self.inner.lock().unwrap(); let logger = WithChannelMonitor::from_impl(logger, &*inner, None); + let _logger_scope = LoggerScope::new(&logger, "best_block_updated"); inner.best_block_updated( - header, height, broadcaster, &bounded_fee_estimator, &logger + header, height, broadcaster, &bounded_fee_estimator, ) } @@ -2556,11 +2557,12 @@ impl ChannelMonitor { let mut lock = self.inner.lock().unwrap(); let inner = &mut *lock; let logger = WithChannelMonitor::from_impl(logger, &*inner, None); + let _logger_scope = LoggerScope::new(&logger, "rebroadcast_pending_claims"); let current_height = inner.best_block.height; let conf_target = inner.closure_conf_target(); inner.onchain_tx_handler.rebroadcast_pending_claims( current_height, FeerateStrategy::HighestOfPreviousOrNew, &broadcaster, conf_target, - &inner.destination_script, &fee_estimator, &logger, + &inner.destination_script, &fee_estimator ); } @@ -2584,11 +2586,12 @@ impl ChannelMonitor { let mut lock = self.inner.lock().unwrap(); let inner = &mut *lock; let logger = WithChannelMonitor::from_impl(logger, &*inner, None); + let _logger_scope = LoggerScope::new(&logger, "signer_unblocked"); let current_height = inner.best_block.height; let conf_target = inner.closure_conf_target(); inner.onchain_tx_handler.rebroadcast_pending_claims( current_height, FeerateStrategy::RetryPrevious, &broadcaster, conf_target, - &inner.destination_script, &fee_estimator, &logger, + &inner.destination_script, &fee_estimator, ); } @@ -3344,7 +3347,7 @@ impl ChannelMonitor { /// been revoked yet, the previous one, we we will never "forget" to resolve an HTLC. macro_rules! fail_unbroadcast_htlcs { ($self: expr, $commitment_tx_type: expr, $commitment_txid_confirmed: expr, $commitment_tx_confirmed: expr, - $commitment_tx_conf_height: expr, $commitment_tx_conf_hash: expr, $confirmed_htlcs_list: expr, $logger: expr) => { { + $commitment_tx_conf_height: expr, $commitment_tx_conf_hash: expr, $confirmed_htlcs_list: expr) => { { debug_assert_eq!($commitment_tx_confirmed.compute_txid(), $commitment_txid_confirmed); macro_rules! check_htlc_fails { @@ -3399,7 +3402,7 @@ macro_rules! fail_unbroadcast_htlcs { commitment_tx_output_idx: None, }, }; - log_trace!($logger, "Failing HTLC with payment_hash {} from {} counterparty commitment tx due to broadcast of {} commitment transaction {}, waiting for confirmation (at height {})", + log_trace!("Failing HTLC with payment_hash {} from {} counterparty commitment tx due to broadcast of {} commitment transaction {}, waiting for confirmation (at height {})", &htlc.payment_hash, $commitment_tx, $commitment_tx_type, $commitment_txid_confirmed, entry.confirmation_threshold()); $self.onchain_events_awaiting_threshold_conf.push(entry); @@ -3826,13 +3829,12 @@ impl ChannelMonitorImpl { /// /// Note that this is often called multiple times for the same payment and must be idempotent. #[rustfmt::skip] - fn provide_payment_preimage( + fn provide_payment_preimage( &mut self, payment_hash: &PaymentHash, payment_preimage: &PaymentPreimage, payment_info: &Option, broadcaster: &B, - fee_estimator: &LowerBoundedFeeEstimator, logger: &WithChannelMonitor) + fee_estimator: &LowerBoundedFeeEstimator) where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { self.payment_preimages.entry(payment_hash.clone()) .and_modify(|(_, payment_infos)| { @@ -3870,7 +3872,7 @@ impl ChannelMonitorImpl { let conf_target = self.closure_conf_target(); self.onchain_tx_handler.update_claims_view_from_requests( htlc_claim_reqs, self.best_block.height, self.best_block.height, broadcaster, - conf_target, &self.destination_script, fee_estimator, logger, + conf_target, &self.destination_script, fee_estimator, ); } } @@ -3880,7 +3882,7 @@ impl ChannelMonitorImpl { claim_htlcs!(*commitment_number, txid, funding_spent.counterparty_claimable_outpoints.get(&txid)); } else { debug_assert!(false); - log_error!(logger, "Detected counterparty commitment tx on-chain without tracking commitment number"); + log_error!("Detected counterparty commitment tx on-chain without tracking commitment number"); } return; } @@ -3891,7 +3893,7 @@ impl ChannelMonitorImpl { claim_htlcs!(*commitment_number, txid, funding_spent.counterparty_claimable_outpoints.get(&txid)); } else { debug_assert!(false); - log_error!(logger, "Detected counterparty commitment tx on-chain without tracking commitment number"); + log_error!("Detected counterparty commitment tx on-chain without tracking commitment number"); } return; } @@ -3924,7 +3926,7 @@ impl ChannelMonitorImpl { let conf_target = self.closure_conf_target(); self.onchain_tx_handler.update_claims_view_from_requests( claim_reqs, self.best_block.height, self.best_block.height, broadcaster, - conf_target, &self.destination_script, fee_estimator, logger, + conf_target, &self.destination_script, fee_estimator, ); } } @@ -4005,14 +4007,13 @@ impl ChannelMonitorImpl { /// See also [`ChannelMonitor::broadcast_latest_holder_commitment_txn`]. /// /// [`ChannelMonitor::broadcast_latest_holder_commitment_txn`]: crate::chain::channelmonitor::ChannelMonitor::broadcast_latest_holder_commitment_txn - pub(crate) fn queue_latest_holder_commitment_txn_for_broadcast( - &mut self, broadcaster: &B, fee_estimator: &LowerBoundedFeeEstimator, logger: &WithChannelMonitor, + pub(crate) fn queue_latest_holder_commitment_txn_for_broadcast( + &mut self, broadcaster: &B, fee_estimator: &LowerBoundedFeeEstimator, require_funding_seen: bool, ) where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { let reason = ClosureReason::HolderForceClosed { broadcasted_latest_txn: Some(true), @@ -4023,25 +4024,21 @@ impl ChannelMonitorImpl { // In manual-broadcast mode, if `require_funding_seen` is true and we have not yet observed // the funding transaction on-chain, do not queue any transactions. if require_funding_seen && self.is_manual_broadcast && !self.funding_seen_onchain { - log_info!(logger, "Not broadcasting holder commitment for manual-broadcast channel before funding appears on-chain"); + log_info!("Not broadcasting holder commitment for manual-broadcast channel before funding appears on-chain"); return; } let conf_target = self.closure_conf_target(); self.onchain_tx_handler.update_claims_view_from_requests( claimable_outpoints, self.best_block.height, self.best_block.height, broadcaster, - conf_target, &self.destination_script, fee_estimator, logger, + conf_target, &self.destination_script, fee_estimator, ); } - fn renegotiated_funding( - &mut self, logger: &WithChannelMonitor, - channel_parameters: &ChannelTransactionParameters, + fn renegotiated_funding( + &mut self, channel_parameters: &ChannelTransactionParameters, alternative_holder_commitment_tx: &HolderCommitmentTransaction, alternative_counterparty_commitment_tx: &CommitmentTransaction, - ) -> Result<(), ()> - where - L::Target: Logger, - { + ) -> Result<(), ()> { let alternative_counterparty_commitment_txid = alternative_counterparty_commitment_tx.trust().txid(); @@ -4058,7 +4055,6 @@ impl ChannelMonitorImpl { } else { debug_assert!(false); log_error!( - logger, "Received funding renegotiation while initial funding negotiation is still pending" ); return Err(()); @@ -4073,10 +4069,7 @@ impl ChannelMonitorImpl { .position(|(htlc, _)| htlc.transaction_output_index.is_none()) .unwrap_or(htlcs_with_sources.len()); if alternative_htlcs.len() != expected_non_dust_htlc_count { - log_error!( - logger, - "Received alternative counterparty commitment with HTLC count mismatch" - ); + log_error!("Received alternative counterparty commitment with HTLC count mismatch"); return Err(()); } @@ -4087,7 +4080,6 @@ impl ChannelMonitorImpl { debug_assert!(alternative_htlc.transaction_output_index.is_some()); if !alternative_htlc.is_data_equal(htlc) { log_error!( - logger, "Received alternative counterparty commitment with non-dust HTLC mismatch" ); return Err(()); @@ -4116,7 +4108,6 @@ impl ChannelMonitorImpl { .any(|funding| funding.funding_txid() == alternative_funding_outpoint.txid) { log_error!( - logger, "Renegotiated funding transaction with a duplicate funding txid {}", alternative_funding_outpoint.txid ); @@ -4128,14 +4119,12 @@ impl ChannelMonitorImpl { // (implying our funding is confirmed) that spends our currently locked funding. if !self.pending_funding.is_empty() { log_error!( - logger, "Negotiated splice while channel is pending channel_ready/splice_locked" ); return Err(()); } if *parent_funding_txid != self.funding.funding_txid() { log_error!( - logger, "Negotiated splice that does not spend currently locked funding transaction" ); return Err(()); @@ -4209,21 +4198,20 @@ impl ChannelMonitorImpl { } #[rustfmt::skip] - fn update_monitor( - &mut self, updates: &ChannelMonitorUpdate, broadcaster: &B, fee_estimator: &F, logger: &WithChannelMonitor + fn update_monitor( + &mut self, updates: &ChannelMonitorUpdate, broadcaster: &B, fee_estimator: &F, ) -> Result<(), ()> where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { if self.latest_update_id == LEGACY_CLOSED_CHANNEL_UPDATE_ID && updates.update_id == LEGACY_CLOSED_CHANNEL_UPDATE_ID { - log_info!(logger, "Applying pre-0.1 post-force-closed update to monitor {} with {} change(s).", + log_info!( "Applying pre-0.1 post-force-closed update to monitor {} with {} change(s).", log_funding_info!(self), updates.updates.len()); } else if updates.update_id == LEGACY_CLOSED_CHANNEL_UPDATE_ID { - log_info!(logger, "Applying pre-0.1 force close update to monitor {} with {} change(s).", + log_info!( "Applying pre-0.1 force close update to monitor {} with {} change(s).", log_funding_info!(self), updates.updates.len()); } else { - log_info!(logger, "Applying update, bringing update_id from {} to {} with {} change(s).", + log_info!( "Applying update, bringing update_id from {} to {} with {} change(s).", self.latest_update_id, updates.update_id, updates.updates.len()); } @@ -4245,7 +4233,7 @@ impl ChannelMonitorImpl { ChannelMonitorUpdateStep::PaymentPreimage { .. } => debug_assert!(self.lockdown_from_offchain), _ => { - log_error!(logger, "Attempted to apply post-force-close ChannelMonitorUpdate of type {}", updates.updates[0].variant_name()); + log_error!("Attempted to apply post-force-close ChannelMonitorUpdate of type {}", updates.updates[0].variant_name()); panic!("Attempted to apply post-force-close ChannelMonitorUpdate that wasn't providing a payment preimage"); }, } @@ -4260,25 +4248,25 @@ impl ChannelMonitorImpl { for update in updates.updates.iter() { match update { ChannelMonitorUpdateStep::LatestHolderCommitmentTXInfo { commitment_tx, htlc_outputs, claimed_htlcs, nondust_htlc_sources } => { - log_trace!(logger, "Updating ChannelMonitor with latest holder commitment transaction info"); + log_trace!("Updating ChannelMonitor with latest holder commitment transaction info"); if self.lockdown_from_offchain { panic!(); } if let Err(e) = self.provide_latest_holder_commitment_tx( commitment_tx.clone(), htlc_outputs, &claimed_htlcs, nondust_htlc_sources.clone() ) { - log_error!(logger, "Failed updating latest holder commitment transaction info: {}", e); + log_error!("Failed updating latest holder commitment transaction info: {}", e); ret = Err(()); } } ChannelMonitorUpdateStep::LatestHolderCommitment { commitment_txs, htlc_data, claimed_htlcs, } => { - log_trace!(logger, "Updating ChannelMonitor with {} latest holder commitment(s)", commitment_txs.len()); + log_trace!("Updating ChannelMonitor with {} latest holder commitment(s)", commitment_txs.len()); assert!(!self.lockdown_from_offchain); if let Err(e) = self.update_holder_commitment_data( commitment_txs.clone(), htlc_data.clone(), claimed_htlcs, ) { - log_error!(logger, "Failed updating latest holder commitment state: {}", e); + log_error!("Failed updating latest holder commitment state: {}", e); ret = Err(()); } }, @@ -4286,56 +4274,56 @@ impl ChannelMonitorImpl { // For now we just add the code to handle the new updates. // Next step: in channel, switch channel monitor updates to use the `LatestCounterpartyCommitment` variant. ChannelMonitorUpdateStep::LatestCounterpartyCommitmentTXInfo { commitment_txid, htlc_outputs, commitment_number, their_per_commitment_point, .. } => { - log_trace!(logger, "Updating ChannelMonitor with latest counterparty commitment transaction info"); + log_trace!("Updating ChannelMonitor with latest counterparty commitment transaction info"); if self.pending_funding.is_empty() { self.provide_latest_counterparty_commitment_tx(*commitment_txid, htlc_outputs.clone(), *commitment_number, *their_per_commitment_point) } else { - log_error!(logger, "Received unexpected non-splice counterparty commitment monitor update"); + log_error!("Received unexpected non-splice counterparty commitment monitor update"); ret = Err(()); } }, ChannelMonitorUpdateStep::LatestCounterpartyCommitment { commitment_txs, htlc_data, } => { - log_trace!(logger, "Updating ChannelMonitor with {} latest counterparty commitments", commitment_txs.len()); + log_trace!("Updating ChannelMonitor with {} latest counterparty commitments", commitment_txs.len()); if let Err(e) = self.update_counterparty_commitment_data(commitment_txs, htlc_data) { - log_error!(logger, "Failed updating latest counterparty commitment state: {}", e); + log_error!("Failed updating latest counterparty commitment state: {}", e); ret = Err(()); } }, ChannelMonitorUpdateStep::PaymentPreimage { payment_preimage, payment_info } => { - log_trace!(logger, "Updating ChannelMonitor with payment preimage"); - self.provide_payment_preimage(&PaymentHash(Sha256::hash(&payment_preimage.0[..]).to_byte_array()), &payment_preimage, payment_info, broadcaster, &bounded_fee_estimator, logger) + log_trace!("Updating ChannelMonitor with payment preimage"); + self.provide_payment_preimage(&PaymentHash(Sha256::hash(&payment_preimage.0[..]).to_byte_array()), &payment_preimage, payment_info, broadcaster, &bounded_fee_estimator) }, ChannelMonitorUpdateStep::CommitmentSecret { idx, secret } => { - log_trace!(logger, "Updating ChannelMonitor with commitment secret"); + log_trace!("Updating ChannelMonitor with commitment secret"); if let Err(e) = self.provide_secret(*idx, *secret) { debug_assert!(false, "Latest counterparty commitment secret was invalid"); - log_error!(logger, "Providing latest counterparty commitment secret failed/was refused:"); - log_error!(logger, " {}", e); + log_error!("Providing latest counterparty commitment secret failed/was refused:"); + log_error!(" {}", e); ret = Err(()); } }, ChannelMonitorUpdateStep::RenegotiatedFunding { channel_parameters, holder_commitment_tx, counterparty_commitment_tx, } => { - log_trace!(logger, "Updating ChannelMonitor with alternative holder and counterparty commitment transactions for funding txid {}", + log_trace!("Updating ChannelMonitor with alternative holder and counterparty commitment transactions for funding txid {}", channel_parameters.funding_outpoint.unwrap().txid); if let Err(_) = self.renegotiated_funding( - logger, channel_parameters, holder_commitment_tx, counterparty_commitment_tx, + channel_parameters, holder_commitment_tx, counterparty_commitment_tx, ) { ret = Err(()); } }, ChannelMonitorUpdateStep::RenegotiatedFundingLocked { funding_txid } => { - log_trace!(logger, "Updating ChannelMonitor with locked renegotiated funding txid {}", funding_txid); + log_trace!("Updating ChannelMonitor with locked renegotiated funding txid {}", funding_txid); if let Err(_) = self.promote_funding(*funding_txid) { - log_error!(logger, "Unknown funding with txid {} became locked", funding_txid); + log_error!("Unknown funding with txid {} became locked", funding_txid); ret = Err(()); } }, ChannelMonitorUpdateStep::ChannelForceClosed { should_broadcast } => { - log_trace!(logger, "Updating ChannelMonitor: channel force closed, should broadcast: {}", should_broadcast); + log_trace!("Updating ChannelMonitor: channel force closed, should broadcast: {}", should_broadcast); self.lockdown_from_offchain = true; if *should_broadcast { // There's no need to broadcast our commitment transaction if we've seen one @@ -4345,29 +4333,29 @@ impl ChannelMonitorImpl { self.onchain_events_awaiting_threshold_conf.iter().any( |event| matches!(event.event, OnchainEvent::FundingSpendConfirmation { .. })); if detected_funding_spend { - log_trace!(logger, "Avoiding commitment broadcast, already detected confirmed spend onchain"); + log_trace!("Avoiding commitment broadcast, already detected confirmed spend onchain"); continue; } - self.queue_latest_holder_commitment_txn_for_broadcast(broadcaster, &bounded_fee_estimator, logger, true); + self.queue_latest_holder_commitment_txn_for_broadcast(broadcaster, &bounded_fee_estimator, true); } else if !self.holder_tx_signed { - log_error!(logger, "WARNING: You have a potentially-unsafe holder commitment transaction available to broadcast"); - log_error!(logger, " in channel monitor!"); - log_error!(logger, " Read the docs for ChannelMonitor::broadcast_latest_holder_commitment_txn to take manual action!"); + log_error!("WARNING: You have a potentially-unsafe holder commitment transaction available to broadcast"); + log_error!(" in channel monitor!"); + log_error!(" Read the docs for ChannelMonitor::broadcast_latest_holder_commitment_txn to take manual action!"); } else { // If we generated a MonitorEvent::HolderForceClosed, the ChannelManager // will still give us a ChannelForceClosed event with !should_broadcast, but we // shouldn't print the scary warning above. - log_info!(logger, "Channel off-chain state closed after we broadcasted our latest commitment transaction."); + log_info!( "Channel off-chain state closed after we broadcasted our latest commitment transaction."); } }, ChannelMonitorUpdateStep::ShutdownScript { scriptpubkey } => { - log_trace!(logger, "Updating ChannelMonitor with shutdown script"); + log_trace!("Updating ChannelMonitor with shutdown script"); if let Some(shutdown_script) = self.shutdown_script.replace(scriptpubkey.clone()) { panic!("Attempted to replace shutdown script {} with {}", shutdown_script, scriptpubkey); } }, ChannelMonitorUpdateStep::ReleasePaymentComplete { htlc } => { - log_trace!(logger, "HTLC {htlc:?} permanently and fully resolved"); + log_trace!("HTLC {htlc:?} permanently and fully resolved"); self.htlcs_resolved_to_user.insert(*htlc); }, } @@ -4406,7 +4394,7 @@ impl ChannelMonitorImpl { } if ret.is_ok() && self.no_further_updates_allowed() && is_pre_close_update { - log_error!(logger, "Refusing Channel Monitor Update as counterparty attempted to update commitment after funding was spent"); + log_error!("Refusing Channel Monitor Update as counterparty attempted to update commitment after funding was spent"); Err(()) } else { ret } } @@ -4677,9 +4665,8 @@ impl ChannelMonitorImpl { /// Returns packages to claim the revoked output(s) and general information about the output that /// is to the counterparty in the commitment transaction. #[rustfmt::skip] - fn check_spend_counterparty_transaction(&mut self, commitment_txid: Txid, commitment_tx: &Transaction, height: u32, block_hash: &BlockHash, logger: &L) - -> (Vec, CommitmentTxCounterpartyOutputInfo) - where L::Target: Logger { + fn check_spend_counterparty_transaction(&mut self, commitment_txid: Txid, commitment_tx: &Transaction, height: u32, block_hash: &BlockHash) + -> (Vec, CommitmentTxCounterpartyOutputInfo) { // Most secp and related errors trying to create keys means we have no hope of constructing // a spend transaction...so we return no transactions to broadcast let mut claimable_outpoints = Vec::new(); @@ -4761,14 +4748,14 @@ impl ChannelMonitorImpl { // Last, track onchain revoked commitment transaction and fail backward outgoing HTLCs as payment path is broken if !claimable_outpoints.is_empty() || per_commitment_option.is_some() { // ie we're confident this is actually ours // We're definitely a counterparty commitment transaction! - log_error!(logger, "Got broadcast of revoked counterparty commitment transaction, going to generate general spend tx with {} inputs", claimable_outpoints.len()); + log_error!("Got broadcast of revoked counterparty commitment transaction, going to generate general spend tx with {} inputs", claimable_outpoints.len()); self.counterparty_commitment_txn_on_chain.insert(commitment_txid, commitment_number); if let Some(per_commitment_claimable_data) = per_commitment_option { fail_unbroadcast_htlcs!(self, "revoked_counterparty", commitment_txid, commitment_tx, height, block_hash, per_commitment_claimable_data.iter().map(|(htlc, htlc_source)| (htlc, htlc_source.as_ref().map(|htlc_source| htlc_source.as_ref())) - ), logger); + )); } else { // Our fuzzers aren't constrained by pesky things like valid signatures, so can // spend our funding output with a transaction which doesn't match our past @@ -4776,7 +4763,7 @@ impl ChannelMonitorImpl { // fuzzing. debug_assert!(cfg!(fuzzing), "We should have per-commitment option for any recognized old commitment txn"); fail_unbroadcast_htlcs!(self, "revoked counterparty", commitment_txid, commitment_tx, height, - block_hash, [].iter().map(|reference| *reference), logger); + block_hash, [].iter().map(|reference| *reference)); } } } else if let Some(per_commitment_claimable_data) = per_commitment_option { @@ -4791,11 +4778,11 @@ impl ChannelMonitorImpl { // insert it here. self.counterparty_commitment_txn_on_chain.insert(commitment_txid, commitment_number); - log_info!(logger, "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid); + log_info!( "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid); fail_unbroadcast_htlcs!(self, "counterparty", commitment_txid, commitment_tx, height, block_hash, per_commitment_claimable_data.iter().map(|(htlc, htlc_source)| (htlc, htlc_source.as_ref().map(|htlc_source| htlc_source.as_ref())) - ), logger); + )); let (htlc_claim_reqs, counterparty_output_info) = self.get_counterparty_output_claim_info(funding_spent, commitment_number, commitment_txid, commitment_tx, per_commitment_claimable_data, Some(height)); to_counterparty_output_info = counterparty_output_info; @@ -4967,9 +4954,9 @@ impl ChannelMonitorImpl { /// Attempts to claim a counterparty HTLC-Success/HTLC-Timeout's outputs using the revocation key #[rustfmt::skip] - fn check_spend_counterparty_htlc( - &mut self, tx: &Transaction, commitment_number: u64, commitment_txid: &Txid, height: u32, logger: &L - ) -> (Vec, Option) where L::Target: Logger { + fn check_spend_counterparty_htlc( + &mut self, tx: &Transaction, commitment_number: u64, commitment_txid: &Txid, height: u32 + ) -> (Vec, Option) { let secret = if let Some(secret) = self.get_secret(commitment_number) { secret } else { return (Vec::new(), None); }; let per_commitment_key = match SecretKey::from_slice(&secret) { Ok(key) => key, @@ -4995,7 +4982,7 @@ impl ChannelMonitorImpl { // have a corresponding output at the same index within the transaction. for (idx, input) in tx.input.iter().enumerate() { if input.previous_output.txid == *commitment_txid && input.witness.len() == 5 && tx.output.get(idx).is_some() { - log_error!(logger, "Got broadcast of revoked counterparty HTLC transaction, spending {}:{}", htlc_txid, idx); + log_error!("Got broadcast of revoked counterparty HTLC transaction, spending {}:{}", htlc_txid, idx); let revk_outp = RevokedOutput::build( per_commitment_point, per_commitment_key, tx.output[idx].value, self.funding.channel_parameters.clone(), height, @@ -5110,13 +5097,10 @@ impl ChannelMonitorImpl { /// revoked using data in holder_claimable_outpoints. /// Should not be used if check_spend_revoked_transaction succeeds. /// Returns None unless the transaction is definitely one of our commitment transactions. - fn check_spend_holder_transaction( + fn check_spend_holder_transaction( &mut self, commitment_txid: Txid, commitment_tx: &Transaction, height: u32, - block_hash: &BlockHash, logger: &L, - ) -> Option<(Vec, TransactionOutputs)> - where - L::Target: Logger, - { + block_hash: &BlockHash, + ) -> Option<(Vec, TransactionOutputs)> { let funding_spent = get_confirmed_funding_scope!(self); // HTLCs set may differ between last and previous holder commitment txn, in case of one them hitting chain, ensure we cancel all HTLCs backward @@ -5139,7 +5123,7 @@ impl ChannelMonitorImpl { assert_eq!(funding_spent.funding_txid(), funding_txid_spent); let current_msg = if current { "latest holder" } else { "previous holder" }; - log_info!(logger, "Got broadcast of {current_msg} commitment tx {commitment_txid}, searching for available HTLCs to claim"); + log_info!("Got broadcast of {current_msg} commitment tx {commitment_txid}, searching for available HTLCs to claim"); let (claim_requests, broadcasted_holder_revokable_script) = self.get_broadcasted_holder_claims(funding_spent, holder_commitment_tx, height); @@ -5154,8 +5138,7 @@ impl ChannelMonitorImpl { commitment_tx, height, block_hash, - holder_commitment_htlcs!(self, CURRENT_WITH_SOURCES), - logger + holder_commitment_htlcs!(self, CURRENT_WITH_SOURCES) ); } else { fail_unbroadcast_htlcs!( @@ -5165,8 +5148,7 @@ impl ChannelMonitorImpl { commitment_tx, height, block_hash, - holder_commitment_htlcs!(self, PREV_WITH_SOURCES).unwrap(), - logger + holder_commitment_htlcs!(self, PREV_WITH_SOURCES).unwrap() ); } @@ -5179,9 +5161,9 @@ impl ChannelMonitorImpl { /// Cancels any existing pending claims for a commitment that previously confirmed and has now /// been replaced by another. #[rustfmt::skip] - pub fn cancel_prev_commitment_claims( - &mut self, logger: &L, confirmed_commitment_txid: &Txid - ) where L::Target: Logger { + pub(crate) fn cancel_prev_commitment_claims( + &mut self, confirmed_commitment_txid: &Txid + ) { for (counterparty_commitment_txid, _) in &self.counterparty_commitment_txn_on_chain { // Cancel any pending claims for counterparty commitments we've seen confirm. if counterparty_commitment_txid == confirmed_commitment_txid { @@ -5201,7 +5183,7 @@ impl ChannelMonitorImpl { } } if found_claim { - log_trace!(logger, "Canceled claims for previously confirmed counterparty commitment with txid {counterparty_commitment_txid}"); + log_trace!("Canceled claims for previously confirmed counterparty commitment with txid {counterparty_commitment_txid}"); } } } @@ -5224,7 +5206,7 @@ impl ChannelMonitorImpl { } } if found_claim { - log_trace!(logger, "Canceled claims for previously broadcast holder commitment with txid {txid}"); + log_trace!("Canceled claims for previously broadcast holder commitment with txid {txid}"); } } if let Some(prev_holder_commitment_tx) = &funding.prev_holder_commitment_tx { @@ -5243,7 +5225,7 @@ impl ChannelMonitorImpl { } } if found_claim { - log_trace!(logger, "Canceled claims for previously broadcast holder commitment with txid {txid}"); + log_trace!("Canceled claims for previously broadcast holder commitment with txid {txid}"); } } } @@ -5305,67 +5287,62 @@ impl ChannelMonitorImpl { } #[rustfmt::skip] - fn block_connected( + fn block_connected( &mut self, header: &Header, txdata: &TransactionData, height: u32, broadcaster: B, - fee_estimator: F, logger: &WithChannelMonitor, + fee_estimator: F, ) -> Vec where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { let block_hash = header.block_hash(); self.best_block = BestBlock::new(block_hash, height); let bounded_fee_estimator = LowerBoundedFeeEstimator::new(fee_estimator); - self.transactions_confirmed(header, txdata, height, broadcaster, &bounded_fee_estimator, logger) + self.transactions_confirmed(header, txdata, height, broadcaster, &bounded_fee_estimator) } #[rustfmt::skip] - fn best_block_updated( + fn best_block_updated( &mut self, header: &Header, height: u32, broadcaster: B, fee_estimator: &LowerBoundedFeeEstimator, - logger: &WithChannelMonitor, ) -> Vec where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { let block_hash = header.block_hash(); if height > self.best_block.height { self.best_block = BestBlock::new(block_hash, height); - log_trace!(logger, "Connecting new block {} at height {}", block_hash, height); - self.block_confirmed(height, block_hash, vec![], vec![], vec![], &broadcaster, &fee_estimator, logger) + log_trace!("Connecting new block {} at height {}", block_hash, height); + self.block_confirmed(height, block_hash, vec![], vec![], vec![], &broadcaster, &fee_estimator) } else if block_hash != self.best_block.block_hash { self.best_block = BestBlock::new(block_hash, height); - log_trace!(logger, "Best block re-orged, replaced with new block {} at height {}", block_hash, height); + log_trace!("Best block re-orged, replaced with new block {} at height {}", block_hash, height); self.onchain_events_awaiting_threshold_conf.retain(|ref entry| entry.height <= height); let conf_target = self.closure_conf_target(); self.onchain_tx_handler.blocks_disconnected( - height, &broadcaster, conf_target, &self.destination_script, fee_estimator, logger, + height, &broadcaster, conf_target, &self.destination_script, fee_estimator, ); Vec::new() } else { Vec::new() } } #[rustfmt::skip] - fn transactions_confirmed( + fn transactions_confirmed( &mut self, header: &Header, txdata: &TransactionData, height: u32, broadcaster: B, fee_estimator: &LowerBoundedFeeEstimator, - logger: &WithChannelMonitor, ) -> Vec where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { let funding_seen_before = self.funding_seen_onchain; let txn_matched = self.filter_block(txdata); @@ -5409,14 +5386,14 @@ impl ChannelMonitorImpl { } 'tx_iter: for tx in &txn_matched { let txid = tx.compute_txid(); - log_trace!(logger, "Transaction {} confirmed in block {}", txid , block_hash); + log_trace!("Transaction {} confirmed in block {}", txid , block_hash); // If a transaction has already been confirmed, ensure we don't bother processing it duplicatively. if self.alternative_funding_confirmed.map(|(alternative_funding_txid, _)| alternative_funding_txid == txid).unwrap_or(false) { - log_debug!(logger, "Skipping redundant processing of funding-spend tx {} as it was previously confirmed", txid); + log_debug!("Skipping redundant processing of funding-spend tx {} as it was previously confirmed", txid); continue 'tx_iter; } if Some(txid) == self.funding_spend_confirmed { - log_debug!(logger, "Skipping redundant processing of funding-spend tx {} as it was previously confirmed", txid); + log_debug!("Skipping redundant processing of funding-spend tx {} as it was previously confirmed", txid); continue 'tx_iter; } for ev in self.onchain_events_awaiting_threshold_conf.iter() { @@ -5426,19 +5403,19 @@ impl ChannelMonitorImpl { "Transaction {} was already confirmed and is being re-confirmed in a different block.\n\ This indicates a severe bug in the transaction connection logic - a reorg should have been processed first!", ev.txid); } - log_debug!(logger, "Skipping redundant processing of confirming tx {} as it was previously confirmed", txid); + log_debug!("Skipping redundant processing of confirming tx {} as it was previously confirmed", txid); continue 'tx_iter; } } for htlc in self.htlcs_resolved_on_chain.iter() { if Some(txid) == htlc.resolving_txid { - log_debug!(logger, "Skipping redundant processing of HTLC resolution tx {} as it was previously confirmed", txid); + log_debug!("Skipping redundant processing of HTLC resolution tx {} as it was previously confirmed", txid); continue 'tx_iter; } } for spendable_txid in self.spendable_txids_confirmed.iter() { if txid == *spendable_txid { - log_debug!(logger, "Skipping redundant processing of spendable tx {} as it was previously confirmed", txid); + log_debug!("Skipping redundant processing of spendable tx {} as it was previously confirmed", txid); continue 'tx_iter; } } @@ -5479,7 +5456,7 @@ impl ChannelMonitorImpl { } else { "".to_string() }; - log_info!(logger, "{desc} confirmed with txid {txid}{action}"); + log_info!("{} confirmed with txid {}{}", desc, txid, action); self.alternative_funding_confirmed = Some((txid, height)); @@ -5501,7 +5478,7 @@ impl ChannelMonitorImpl { // different funding transaction. let new_holder_commitment_txid = alternative_funding.current_holder_commitment_tx.trust().txid(); - self.cancel_prev_commitment_claims(&logger, &new_holder_commitment_txid); + self.cancel_prev_commitment_claims(&new_holder_commitment_txid); // We either attempted to broadcast a holder commitment, or saw one confirm // onchain, so broadcast the new holder commitment for the confirmed funding to @@ -5531,7 +5508,7 @@ impl ChannelMonitorImpl { .map(|(txid, _)| txid) .unwrap_or_else(|| self.funding.funding_txid()) ); - log_info!(logger, "Channel closed by funding output spend in txid {txid}"); + log_info!("Channel closed by funding output spend in txid {txid}"); if !self.funding_spend_seen { self.pending_monitor_events.push(MonitorEvent::CommitmentTxConfirmed(())); } @@ -5542,7 +5519,7 @@ impl ChannelMonitorImpl { // Is it a commitment transaction? if (tx.input[0].sequence.0 >> 8*3) as u8 == 0x80 && (tx.lock_time.to_consensus_u32() >> 8*3) as u8 == 0x20 { - if let Some((mut new_outpoints, new_outputs)) = self.check_spend_holder_transaction(txid, &tx, height, &block_hash, &logger) { + if let Some((mut new_outpoints, new_outputs)) = self.check_spend_holder_transaction(txid, &tx, height, &block_hash) { if !new_outputs.1.is_empty() { watch_outputs.push(new_outputs); } @@ -5557,7 +5534,7 @@ impl ChannelMonitorImpl { watch_outputs.push((txid, new_watch_outputs)); let (mut new_outpoints, counterparty_output_idx_sats) = - self.check_spend_counterparty_transaction(txid, &tx, height, &block_hash, &logger); + self.check_spend_counterparty_transaction(txid, &tx, height, &block_hash); commitment_tx_to_counterparty_output = counterparty_output_idx_sats; claimable_outpoints.append(&mut new_outpoints); @@ -5566,7 +5543,7 @@ impl ChannelMonitorImpl { // We've just seen a commitment confirm, which conflicts with the holder // commitment we intend to broadcast if should_broadcast_commitment { - log_info!(logger, "Canceling our queued holder commitment broadcast as we've found a conflict confirm instead"); + log_info!("Canceling our queued holder commitment broadcast as we've found a conflict confirm instead"); should_broadcast_commitment = false; } } @@ -5585,7 +5562,7 @@ impl ChannelMonitorImpl { // Now that we've detected a confirmed commitment transaction, attempt to cancel // pending claims for any commitments that were previously confirmed such that // we don't continue claiming inputs that no longer exist. - self.cancel_prev_commitment_claims(&logger, &txid); + self.cancel_prev_commitment_claims(&txid); } } if tx.input.len() >= 1 { @@ -5596,7 +5573,7 @@ impl ChannelMonitorImpl { let commitment_txid = tx_input.previous_output.txid; if let Some(&commitment_number) = self.counterparty_commitment_txn_on_chain.get(&commitment_txid) { let (mut new_outpoints, new_outputs_option) = self.check_spend_counterparty_htlc( - &tx, commitment_number, &commitment_txid, height, &logger + &tx, commitment_number, &commitment_txid, height ); claimable_outpoints.append(&mut new_outpoints); if let Some(new_outputs) = new_outputs_option { @@ -5609,9 +5586,9 @@ impl ChannelMonitorImpl { break; } } - self.is_resolving_htlc_output(&tx, height, &block_hash, logger); + self.is_resolving_htlc_output(&tx, height, &block_hash); - self.check_tx_and_push_spendable_outputs(&tx, height, &block_hash, logger); + self.check_tx_and_push_spendable_outputs(&tx, height, &block_hash); } } @@ -5626,7 +5603,7 @@ impl ChannelMonitorImpl { watch_outputs.append(&mut outputs); } - self.block_confirmed(height, block_hash, txn_matched, watch_outputs, claimable_outpoints, &broadcaster, &fee_estimator, logger) + self.block_confirmed(height, block_hash, txn_matched, watch_outputs, claimable_outpoints, &broadcaster, &fee_estimator) } /// Update state for new block(s)/transaction(s) confirmed. Note that the caller must update @@ -5638,7 +5615,7 @@ impl ChannelMonitorImpl { /// `conf_height` should be set to the height at which any new transaction(s)/block(s) were /// confirmed at, even if it is not the current best height. #[rustfmt::skip] - fn block_confirmed( + fn block_confirmed( &mut self, conf_height: u32, conf_hash: BlockHash, @@ -5647,19 +5624,17 @@ impl ChannelMonitorImpl { mut claimable_outpoints: Vec, broadcaster: &B, fee_estimator: &LowerBoundedFeeEstimator, - logger: &WithChannelMonitor, ) -> Vec where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { - log_trace!(logger, "Processing {} matched transactions for block at height {}.", txn_matched.len(), conf_height); + log_trace!("Processing {} matched transactions for block at height {}.", txn_matched.len(), conf_height); debug_assert!(self.best_block.height >= conf_height); // Only generate claims if we haven't already done so (e.g., in transactions_confirmed). if claimable_outpoints.is_empty() { - let should_broadcast = self.should_broadcast_holder_commitment_txn(logger); + let should_broadcast = self.should_broadcast_holder_commitment_txn(); if let Some(payment_hash) = should_broadcast { let reason = ClosureReason::HTLCsTimedOut { payment_hash: Some(payment_hash) }; let (mut new_outpoints, mut new_outputs) = @@ -5668,7 +5643,7 @@ impl ChannelMonitorImpl { claimable_outpoints.append(&mut new_outpoints); watch_outputs.append(&mut new_outputs); } else { - log_info!(logger, "Not broadcasting holder commitment for manual-broadcast channel before funding appears on-chain"); + log_info!("Not broadcasting holder commitment for manual-broadcast channel before funding appears on-chain"); } } } @@ -5711,7 +5686,7 @@ impl ChannelMonitorImpl { matured_htlcs.push(source.clone()); } - log_debug!(logger, "HTLC {} failure update in {} has got enough confirmations to be passed upstream", + log_debug!("HTLC {} failure update in {} has got enough confirmations to be passed upstream", &payment_hash, entry.txid); self.pending_monitor_events.push(MonitorEvent::HTLCEvent(HTLCUpdate { payment_hash, @@ -5727,7 +5702,7 @@ impl ChannelMonitorImpl { }); }, OnchainEvent::MaturingOutput { descriptor } => { - log_debug!(logger, "Descriptor {} has got enough confirmations to be passed upstream", log_spendable!(descriptor)); + log_debug!("Descriptor {} has got enough confirmations to be passed upstream", log_spendable!(descriptor)); self.pending_events.push(Event::SpendableOutputs { outputs: vec![descriptor], channel_id: Some(self.channel_id()), @@ -5764,7 +5739,7 @@ impl ChannelMonitorImpl { debug_assert_ne!(self.funding.funding_txid(), entry.txid); if let Err(_) = self.promote_funding(entry.txid) { debug_assert!(false); - log_error!(logger, "Missing scope for alternative funding confirmation with txid {}", entry.txid); + log_error!("Missing scope for alternative funding confirmation with txid {}", entry.txid); } }, } @@ -5819,7 +5794,7 @@ impl ChannelMonitorImpl { continue; } if !duplicate_event { - log_error!(logger, "Failing back HTLC {} upstream to preserve the \ + log_error!("Failing back HTLC {} upstream to preserve the \ channel as the forward HTLC hasn't resolved and our backward HTLC \ expires soon at {}", log_bytes!(htlc.payment_hash.0), inbound_htlc_expiry); self.pending_monitor_events.push(MonitorEvent::HTLCEvent(HTLCUpdate { @@ -5835,11 +5810,11 @@ impl ChannelMonitorImpl { let conf_target = self.closure_conf_target(); self.onchain_tx_handler.update_claims_view_from_requests( claimable_outpoints, conf_height, self.best_block.height, broadcaster, conf_target, - &self.destination_script, fee_estimator, logger, + &self.destination_script, fee_estimator, ); self.onchain_tx_handler.update_claims_view_from_matched_txn( &txn_matched, conf_height, conf_hash, self.best_block.height, broadcaster, conf_target, - &self.destination_script, fee_estimator, logger, + &self.destination_script, fee_estimator, ); // Determine new outputs to watch by comparing against previously known outputs to watch, @@ -5866,14 +5841,13 @@ impl ChannelMonitorImpl { } #[rustfmt::skip] - fn blocks_disconnected( - &mut self, fork_point: BestBlock, broadcaster: B, fee_estimator: F, logger: &WithChannelMonitor + fn blocks_disconnected( + &mut self, fork_point: BestBlock, broadcaster: B, fee_estimator: F, ) where B::Target: BroadcasterInterface, F::Target: FeeEstimator, - L::Target: Logger, { let new_height = fork_point.height; - log_trace!(logger, "Block(s) disconnected to height {}", new_height); + log_trace!("Block(s) disconnected to height {}", new_height); assert!(self.best_block.height > fork_point.height, "Blocks disconnected must indicate disconnection from the current best height, i.e. the new chain tip must be lower than the previous best height"); @@ -5892,7 +5866,7 @@ impl ChannelMonitorImpl { // different funding transaction. let new_holder_commitment_txid = self.funding.current_holder_commitment_tx.trust().txid(); - self.cancel_prev_commitment_claims(&logger, &new_holder_commitment_txid); + self.cancel_prev_commitment_claims(&new_holder_commitment_txid); should_broadcast_commitment = true; } @@ -5902,13 +5876,13 @@ impl ChannelMonitorImpl { let bounded_fee_estimator = LowerBoundedFeeEstimator::new(fee_estimator); let conf_target = self.closure_conf_target(); self.onchain_tx_handler.blocks_disconnected( - new_height, &broadcaster, conf_target, &self.destination_script, &bounded_fee_estimator, logger + new_height, &broadcaster, conf_target, &self.destination_script, &bounded_fee_estimator, ); // Only attempt to broadcast the new commitment after the `block_disconnected` call above so that // it doesn't get removed from the set of pending claims. if should_broadcast_commitment { - self.queue_latest_holder_commitment_txn_for_broadcast(&broadcaster, &bounded_fee_estimator, logger, true); + self.queue_latest_holder_commitment_txn_for_broadcast(&broadcaster, &bounded_fee_estimator, true); } self.best_block = fork_point; @@ -5954,7 +5928,7 @@ impl ChannelMonitorImpl { // different funding transaction. let new_holder_commitment_txid = self.funding.current_holder_commitment_tx.trust().txid(); - self.cancel_prev_commitment_claims(&logger, &new_holder_commitment_txid); + self.cancel_prev_commitment_claims(&new_holder_commitment_txid); should_broadcast_commitment = true; } @@ -5963,13 +5937,13 @@ impl ChannelMonitorImpl { let conf_target = self.closure_conf_target(); self.onchain_tx_handler.transaction_unconfirmed( - txid, &broadcaster, conf_target, &self.destination_script, fee_estimator, logger + txid, &broadcaster, conf_target, &self.destination_script, fee_estimator, ); // Only attempt to broadcast the new commitment after the `transaction_unconfirmed` call above so // that it doesn't get removed from the set of pending claims. if should_broadcast_commitment { - self.queue_latest_holder_commitment_txn_for_broadcast(&broadcaster, fee_estimator, logger, true); + self.queue_latest_holder_commitment_txn_for_broadcast(&broadcaster, fee_estimator, true); } } @@ -6030,9 +6004,9 @@ impl ChannelMonitorImpl { } #[rustfmt::skip] - fn should_broadcast_holder_commitment_txn( - &self, logger: &WithChannelMonitor - ) -> Option where L::Target: Logger { + fn should_broadcast_holder_commitment_txn( + &self + ) -> Option { // There's no need to broadcast our commitment transaction if we've seen one confirmed (even // with 1 confirmation) as it'll be rejected as duplicate/conflicting. if self.funding_spend_confirmed.is_some() || @@ -6071,7 +6045,7 @@ impl ChannelMonitorImpl { let htlc_outbound = $holder_tx == htlc.offered; if ( htlc_outbound && htlc.cltv_expiry + LATENCY_GRACE_PERIOD_BLOCKS <= height) || (!htlc_outbound && htlc.cltv_expiry <= height + CLTV_CLAIM_BUFFER && self.payment_preimages.contains_key(&htlc.payment_hash)) { - log_info!(logger, "Force-closing channel due to {} HTLC timeout - HTLC with payment hash {} expires at {}", if htlc_outbound { "outbound" } else { "inbound"}, htlc.payment_hash, htlc.cltv_expiry); + log_info!("Force-closing channel due to {} HTLC timeout - HTLC with payment hash {} expires at {}", if htlc_outbound { "outbound" } else { "inbound"}, htlc.payment_hash, htlc.cltv_expiry); return Some(htlc.payment_hash); } } @@ -6097,9 +6071,9 @@ impl ChannelMonitorImpl { /// Check if any transaction broadcasted is resolving HTLC output by a success or timeout on a holder /// or counterparty commitment tx, if so send back the source, preimage if found and payment_hash of resolved HTLC #[rustfmt::skip] - fn is_resolving_htlc_output( - &mut self, tx: &Transaction, height: u32, block_hash: &BlockHash, logger: &WithChannelMonitor, - ) where L::Target: Logger { + fn is_resolving_htlc_output( + &mut self, tx: &Transaction, height: u32, block_hash: &BlockHash, + ) { let funding_spent = get_confirmed_funding_scope!(self); 'outer_loop: for input in &tx.input { @@ -6135,12 +6109,12 @@ impl ChannelMonitorImpl { revocation_sig_claim as u8, 1); if ($holder_tx && revocation_sig_claim) || (outbound_htlc && !$source_avail && (accepted_preimage_claim || offered_preimage_claim)) { - log_error!(logger, "Input spending {} ({}:{}) in {} resolves {} HTLC with payment hash {} with {}!", + log_error!("Input spending {} ({}:{}) in {} resolves {} HTLC with payment hash {} with {}!", $tx_info, input.previous_output.txid, input.previous_output.vout, tx.compute_txid(), if outbound_htlc { "outbound" } else { "inbound" }, &$htlc.payment_hash, if revocation_sig_claim { "revocation sig" } else { "preimage claim after we'd passed the HTLC resolution back. We can likely claim the HTLC output with a revocation claim" }); } else { - log_info!(logger, "Input spending {} ({}:{}) in {} resolves {} HTLC with payment hash {} with {}", + log_info!("Input spending {} ({}:{}) in {} resolves {} HTLC with payment hash {} with {}", $tx_info, input.previous_output.txid, input.previous_output.vout, tx.compute_txid(), if outbound_htlc { "outbound" } else { "inbound" }, &$htlc.payment_hash, if revocation_sig_claim { "revocation sig" } else if accepted_preimage_claim || offered_preimage_claim { "preimage" } else { "timeout" }); @@ -6299,7 +6273,7 @@ impl ChannelMonitorImpl { commitment_tx_output_idx: Some(input.previous_output.vout), }, }; - log_info!(logger, "Failing HTLC with payment_hash {} timeout by a spend tx, waiting for confirmation (at height {})", &payment_hash, entry.confirmation_threshold()); + log_info!("Failing HTLC with payment_hash {} timeout by a spend tx, waiting for confirmation (at height {})", &payment_hash, entry.confirmation_threshold()); self.onchain_events_awaiting_threshold_conf.push(entry); } } @@ -6354,9 +6328,9 @@ impl ChannelMonitorImpl { /// Checks if the confirmed transaction is paying funds back to some address we can assume to /// own. #[rustfmt::skip] - fn check_tx_and_push_spendable_outputs( - &mut self, tx: &Transaction, height: u32, block_hash: &BlockHash, logger: &WithChannelMonitor, - ) where L::Target: Logger { + fn check_tx_and_push_spendable_outputs( + &mut self, tx: &Transaction, height: u32, block_hash: &BlockHash, + ) { let funding_spent = get_confirmed_funding_scope!(self); for spendable_output in self.get_spendable_outputs(funding_spent, tx) { let entry = OnchainEventEntry { @@ -6366,7 +6340,7 @@ impl ChannelMonitorImpl { block_hash: Some(*block_hash), event: OnchainEvent::MaturingOutput { descriptor: spendable_output.clone() }, }; - log_info!(logger, "Received spendable output {}, spendable at height {}", log_spendable!(spendable_output), entry.confirmation_threshold()); + log_info!("Received spendable output {}, spendable at height {}", log_spendable!(spendable_output), entry.confirmation_threshold()); self.onchain_events_awaiting_threshold_conf.push(entry); } } diff --git a/lightning/src/chain/onchaintx.rs b/lightning/src/chain/onchaintx.rs index fb65aa0f157..dceac73701a 100644 --- a/lightning/src/chain/onchaintx.rs +++ b/lightning/src/chain/onchaintx.rs @@ -34,7 +34,6 @@ use crate::ln::chan_utils::{ }; use crate::ln::msgs::DecodeError; use crate::sign::{ecdsa::EcdsaChannelSigner, EntropySource, HTLCDescriptor, SignerProvider}; -use crate::util::logger::Logger; use crate::util::ser::{ MaybeReadable, Readable, ReadableArgs, UpgradableRequired, Writeable, Writer, }; @@ -485,10 +484,10 @@ impl OnchainTxHandler { /// invoking this every 30 seconds, or lower if running in an environment with spotty /// connections, like on mobile. #[rustfmt::skip] - pub(super) fn rebroadcast_pending_claims( + pub(super) fn rebroadcast_pending_claims( &mut self, current_height: u32, feerate_strategy: FeerateStrategy, broadcaster: &B, conf_target: ConfirmationTarget, destination_script: &Script, - fee_estimator: &LowerBoundedFeeEstimator, logger: &L, + fee_estimator: &LowerBoundedFeeEstimator, ) where B::Target: BroadcasterInterface, @@ -497,13 +496,13 @@ impl OnchainTxHandler { let mut bump_requests = Vec::with_capacity(self.pending_claim_requests.len()); for (claim_id, request) in self.pending_claim_requests.iter() { let inputs = request.outpoints(); - log_info!(logger, "Triggering rebroadcast/fee-bump for request with inputs {:?}", inputs); + log_info!("Triggering rebroadcast/fee-bump for request with inputs {:?}", inputs); bump_requests.push((*claim_id, request.clone())); } for (claim_id, request) in bump_requests { self.generate_claim( current_height, &request, &feerate_strategy, conf_target, destination_script, - fee_estimator, logger, + fee_estimator, ) .map(|(_, new_feerate, claim)| { let mut feerate_was_bumped = false; @@ -515,15 +514,15 @@ impl OnchainTxHandler { OnchainClaim::Tx(tx) => { if tx.is_fully_signed() { let log_start = if feerate_was_bumped { "Broadcasting RBF-bumped" } else { "Rebroadcasting" }; - log_info!(logger, "{} onchain {}", log_start, log_tx!(tx.0)); + log_info!("{} onchain {}", log_start, log_tx!(tx.0)); broadcaster.broadcast_transactions(&[&tx.0]); } else { - log_info!(logger, "Waiting for signature of unsigned onchain transaction {}", tx.0.compute_txid()); + log_info!("Waiting for signature of unsigned onchain transaction {}", tx.0.compute_txid()); } }, OnchainClaim::Event(event) => { let log_start = if feerate_was_bumped { "Yielding fee-bumped" } else { "Replaying" }; - log_info!(logger, "{} onchain event to spend inputs {:?}", log_start, + log_info!("{} onchain event to spend inputs {:?}", log_start, request.outpoints()); #[cfg(debug_assertions)] { debug_assert!(request.requires_external_funding()); @@ -554,10 +553,10 @@ impl OnchainTxHandler { /// Panics if there are signing errors, because signing operations in reaction to on-chain /// events are not expected to fail, and if they do, we may lose funds. #[rustfmt::skip] - fn generate_claim( + fn generate_claim( &mut self, cur_height: u32, cached_request: &PackageTemplate, feerate_strategy: &FeerateStrategy, conf_target: ConfirmationTarget, - destination_script: &Script, fee_estimator: &LowerBoundedFeeEstimator, logger: &L, + destination_script: &Script, fee_estimator: &LowerBoundedFeeEstimator ) -> Option<(u32, u64, OnchainClaim)> where F::Target: FeeEstimator, { @@ -622,12 +621,12 @@ impl OnchainTxHandler { let predicted_weight = cached_request.package_weight(destination_script); if let Some((output_value, new_feerate)) = cached_request.compute_package_output( predicted_weight, destination_script.minimal_non_dust().to_sat(), - feerate_strategy, conf_target, fee_estimator, logger, + feerate_strategy, conf_target, fee_estimator, ) { assert!(new_feerate != 0); let transaction = cached_request.maybe_finalize_malleable_package( - cur_height, self, Amount::from_sat(output_value), destination_script.into(), logger + cur_height, self, Amount::from_sat(output_value), destination_script.into() ).unwrap(); assert!(predicted_weight >= transaction.0.weight().to_wu()); return Some((new_timer, new_feerate, OnchainClaim::Tx(transaction))); @@ -640,7 +639,7 @@ impl OnchainTxHandler { debug_assert_eq!(inputs.len(), 1); if !cached_request.requires_external_funding() { - return cached_request.maybe_finalize_untractable_package(self, logger) + return cached_request.maybe_finalize_untractable_package(self) .map(|tx| (new_timer, 0, OnchainClaim::Tx(tx))) } @@ -761,16 +760,16 @@ impl OnchainTxHandler { /// does not need to equal the current blockchain tip height, which should be provided via /// `cur_height`, however it must never be higher than `cur_height`. #[rustfmt::skip] - pub(super) fn update_claims_view_from_requests( + pub(super) fn update_claims_view_from_requests( &mut self, mut requests: Vec, conf_height: u32, cur_height: u32, broadcaster: &B, conf_target: ConfirmationTarget, destination_script: &Script, - fee_estimator: &LowerBoundedFeeEstimator, logger: &L + fee_estimator: &LowerBoundedFeeEstimator, ) where B::Target: BroadcasterInterface, F::Target: FeeEstimator, { if !requests.is_empty() { - log_debug!(logger, "Updating claims view at height {} with {} claim requests", cur_height, requests.len()); + log_debug!("Updating claims view at height {} with {} claim requests", cur_height, requests.len()); } // First drop any duplicate claims. @@ -787,14 +786,14 @@ impl OnchainTxHandler { } } if all_outpoints_claiming { - log_info!(logger, "Ignoring second claim for outpoint {}:{}, already registered its claiming request", + log_info!("Ignoring second claim for outpoint {}:{}, already registered its claiming request", req.outpoints()[0].txid, req.outpoints()[0].vout); false } else { let timelocked_equivalent_package = self.locktimed_packages.iter().map(|v| v.1.iter()).flatten() .find(|locked_package| locked_package.outpoints() == req.outpoints()); if let Some(package) = timelocked_equivalent_package { - log_info!(logger, "Ignoring second claim for outpoint {}:{}, we already have one which we're waiting on a timelock at {} for.", + log_info!("Ignoring second claim for outpoint {}:{}, we already have one which we're waiting on a timelock at {} for.", req.outpoints()[0].txid, req.outpoints()[0].vout, package.package_locktime(cur_height)); false } else { @@ -823,9 +822,9 @@ impl OnchainTxHandler { for req in requests { let package_locktime = req.package_locktime(cur_height); if package_locktime > cur_height { - log_info!(logger, "Delaying claim of package until its timelock at {} (current height {}), the following outpoints are spent:", package_locktime, cur_height); + log_info!("Delaying claim of package until its timelock at {} (current height {}), the following outpoints are spent:", package_locktime, cur_height); for outpoint in req.outpoints() { - log_info!(logger, " Outpoint {}", outpoint); + log_info!(" Outpoint {}", outpoint); } self.locktimed_packages.entry(package_locktime).or_default().push(req); } else { @@ -836,13 +835,12 @@ impl OnchainTxHandler { // Claim everything up to and including `cur_height`. let remaining_locked_packages = self.locktimed_packages.split_off(&(cur_height + 1)); if !self.locktimed_packages.is_empty() { - log_debug!(logger, - "Updating claims view at height {} with {} locked packages available for claim", + log_debug!("Updating claims view at height {} with {} locked packages available for claim", cur_height, self.locktimed_packages.len()); } for (pop_height, mut entry) in self.locktimed_packages.iter_mut() { - log_trace!(logger, "Restoring delayed claim of package(s) at their timelock at {}.", pop_height); + log_trace!("Restoring delayed claim of package(s) at their timelock at {}.", pop_height); preprocessed_requests.append(&mut entry); } self.locktimed_packages = remaining_locked_packages; @@ -852,7 +850,7 @@ impl OnchainTxHandler { for mut req in preprocessed_requests { if let Some((new_timer, new_feerate, claim)) = self.generate_claim( cur_height, &req, &FeerateStrategy::ForceBump, conf_target, destination_script, - &*fee_estimator, &*logger, + &*fee_estimator ) { req.set_timer(new_timer); req.set_feerate(new_feerate); @@ -862,15 +860,15 @@ impl OnchainTxHandler { let claim_id = match claim { OnchainClaim::Tx(tx) => { if tx.is_fully_signed() { - log_info!(logger, "Broadcasting onchain {}", log_tx!(tx.0)); + log_info!("Broadcasting onchain {}", log_tx!(tx.0)); broadcaster.broadcast_transactions(&[&tx.0]); } else { - log_info!(logger, "Waiting for signature of unsigned onchain transaction {}", tx.0.compute_txid()); + log_info!("Waiting for signature of unsigned onchain transaction {}", tx.0.compute_txid()); } ClaimId(tx.0.compute_txid().to_byte_array()) }, OnchainClaim::Event(claim_event) => { - log_info!(logger, "Yielding onchain event to spend inputs {:?}", req.outpoints()); + log_info!("Yielding onchain event to spend inputs {:?}", req.outpoints()); let claim_id = match claim_event { ClaimEvent::BumpCommitment { ref commitment_tx, .. } => // For commitment claims, we can just use their txid as it should @@ -895,7 +893,7 @@ impl OnchainTxHandler { debug_assert!(cfg!(fuzzing) || self.pending_claim_requests.get(&claim_id).is_none()); for (k, outpoint_confirmation_height) in req.outpoints_and_creation_heights() { let creation_height = outpoint_confirmation_height.unwrap_or(conf_height); - log_info!(logger, "Registering claiming request for {}:{}, which exists as of height {creation_height}", k.txid, k.vout); + log_info!("Registering claiming request for {}:{}, which exists as of height {creation_height}", k.txid, k.vout); self.claimable_outpoints.insert(k.clone(), (claim_id, creation_height)); } self.pending_claim_requests.insert(claim_id, req); @@ -912,10 +910,10 @@ impl OnchainTxHandler { /// confirmed. This does not need to equal the current blockchain tip height, which should be /// provided via `cur_height`, however it must never be higher than `cur_height`. #[rustfmt::skip] - pub(super) fn update_claims_view_from_matched_txn( + pub(super) fn update_claims_view_from_matched_txn( &mut self, txn_matched: &[&Transaction], conf_height: u32, conf_hash: BlockHash, cur_height: u32, broadcaster: &B, conf_target: ConfirmationTarget, - destination_script: &Script, fee_estimator: &LowerBoundedFeeEstimator, logger: &L + destination_script: &Script, fee_estimator: &LowerBoundedFeeEstimator, ) where B::Target: BroadcasterInterface, F::Target: FeeEstimator, @@ -923,7 +921,7 @@ impl OnchainTxHandler { let mut have_logged_intro = false; let mut maybe_log_intro = || { if !have_logged_intro { - log_debug!(logger, "Updating claims view at height {} with {} matched transactions in block {}", cur_height, txn_matched.len(), conf_height); + log_debug!("Updating claims view at height {} with {} matched transactions in block {}", cur_height, txn_matched.len(), conf_height); have_logged_intro = true; } }; @@ -1039,7 +1037,7 @@ impl OnchainTxHandler { // been aggregated in a single tx and claimed so atomically if let Some(request) = self.pending_claim_requests.remove(&claim_id) { for outpoint in request.outpoints() { - log_debug!(logger, "Removing claim tracking for {} due to maturation of claim package {}.", + log_debug!("Removing claim tracking for {} due to maturation of claim package {}.", outpoint, log_bytes!(claim_id.0)); self.claimable_outpoints.remove(outpoint); } @@ -1052,8 +1050,8 @@ impl OnchainTxHandler { } }, OnchainEvent::ContentiousOutpoint { package } => { - log_debug!(logger, "Removing claim tracking due to maturation of claim tx for outpoints:"); - log_debug!(logger, " {:?}", package.outpoints()); + log_debug!("Removing claim tracking due to maturation of claim tx for outpoints:"); + log_debug!(" {:?}", package.outpoints()); self.claimable_outpoints.remove(package.outpoints()[0]); } } @@ -1072,26 +1070,26 @@ impl OnchainTxHandler { // Build, bump and rebroadcast tx accordingly if !bump_candidates.is_empty() { maybe_log_intro(); - log_trace!(logger, "Bumping {} candidates", bump_candidates.len()); + log_trace!("Bumping {} candidates", bump_candidates.len()); } for (claim_id, request) in bump_candidates.iter() { if let Some((new_timer, new_feerate, bump_claim)) = self.generate_claim( cur_height, &request, &FeerateStrategy::ForceBump, conf_target, destination_script, - &*fee_estimator, &*logger, + &*fee_estimator, ) { match bump_claim { OnchainClaim::Tx(bump_tx) => { if bump_tx.is_fully_signed() { - log_info!(logger, "Broadcasting RBF-bumped onchain {}", log_tx!(bump_tx.0)); + log_info!("Broadcasting RBF-bumped onchain {}", log_tx!(bump_tx.0)); broadcaster.broadcast_transactions(&[&bump_tx.0]); } else { - log_info!(logger, "Waiting for signature of RBF-bumped unsigned onchain transaction {}", + log_info!("Waiting for signature of RBF-bumped unsigned onchain transaction {}", bump_tx.0.compute_txid()); } }, OnchainClaim::Event(claim_event) => { - log_info!(logger, "Yielding RBF-bumped onchain event to spend inputs {:?}", request.outpoints()); + log_info!("Yielding RBF-bumped onchain event to spend inputs {:?}", request.outpoints()); #[cfg(debug_assertions)] { let num_existing = self.pending_claim_events.iter(). filter(|entry| entry.0 == *claim_id).count(); @@ -1110,14 +1108,13 @@ impl OnchainTxHandler { } #[rustfmt::skip] - pub(super) fn transaction_unconfirmed( + pub(super) fn transaction_unconfirmed( &mut self, txid: &Txid, broadcaster: &B, conf_target: ConfirmationTarget, destination_script: &Script, fee_estimator: &LowerBoundedFeeEstimator, - logger: &L, ) where B::Target: BroadcasterInterface, F::Target: FeeEstimator, @@ -1132,15 +1129,15 @@ impl OnchainTxHandler { if let Some(height) = height { self.blocks_disconnected( - height - 1, broadcaster, conf_target, destination_script, fee_estimator, logger, + height - 1, broadcaster, conf_target, destination_script, fee_estimator, ); } } #[rustfmt::skip] - pub(super) fn blocks_disconnected( + pub(super) fn blocks_disconnected( &mut self, new_best_height: u32, broadcaster: &B, conf_target: ConfirmationTarget, - destination_script: &Script, fee_estimator: &LowerBoundedFeeEstimator, logger: &L, + destination_script: &Script, fee_estimator: &LowerBoundedFeeEstimator, ) where B::Target: BroadcasterInterface, F::Target: FeeEstimator, @@ -1179,21 +1176,21 @@ impl OnchainTxHandler { for ((_claim_id, _), ref mut request) in bump_candidates.iter_mut() { if let Some((new_timer, new_feerate, bump_claim)) = self.generate_claim( new_best_height, &request, &FeerateStrategy::ForceBump, conf_target, - destination_script, fee_estimator, logger + destination_script, fee_estimator ) { request.set_timer(new_timer); request.set_feerate(new_feerate); match bump_claim { OnchainClaim::Tx(bump_tx) => { if bump_tx.is_fully_signed() { - log_info!(logger, "Broadcasting onchain {}", log_tx!(bump_tx.0)); + log_info!("Broadcasting onchain {}", log_tx!(bump_tx.0)); broadcaster.broadcast_transactions(&[&bump_tx.0]); } else { - log_info!(logger, "Waiting for signature of unsigned onchain transaction {}", bump_tx.0.compute_txid()); + log_info!("Waiting for signature of unsigned onchain transaction {}", bump_tx.0.compute_txid()); } }, OnchainClaim::Event(claim_event) => { - log_info!(logger, "Yielding onchain event after reorg to spend inputs {:?}", request.outpoints()); + log_info!("Yielding onchain event after reorg to spend inputs {:?}", request.outpoints()); #[cfg(debug_assertions)] { let num_existing = self.pending_claim_events.iter() .filter(|entry| entry.0 == *_claim_id).count(); @@ -1283,7 +1280,7 @@ mod tests { use crate::ln::functional_test_utils::create_dummy_block; use crate::sign::{ChannelDerivationParameters, ChannelSigner, HTLCDescriptor, InMemorySigner}; use crate::types::payment::{PaymentHash, PaymentPreimage}; - use crate::util::test_utils::{TestBroadcaster, TestFeeEstimator, TestLogger}; + use crate::util::test_utils::{TestBroadcaster, TestFeeEstimator}; use super::OnchainTxHandler; @@ -1384,7 +1381,6 @@ mod tests { let fee_estimator = TestFeeEstimator::new(253); let fee_estimator = LowerBoundedFeeEstimator::new(&fee_estimator); - let logger = TestLogger::new(); // Request claiming of each HTLC on the holder's commitment, with current block height 1. let holder_commit = tx_handler.current_holder_commitment_tx(); @@ -1421,7 +1417,6 @@ mod tests { ConfirmationTarget::UrgentOnChainSweep, &destination_script, &fee_estimator, - &logger, ); // HTLC-Timeouts should be broadcast for the HTLCs with expiries at heights 0 and 1. The @@ -1445,7 +1440,6 @@ mod tests { ConfirmationTarget::UrgentOnChainSweep, &destination_script, &fee_estimator, - &logger, ); // The final HTLC-Timeout should now be broadcast. diff --git a/lightning/src/chain/package.rs b/lightning/src/chain/package.rs index db46f3be60d..d6cf9a2b7ec 100644 --- a/lightning/src/chain/package.rs +++ b/lightning/src/chain/package.rs @@ -41,7 +41,6 @@ use crate::sign::ecdsa::EcdsaChannelSigner; use crate::sign::{ChannelDerivationParameters, HTLCDescriptor}; use crate::types::features::ChannelTypeFeatures; use crate::types::payment::PaymentPreimage; -use crate::util::logger::Logger; use crate::util::ser::{Readable, ReadableArgs, RequiredWrapper, Writeable, Writer}; use crate::io; @@ -1392,9 +1391,9 @@ impl PackageTemplate { htlcs } #[rustfmt::skip] - pub(crate) fn maybe_finalize_malleable_package( + pub(crate) fn maybe_finalize_malleable_package< Signer: EcdsaChannelSigner>( &self, current_height: u32, onchain_handler: &mut OnchainTxHandler, value: Amount, - destination_script: ScriptBuf, logger: &L + destination_script: ScriptBuf, ) -> Option { debug_assert!(self.is_malleable()); let mut bumped_tx = Transaction { @@ -1410,19 +1409,19 @@ impl PackageTemplate { bumped_tx.input.push(outp.as_tx_input(*outpoint)); } for (i, (outpoint, out)) in self.inputs.iter().enumerate() { - log_debug!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); + log_debug!("Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); if !out.finalize_input(&mut bumped_tx, i, onchain_handler) { continue; } } Some(MaybeSignedTransaction(bumped_tx)) } #[rustfmt::skip] - pub(crate) fn maybe_finalize_untractable_package( - &self, onchain_handler: &mut OnchainTxHandler, logger: &L, + pub(crate) fn maybe_finalize_untractable_package( + &self, onchain_handler: &mut OnchainTxHandler, ) -> Option { debug_assert!(!self.is_malleable()); if let Some((outpoint, outp)) = self.inputs.first() { if let Some(final_tx) = outp.get_maybe_finalized_tx(outpoint, onchain_handler) { - log_debug!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); + log_debug!("Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); return Some(final_tx); } return None; @@ -1512,9 +1511,9 @@ impl PackageTemplate { /// which was used to generate the value. Will not return less than `dust_limit_sats` for the /// value. #[rustfmt::skip] - pub(crate) fn compute_package_output( + pub(crate) fn compute_package_output( &self, predicted_weight: u64, dust_limit_sats: u64, feerate_strategy: &FeerateStrategy, - conf_target: ConfirmationTarget, fee_estimator: &LowerBoundedFeeEstimator, logger: &L, + conf_target: ConfirmationTarget, fee_estimator: &LowerBoundedFeeEstimator, ) -> Option<(u64, u64)> where F::Target: FeeEstimator, { @@ -1526,12 +1525,12 @@ impl PackageTemplate { if self.feerate_previous != 0 { if let Some((new_fee, feerate)) = feerate_bump( predicted_weight, input_amounts, dust_limit_sats, self.feerate_previous, - feerate_strategy, conf_target, fee_estimator, logger, + feerate_strategy, conf_target, fee_estimator, ) { return Some((cmp::max(input_amounts.saturating_sub(new_fee), dust_limit_sats), feerate)); } } else { - if let Some((new_fee, feerate)) = compute_fee_from_spent_amounts(input_amounts, predicted_weight, conf_target, fee_estimator, logger) { + if let Some((new_fee, feerate)) = compute_fee_from_spent_amounts(input_amounts, predicted_weight, conf_target, fee_estimator) { return Some((cmp::max(input_amounts.saturating_sub(new_fee), dust_limit_sats), feerate)); } } @@ -1675,8 +1674,8 @@ impl Readable for PackageTemplate { /// fee and the corresponding updated feerate. If fee is under [`FEERATE_FLOOR_SATS_PER_KW`], /// we return nothing. #[rustfmt::skip] -fn compute_fee_from_spent_amounts( - input_amounts: u64, predicted_weight: u64, conf_target: ConfirmationTarget, fee_estimator: &LowerBoundedFeeEstimator, logger: &L +fn compute_fee_from_spent_amounts( + input_amounts: u64, predicted_weight: u64, conf_target: ConfirmationTarget, fee_estimator: &LowerBoundedFeeEstimator ) -> Option<(u64, u64)> where F::Target: FeeEstimator, { @@ -1686,7 +1685,7 @@ fn compute_fee_from_spent_amounts( // if the fee rate is below the floor, we don't sweep if fee_rate < FEERATE_FLOOR_SATS_PER_KW { - log_error!(logger, "Failed to generate an on-chain tx with fee ({} sat/kw) was less than the floor ({} sat/kw)", + log_error!("Failed to generate an on-chain tx with fee ({} sat/kw) was less than the floor ({} sat/kw)", fee_rate, FEERATE_FLOOR_SATS_PER_KW); None } else { @@ -1701,10 +1700,10 @@ fn compute_fee_from_spent_amounts( /// respect BIP125 rules 3) and 4) and if required adjust the new fee to meet the RBF policy /// requirement. #[rustfmt::skip] -fn feerate_bump( +fn feerate_bump( predicted_weight: u64, input_amounts: u64, dust_limit_sats: u64, previous_feerate: u64, feerate_strategy: &FeerateStrategy, conf_target: ConfirmationTarget, - fee_estimator: &LowerBoundedFeeEstimator, logger: &L, + fee_estimator: &LowerBoundedFeeEstimator, ) -> Option<(u64, u64)> where F::Target: FeeEstimator, @@ -1713,9 +1712,9 @@ where // If old feerate inferior to actual one given back by Fee Estimator, use it to compute new fee... let (new_fee, new_feerate) = if let Some((new_fee, new_feerate)) = - compute_fee_from_spent_amounts(input_amounts, predicted_weight, conf_target, fee_estimator, logger) + compute_fee_from_spent_amounts(input_amounts, predicted_weight, conf_target, fee_estimator) { - log_debug!(logger, "Initiating fee rate bump from {} s/kWU ({} s) to {} s/kWU ({} s) using {:?} strategy", previous_feerate, previous_fee, new_feerate, new_fee, feerate_strategy); + log_debug!("Initiating fee rate bump from {} s/kWU ({} s) to {} s/kWU ({} s) using {:?} strategy", previous_feerate, previous_fee, new_feerate, new_fee, feerate_strategy); match feerate_strategy { FeerateStrategy::RetryPrevious => { let previous_fee = previous_feerate * predicted_weight / 1000; @@ -1738,7 +1737,7 @@ where }, } } else { - log_warn!(logger, "Can't bump new claiming tx, input amount {} is too small", input_amounts); + log_warn!("Can't bump new claiming tx, input amount {} is too small", input_amounts); return None; }; @@ -1757,17 +1756,17 @@ where let new_fee = cmp::max(new_fee, previous_fee + min_relay_fee); if new_fee > naive_new_fee { - log_debug!(logger, "Naive fee bump of {}s does not meet min relay fee requirements of {}s", naive_new_fee - previous_fee, min_relay_fee); + log_debug!("Naive fee bump of {}s does not meet min relay fee requirements of {}s", naive_new_fee - previous_fee, min_relay_fee); } let remaining_output_amount = input_amounts.saturating_sub(new_fee); if remaining_output_amount < dust_limit_sats { - log_warn!(logger, "Can't bump new claiming tx, output amount {} would end up below dust threshold {}", remaining_output_amount, dust_limit_sats); + log_warn!("Can't bump new claiming tx, output amount {} would end up below dust threshold {}", remaining_output_amount, dust_limit_sats); return None; } let new_feerate = new_fee * 1000 / predicted_weight; - log_debug!(logger, "Fee rate bumped by {}s from {} s/KWU ({} s) to {} s/KWU ({} s)", new_fee - previous_fee, previous_feerate, previous_fee, new_feerate, new_fee); + log_debug!("Fee rate bumped by {}s from {} s/KWU ({} s) to {} s/KWU ({} s)", new_fee - previous_fee, previous_feerate, previous_fee, new_feerate, new_fee); Some((new_fee, new_feerate)) } @@ -1784,6 +1783,7 @@ mod tests { }; use crate::sign::{ChannelDerivationParameters, HTLCDescriptor}; use crate::types::payment::{PaymentHash, PaymentPreimage}; + use crate::util::logger::LoggerScope; use bitcoin::absolute::LockTime; use bitcoin::amount::Amount; @@ -2232,7 +2232,8 @@ mod tests { let input_satoshis = 505; let logger = TestLogger::new(); - let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator, &logger); + let _logger_scope = LoggerScope::new(&logger, "test"); + let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator); assert!(bumped_fee_rate.is_none()); logger.assert_log_regex("lightning::chain::package", regex::Regex::new(r"Can't bump new claiming tx, input amount 505 is too small").unwrap(), 1); } @@ -2250,7 +2251,8 @@ mod tests { let input_satoshis = 2734; let logger = TestLogger::new(); - let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 2188, &fee_rate_strategy, confirmation_target, &fee_estimator, &logger); + let _logger_scope = LoggerScope::new(&logger, "test"); + let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 2188, &fee_rate_strategy, confirmation_target, &fee_estimator); assert!(bumped_fee_rate.is_none()); logger.assert_log_regex("lightning::chain::package", regex::Regex::new(r"Can't bump new claiming tx, output amount 0 would end up below dust threshold 546").unwrap(), 1); } @@ -2261,7 +2263,8 @@ mod tests { let input_satoshis = 506; let logger = TestLogger::new(); - let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator, &logger); + let _logger_scope = LoggerScope::new(&logger, "test"); + let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator); assert!(bumped_fee_rate.is_none()); logger.assert_log_regex("lightning::chain::package", regex::Regex::new(r"Can't bump new claiming tx, output amount 0 would end up below dust threshold 546").unwrap(), 1); } @@ -2272,7 +2275,8 @@ mod tests { let input_satoshis = 1051; let logger = TestLogger::new(); - let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator, &logger); + let _logger_scope = LoggerScope::new(&logger, "test"); + let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator); assert!(bumped_fee_rate.is_none()); logger.assert_log_regex("lightning::chain::package", regex::Regex::new(r"Can't bump new claiming tx, output amount 545 would end up below dust threshold 546").unwrap(), 1); } @@ -2282,7 +2286,8 @@ mod tests { let input_satoshis = 1052; let logger = TestLogger::new(); - let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator, &logger).unwrap(); + let _logger_scope = LoggerScope::new(&logger, "test"); + let bumped_fee_rate = feerate_bump(predicted_weight_units, input_satoshis, 546, 253, &fee_rate_strategy, confirmation_target, &fee_estimator).unwrap(); assert_eq!(bumped_fee_rate, (506, 506)); logger.assert_log_regex("lightning::chain::package", regex::Regex::new(r"Naive fee bump of 63s does not meet min relay fee requirements of 253s").unwrap(), 1); } From 7dd7d6fb63caae012e414bbd19dd409cdc324329 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Wed, 3 Dec 2025 14:16:59 +0100 Subject: [PATCH 3/3] Add log scope to send_payment Demonstrating how the proc macro can be used to set a thread-local logger at a public entry point. The scope name is also picked up and logged via log statements that still have an explicit logger instance. --- lightning/src/ln/channelmanager.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs index 72585d69f80..a4bf1e61e7c 100644 --- a/lightning/src/ln/channelmanager.rs +++ b/lightning/src/ln/channelmanager.rs @@ -22,6 +22,7 @@ use bitcoin::constants::ChainHash; use bitcoin::key::constants::SECRET_KEY_SIZE; use bitcoin::network::Network; use bitcoin::transaction::Transaction; +use lightning_macros::log_scope; use bitcoin::hash_types::{BlockHash, Txid}; use bitcoin::hashes::hmac::Hmac; @@ -5442,6 +5443,7 @@ where /// [`UpdateHTLCs`]: MessageSendEvent::UpdateHTLCs /// [`PeerManager::process_events`]: crate::ln::peer_handler::PeerManager::process_events /// [`ChannelMonitorUpdateStatus::InProgress`]: crate::chain::ChannelMonitorUpdateStatus::InProgress + #[log_scope(name = "send_payment")] pub fn send_payment( &self, payment_hash: PaymentHash, recipient_onion: RecipientOnionFields, payment_id: PaymentId, route_params: RouteParameters, retry_strategy: Retry,