From 74717d390c3ac654978d1a22123d9085729529cd Mon Sep 17 00:00:00 2001 From: Matt Corallo Date: Wed, 23 Jun 2021 03:32:32 +0000 Subject: [PATCH] Increase the log level of several channelmonitor/onchain logs. ChannelMonitor and related log entries can generally lean towards being higher log levels than they necessarily need to be, as they should be exceedingly rare, if only because they require confirmation of an on-chain transaction. --- lightning/src/chain/channelmonitor.rs | 22 +++++++++++----------- lightning/src/chain/onchaintx.rs | 16 ++++++++-------- lightning/src/chain/package.rs | 12 ++++++------ lightning/src/ln/channelmanager.rs | 2 +- 4 files changed, 26 insertions(+), 26 deletions(-) diff --git a/lightning/src/chain/channelmonitor.rs b/lightning/src/chain/channelmonitor.rs index 0bd212705..eba96ea6a 100644 --- a/lightning/src/chain/channelmonitor.rs +++ b/lightning/src/chain/channelmonitor.rs @@ -1543,7 +1543,7 @@ 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_trace!(logger, "Got broadcast of revoked counterparty commitment transaction, going to generate general spend tx with {} inputs", claimable_outpoints.len()); + log_error!(logger, "Got broadcast of revoked counterparty commitment transaction, going to generate general spend tx with {} inputs", claimable_outpoints.len()); for (idx, outp) in tx.output.iter().enumerate() { watch_outputs.push((idx as u32, outp.clone())); } @@ -1599,7 +1599,7 @@ impl ChannelMonitorImpl { } self.counterparty_commitment_txn_on_chain.insert(commitment_txid, commitment_number); - log_trace!(logger, "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid); + log_info!(logger, "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid); macro_rules! check_htlc_fails { ($txid: expr, $commitment_tx: expr, $id: tt) => { @@ -1717,7 +1717,7 @@ impl ChannelMonitorImpl { let per_commitment_key = ignore_error!(SecretKey::from_slice(&secret)); let per_commitment_point = PublicKey::from_secret_key(&self.secp_ctx, &per_commitment_key); - log_trace!(logger, "Counterparty HTLC broadcast {}:{}", htlc_txid, 0); + log_error!(logger, "Got broadcast of revoked counterparty HTLC transaction, spending {}:{}", htlc_txid, 0); let revk_outp = RevokedOutput::build(per_commitment_point, self.counterparty_tx_cache.counterparty_delayed_payment_base_key, self.counterparty_tx_cache.counterparty_htlc_base_key, per_commitment_key, tx.output[0].value, self.counterparty_tx_cache.on_counterparty_tx_csv); let justice_package = PackageTemplate::build_package(htlc_txid, 0, PackageSolvingData::RevokedOutput(revk_outp), height + self.counterparty_tx_cache.on_counterparty_tx_csv as u32, true, height); let claimable_outpoints = vec!(justice_package); @@ -1808,14 +1808,14 @@ impl ChannelMonitorImpl { if self.current_holder_commitment_tx.txid == commitment_txid { is_holder_tx = true; - log_trace!(logger, "Got latest holder commitment tx broadcast, searching for available HTLCs to claim"); + log_info!(logger, "Got broadcast of latest holder commitment tx {}, searching for available HTLCs to claim", commitment_txid); let res = self.get_broadcasted_holder_claims(&self.current_holder_commitment_tx, height); let mut to_watch = self.get_broadcasted_holder_watch_outputs(&self.current_holder_commitment_tx, tx); append_onchain_update!(res, to_watch); } else if let &Some(ref holder_tx) = &self.prev_holder_signed_commitment_tx { if holder_tx.txid == commitment_txid { is_holder_tx = true; - log_trace!(logger, "Got previous holder commitment tx broadcast, searching for available HTLCs to claim"); + log_info!(logger, "Got broadcast of previous holder commitment tx {}, searching for available HTLCs to claim", commitment_txid); let res = self.get_broadcasted_holder_claims(holder_tx, height); let mut to_watch = self.get_broadcasted_holder_watch_outputs(holder_tx, tx); append_onchain_update!(res, to_watch); @@ -1845,7 +1845,7 @@ impl ChannelMonitorImpl { } pub fn get_latest_holder_commitment_txn(&mut self, logger: &L) -> Vec where L::Target: Logger { - log_trace!(logger, "Getting signed latest holder commitment transaction!"); + log_debug!(logger, "Getting signed latest holder commitment transaction!"); self.holder_tx_signed = true; let commitment_tx = self.onchain_tx_handler.get_fully_signed_holder_tx(&self.funding_redeemscript); let txid = commitment_tx.txid(); @@ -1879,7 +1879,7 @@ impl ChannelMonitorImpl { #[cfg(any(test,feature = "unsafe_revoked_tx_signing"))] /// Note that this includes possibly-locktimed-in-the-future transactions! fn unsafe_get_latest_holder_commitment_txn(&mut self, logger: &L) -> Vec where L::Target: Logger { - log_trace!(logger, "Getting signed copy of latest holder commitment transaction!"); + log_debug!(logger, "Getting signed copy of latest holder commitment transaction!"); let commitment_tx = self.onchain_tx_handler.get_fully_signed_copy_holder_tx(&self.funding_redeemscript); let txid = commitment_tx.txid(); let mut holder_transactions = vec![commitment_tx]; @@ -2086,7 +2086,7 @@ impl ChannelMonitorImpl { matured_htlcs.push(source.clone()); } - log_trace!(logger, "HTLC {} failure update has got enough confirmations to be passed upstream", log_bytes!(payment_hash.0)); + log_debug!(logger, "HTLC {} failure update has got enough confirmations to be passed upstream", log_bytes!(payment_hash.0)); self.pending_monitor_events.push(MonitorEvent::HTLCEvent(HTLCUpdate { payment_hash: payment_hash, payment_preimage: None, @@ -2094,7 +2094,7 @@ impl ChannelMonitorImpl { })); }, OnchainEvent::MaturingOutput { descriptor } => { - log_trace!(logger, "Descriptor {} has got enough confirmations to be passed upstream", log_spendable!(descriptor)); + log_debug!(logger, "Descriptor {} has got enough confirmations to be passed upstream", log_spendable!(descriptor)); self.pending_events.push(Event::SpendableOutputs { outputs: vec![descriptor] }); @@ -2398,7 +2398,7 @@ impl ChannelMonitorImpl { height, event: OnchainEvent::HTLCUpdate { source: source, payment_hash: payment_hash }, }; - log_info!(logger, "Failing HTLC with payment_hash {} timeout by a spend tx, waiting for confirmation (at height{})", log_bytes!(payment_hash.0), entry.confirmation_threshold()); + log_info!(logger, "Failing HTLC with payment_hash {} timeout by a spend tx, waiting for confirmation (at height {})", log_bytes!(payment_hash.0), entry.confirmation_threshold()); self.onchain_events_awaiting_threshold_conf.push(entry); } } @@ -2463,7 +2463,7 @@ impl ChannelMonitorImpl { height: height, event: OnchainEvent::MaturingOutput { descriptor: spendable_output.clone() }, }; - log_trace!(logger, "Maturing {} until {}", log_spendable!(spendable_output), entry.confirmation_threshold()); + log_info!(logger, "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 30493eb56..cb34c59b3 100644 --- a/lightning/src/chain/onchaintx.rs +++ b/lightning/src/chain/onchaintx.rs @@ -382,7 +382,7 @@ impl OnchainTxHandler { F::Target: FeeEstimator, L::Target: Logger, { - log_trace!(logger, "Updating claims view at height {} with {} matched transactions and {} claim requests", height, txn_matched.len(), requests.len()); + log_debug!(logger, "Updating claims view at height {} with {} matched transactions and {} claim requests", height, txn_matched.len(), requests.len()); let mut preprocessed_requests = Vec::with_capacity(requests.len()); let mut aggregated_request = None; @@ -391,20 +391,20 @@ impl OnchainTxHandler { for req in requests { // Don't claim a outpoint twice that would be bad for privacy and may uselessly lock a CPFP input for a while if let Some(_) = self.claimable_outpoints.get(req.outpoints()[0]) { - log_trace!(logger, "Ignoring second claim for outpoint {}:{}, already registered its claiming request", req.outpoints()[0].txid, req.outpoints()[0].vout); + log_info!(logger, "Ignoring second claim for outpoint {}:{}, already registered its claiming request", req.outpoints()[0].txid, req.outpoints()[0].vout); } 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_trace!(logger, "Ignoring second claim for outpoint {}:{}, we already have one which we're waiting on a timelock at {} for.", + log_info!(logger, "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_timelock()); continue; } if req.package_timelock() > height + 1 { - log_debug!(logger, "Delaying claim of package until its timelock at {} (current height {}), the following outpoints are spent:", req.package_timelock(), height); + log_info!(logger, "Delaying claim of package until its timelock at {} (current height {}), the following outpoints are spent:", req.package_timelock(), height); for outpoint in req.outpoints() { - log_debug!(logger, " Outpoint {}", outpoint); + log_info!(logger, " Outpoint {}", outpoint); } self.locktimed_packages.entry(req.package_timelock()).or_insert(Vec::new()).push(req); continue; @@ -441,11 +441,11 @@ impl OnchainTxHandler { req.set_feerate(new_feerate); let txid = tx.txid(); for k in req.outpoints() { - log_trace!(logger, "Registering claiming request for {}:{}", k.txid, k.vout); + log_info!(logger, "Registering claiming request for {}:{}", k.txid, k.vout); self.claimable_outpoints.insert(k.clone(), (txid, height)); } self.pending_claim_requests.insert(txid, req); - log_trace!(logger, "Broadcasting onchain {}", log_tx!(tx)); + log_info!(logger, "Broadcasting onchain {}", log_tx!(tx)); broadcaster.broadcast_transaction(&tx); } } @@ -562,7 +562,7 @@ impl OnchainTxHandler { log_trace!(logger, "Bumping {} candidates", bump_candidates.len()); for (first_claim_txid, request) in bump_candidates.iter() { if let Some((new_timer, new_feerate, bump_tx)) = self.generate_claim_tx(height, &request, &*fee_estimator, &*logger) { - log_trace!(logger, "Broadcasting onchain {}", log_tx!(bump_tx)); + log_info!(logger, "Broadcasting RBF-bumped onchain {}", log_tx!(bump_tx)); broadcaster.broadcast_transaction(&bump_tx); if let Some(request) = self.pending_claim_requests.get_mut(first_claim_txid) { request.set_timer(new_timer); diff --git a/lightning/src/chain/package.rs b/lightning/src/chain/package.rs index bd983ecd9..bda924d55 100644 --- a/lightning/src/chain/package.rs +++ b/lightning/src/chain/package.rs @@ -603,18 +603,18 @@ impl PackageTemplate { }); } for (i, (outpoint, out)) in self.inputs.iter().enumerate() { - log_trace!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); + log_debug!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); if !out.finalize_input(&mut bumped_tx, i, onchain_handler) { return None; } } - log_trace!(logger, "Finalized transaction {} ready to broadcast", bumped_tx.txid()); + log_debug!(logger, "Finalized transaction {} ready to broadcast", bumped_tx.txid()); return Some(bumped_tx); }, PackageMalleability::Untractable => { debug_assert_eq!(value, 0, "value is ignored for non-malleable packages, should be zero to ensure callsites are correct"); if let Some((outpoint, outp)) = self.inputs.first() { if let Some(final_tx) = outp.get_finalized_tx(outpoint, onchain_handler) { - log_trace!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); - log_trace!(logger, "Finalized transaction {} ready to broadcast", final_tx.txid()); + log_debug!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout); + log_debug!(logger, "Finalized transaction {} ready to broadcast", final_tx.txid()); return Some(final_tx); } return None; @@ -794,13 +794,13 @@ fn feerate_bump(predicted_weight: usize, input_amounts: u64, // ...else just increase the previous feerate by 25% (because that's a nice number) let new_fee = previous_feerate * (predicted_weight as u64) / 750; if input_amounts <= new_fee { - log_trace!(logger, "Can't 25% bump new claiming tx, amount {} is too small", input_amounts); + log_warn!(logger, "Can't 25% bump new claiming tx, amount {} is too small", input_amounts); return None; } new_fee } } else { - log_trace!(logger, "Can't new-estimation bump new claiming tx, amount {} is too small", input_amounts); + log_warn!(logger, "Can't new-estimation bump new claiming tx, amount {} is too small", input_amounts); return None; }; diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs index 84e500c54..a9e714cea 100644 --- a/lightning/src/ln/channelmanager.rs +++ b/lightning/src/ln/channelmanager.rs @@ -2667,7 +2667,7 @@ impl ChannelMana } } if let Some((msg, commitment_signed)) = msgs { - log_debug!(self.logger, "Caliming funds for HTLC with preimage {} resulted in a commitment_signed for channel {}", + log_debug!(self.logger, "Claiming funds for HTLC with preimage {} resulted in a commitment_signed for channel {}", log_bytes!(payment_preimage.0), log_bytes!(chan.get().channel_id())); channel_state.pending_msg_events.push(events::MessageSendEvent::UpdateHTLCs { node_id: chan.get().get_counterparty_node_id(), -- 2.39.5