From 964b4939b16f5d768f68ba4ebf2f43e544970d76 Mon Sep 17 00:00:00 2001 From: Wilmer Paulino Date: Tue, 11 Jul 2023 16:43:10 -0700 Subject: [PATCH] Improve logging in BumpTransactionEventHandler paths --- lightning/src/events/bump_transaction.rs | 66 ++++++++++++++++++++---- 1 file changed, 57 insertions(+), 9 deletions(-) diff --git a/lightning/src/events/bump_transaction.rs b/lightning/src/events/bump_transaction.rs index dbe1b734..bf56a84c 100644 --- a/lightning/src/events/bump_transaction.rs +++ b/lightning/src/events/bump_transaction.rs @@ -140,6 +140,15 @@ pub struct HTLCDescriptor { } impl HTLCDescriptor { + /// Returns the outpoint of the HTLC output in the commitment transaction. This is the outpoint + /// being spent by the HTLC input in the HTLC transaction. + pub fn outpoint(&self) -> OutPoint { + OutPoint { + txid: self.commitment_txid, + vout: self.htlc.transaction_output_index.unwrap(), + } + } + /// Returns the UTXO to be spent by the HTLC input, which can be obtained via /// [`Self::unsigned_tx_input`]. pub fn previous_utxo(&self, secp: &Secp256k1) -> TxOut { @@ -480,19 +489,28 @@ pub trait WalletSource { /// A wrapper over [`WalletSource`] that implements [`CoinSelection`] by preferring UTXOs that would /// avoid conflicting double spends. If not enough UTXOs are available to do so, conflicting double /// spends may happen. -pub struct Wallet where W::Target: WalletSource { +pub struct Wallet +where + W::Target: WalletSource, + L::Target: Logger +{ source: W, + logger: L, // TODO: Do we care about cleaning this up once the UTXOs have a confirmed spend? We can do so // by checking whether any UTXOs that exist in the map are no longer returned in // `list_confirmed_utxos`. locked_utxos: Mutex>, } -impl Wallet where W::Target: WalletSource { +impl Wallet +where + W::Target: WalletSource, + L::Target: Logger +{ /// Returns a new instance backed by the given [`WalletSource`] that serves as an implementation /// of [`CoinSelectionSource`]. - pub fn new(source: W) -> Self { - Self { source, locked_utxos: Mutex::new(HashMap::new()) } + pub fn new(source: W, logger: L) -> Self { + Self { source, logger, locked_utxos: Mutex::new(HashMap::new()) } } /// Performs coin selection on the set of UTXOs obtained from @@ -512,6 +530,7 @@ impl Wallet where W::Target: WalletSource { let mut eligible_utxos = utxos.iter().filter_map(|utxo| { if let Some(utxo_claim_id) = locked_utxos.get(&utxo.outpoint) { if *utxo_claim_id != claim_id && !force_conflicting_utxo_spend { + log_trace!(self.logger, "Skipping UTXO {} to prevent conflicting spend", utxo.outpoint); return None; } } @@ -526,6 +545,7 @@ impl Wallet where W::Target: WalletSource { if should_spend { Some((utxo, fee_to_spend_utxo)) } else { + log_trace!(self.logger, "Skipping UTXO {} due to dust proximity after spend", utxo.outpoint); None } }).collect::>(); @@ -543,6 +563,8 @@ impl Wallet where W::Target: WalletSource { selected_utxos.push(utxo.clone()); } if selected_amount < target_amount_sat + total_fees { + log_debug!(self.logger, "Insufficient funds to meet target feerate {} sat/kW", + target_feerate_sat_per_1000_weight); return Err(()); } for utxo in &selected_utxos { @@ -559,6 +581,7 @@ impl Wallet where W::Target: WalletSource { ); let change_output_amount = remaining_amount.saturating_sub(change_output_fee); let change_output = if change_output_amount < change_script.dust_value().to_sat() { + log_debug!(self.logger, "Coin selection attempt did not yield change output"); None } else { Some(TxOut { script_pubkey: change_script, value: change_output_amount }) @@ -571,7 +594,11 @@ impl Wallet where W::Target: WalletSource { } } -impl CoinSelectionSource for Wallet where W::Target: WalletSource { +impl CoinSelectionSource for Wallet +where + W::Target: WalletSource, + L::Target: Logger +{ fn select_confirmed_utxos( &self, claim_id: ClaimId, must_spend: &[Input], must_pay_to: &[TxOut], target_feerate_sat_per_1000_weight: u32, @@ -589,6 +616,8 @@ impl CoinSelectionSource for Wallet where W::Target: WalletSource { ((BASE_TX_SIZE + total_output_size) * WITNESS_SCALE_FACTOR as u64); let target_amount_sat = must_pay_to.iter().map(|output| output.value).sum(); let do_coin_selection = |force_conflicting_utxo_spend: bool, tolerate_high_network_feerates: bool| { + log_debug!(self.logger, "Attempting coin selection targeting {} sat/kW (force_conflicting_utxo_spend = {}, tolerate_high_network_feerates = {})", + target_feerate_sat_per_1000_weight, force_conflicting_utxo_spend, tolerate_high_network_feerates); self.select_confirmed_utxos_internal( &utxos, claim_id, force_conflicting_utxo_spend, tolerate_high_network_feerates, target_feerate_sat_per_1000_weight, preexisting_tx_weight, target_amount_sat, @@ -661,6 +690,7 @@ where // match, but we still need to have at least one output in the transaction for it to be // considered standard. We choose to go with an empty OP_RETURN as it is the cheapest // way to include a dummy output. + log_debug!(self.logger, "Including dummy OP_RETURN output since an output is needed and a change output was not provided"); tx.output.push(TxOut { value: 0, script_pubkey: Script::new_op_return(&[]), @@ -688,6 +718,8 @@ where FEERATE_FLOOR_SATS_PER_KW, ); + log_debug!(self.logger, "Peforming coin selection for anchor transaction targeting {} sat/kW", + anchor_target_feerate_sat_per_1000_weight); let must_spend = vec![Input { outpoint: anchor_descriptor.outpoint, previous_utxo: anchor_descriptor.previous_utxo(), @@ -709,11 +741,13 @@ where ANCHOR_INPUT_WITNESS_WEIGHT + EMPTY_SCRIPT_SIG_WEIGHT; self.process_coin_selection(&mut anchor_tx, coin_selection); + let anchor_txid = anchor_tx.txid(); debug_assert_eq!(anchor_tx.output.len(), 1); #[cfg(debug_assertions)] let unsigned_tx_weight = anchor_tx.weight() as u64 - (anchor_tx.input.len() as u64 * EMPTY_SCRIPT_SIG_WEIGHT); + log_debug!(self.logger, "Signing anchor transaction {}", anchor_txid); self.utxo_source.sign_tx(&mut anchor_tx)?; let signer = anchor_descriptor.derive_channel_signer(&self.signer_provider); let anchor_sig = signer.sign_holder_anchor_input(&anchor_tx, 0, &self.secp)?; @@ -722,10 +756,14 @@ where #[cfg(debug_assertions)] { let signed_tx_weight = anchor_tx.weight() as u64; let expected_signed_tx_weight = unsigned_tx_weight + total_satisfaction_weight; - // Our estimate should be within a 1% error margin of the actual weight. - assert!(expected_signed_tx_weight - (expected_signed_tx_weight / 100) <= signed_tx_weight); + // Our estimate should be within a 1% error margin of the actual weight and we should + // never underestimate. + assert!(expected_signed_tx_weight >= signed_tx_weight && + expected_signed_tx_weight - (expected_signed_tx_weight / 100) <= signed_tx_weight); } + log_info!(self.logger, "Broadcasting anchor transaction {} to bump channel close with txid {}", + anchor_txid, commitment_tx.txid()); self.broadcaster.broadcast_transactions(&[&commitment_tx, &anchor_tx]); Ok(()) } @@ -759,6 +797,8 @@ where htlc_tx.output.push(htlc_output); } + log_debug!(self.logger, "Peforming coin selection for HTLC transaction targeting {} sat/kW", + target_feerate_sat_per_1000_weight); let coin_selection = self.utxo_source.select_confirmed_utxos( claim_id, &must_spend, &htlc_tx.output, target_feerate_sat_per_1000_weight, )?; @@ -771,6 +811,7 @@ where #[cfg(debug_assertions)] let unsigned_tx_weight = htlc_tx.weight() as u64 - (htlc_tx.input.len() as u64 * EMPTY_SCRIPT_SIG_WEIGHT); + log_debug!(self.logger, "Signing HTLC transaction {}", htlc_tx.txid()); self.utxo_source.sign_tx(&mut htlc_tx)?; let mut signers = BTreeMap::new(); for (idx, htlc_descriptor) in htlc_descriptors.iter().enumerate() { @@ -784,10 +825,13 @@ where #[cfg(debug_assertions)] { let signed_tx_weight = htlc_tx.weight() as u64; let expected_signed_tx_weight = unsigned_tx_weight + total_satisfaction_weight; - // Our estimate should be within a 1% error margin of the actual weight. - assert!(expected_signed_tx_weight - (expected_signed_tx_weight / 100) <= signed_tx_weight); + // Our estimate should be within a 1% error margin of the actual weight and we should + // never underestimate. + assert!(expected_signed_tx_weight >= signed_tx_weight && + expected_signed_tx_weight - (expected_signed_tx_weight / 100) <= signed_tx_weight); } + log_info!(self.logger, "Broadcasting {}", log_tx!(htlc_tx)); self.broadcaster.broadcast_transactions(&[&htlc_tx]); Ok(()) } @@ -799,6 +843,8 @@ where claim_id, package_target_feerate_sat_per_1000_weight, commitment_tx, commitment_tx_fee_satoshis, anchor_descriptor, .. } => { + log_info!(self.logger, "Handling channel close bump (claim_id = {}, commitment_txid = {})", + log_bytes!(claim_id.0), commitment_tx.txid()); if let Err(_) = self.handle_channel_close( *claim_id, *package_target_feerate_sat_per_1000_weight, commitment_tx, *commitment_tx_fee_satoshis, anchor_descriptor, @@ -810,6 +856,8 @@ where BumpTransactionEvent::HTLCResolution { claim_id, target_feerate_sat_per_1000_weight, htlc_descriptors, tx_lock_time, } => { + log_info!(self.logger, "Handling HTLC bump (claim_id = {}, htlcs_to_claim = {})", + log_bytes!(claim_id.0), log_iter!(htlc_descriptors.iter().map(|d| d.outpoint()))); if let Err(_) = self.handle_htlc_resolution( *claim_id, *target_feerate_sat_per_1000_weight, htlc_descriptors, *tx_lock_time, ) { -- 2.30.2