Improve logging in BumpTransactionEventHandler paths
authorWilmer Paulino <wilmer@wilmerpaulino.com>
Tue, 11 Jul 2023 23:43:10 +0000 (16:43 -0700)
committerWilmer Paulino <wilmer@wilmerpaulino.com>
Fri, 14 Jul 2023 21:45:19 +0000 (14:45 -0700)
lightning/src/events/bump_transaction.rs

index dbe1b734e5642339045d89b16b3f9d31b39ba56e..bf56a84ca469b3bac5b4bff53eac17134800e251 100644 (file)
@@ -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<C: secp256k1::Signing + secp256k1::Verification>(&self, secp: &Secp256k1<C>) -> 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<W: Deref> where W::Target: WalletSource {
+pub struct Wallet<W: Deref, L: Deref>
+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<HashMap<OutPoint, ClaimId>>,
 }
 
-impl<W: Deref> Wallet<W> where W::Target: WalletSource {
+impl<W: Deref, L: Deref> Wallet<W, L>
+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<W: Deref> Wallet<W> 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<W: Deref> Wallet<W> 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::<Vec<_>>();
@@ -543,6 +563,8 @@ impl<W: Deref> Wallet<W> 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<W: Deref> Wallet<W> 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<W: Deref> Wallet<W> where W::Target: WalletSource {
        }
 }
 
-impl<W: Deref> CoinSelectionSource for Wallet<W> where W::Target: WalletSource {
+impl<W: Deref, L: Deref> CoinSelectionSource for Wallet<W, L>
+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<W: Deref> CoinSelectionSource for Wallet<W> 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,
                                ) {