Increase the log level of several channelmonitor/onchain logs.
authorMatt Corallo <git@bluematt.me>
Wed, 23 Jun 2021 03:32:32 +0000 (03:32 +0000)
committerMatt Corallo <git@bluematt.me>
Tue, 29 Jun 2021 19:36:47 +0000 (19:36 +0000)
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
lightning/src/chain/onchaintx.rs
lightning/src/chain/package.rs
lightning/src/ln/channelmanager.rs

index 0bd212705d5f14009cf0fe19a3e750f8b3f39d96..eba96ea6a5ceed1bbbcffbe042ccf90bd2e7d8e0 100644 (file)
@@ -1543,7 +1543,7 @@ impl<Signer: Sign> ChannelMonitorImpl<Signer> {
                        // 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<Signer: Sign> ChannelMonitorImpl<Signer> {
                        }
                        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<Signer: Sign> ChannelMonitorImpl<Signer> {
                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<Signer: Sign> ChannelMonitorImpl<Signer> {
 
                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<Signer: Sign> ChannelMonitorImpl<Signer> {
        }
 
        pub fn get_latest_holder_commitment_txn<L: Deref>(&mut self, logger: &L) -> Vec<Transaction> 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<Signer: Sign> ChannelMonitorImpl<Signer> {
        #[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<L: Deref>(&mut self, logger: &L) -> Vec<Transaction> 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<Signer: Sign> ChannelMonitorImpl<Signer> {
                                                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<Signer: Sign> ChannelMonitorImpl<Signer> {
                                        }));
                                },
                                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<Signer: Sign> ChannelMonitorImpl<Signer> {
                                                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<Signer: Sign> ChannelMonitorImpl<Signer> {
                                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);
                }
        }
index 30493eb56c696ed2f055d477db033a4cecfe8500..cb34c59b3995daf36bceea7a755a70a27e094878 100644 (file)
@@ -382,7 +382,7 @@ impl<ChannelSigner: Sign> OnchainTxHandler<ChannelSigner> {
                      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<ChannelSigner: Sign> OnchainTxHandler<ChannelSigner> {
                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<ChannelSigner: Sign> OnchainTxHandler<ChannelSigner> {
                                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<ChannelSigner: Sign> OnchainTxHandler<ChannelSigner> {
                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);
index bd983ecd9163589b19b12f85199c9d851d0fb5f0..bda924d5565a0dcd15e7850854024d4ee582c2d9 100644 (file)
@@ -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<F: Deref, L: Deref>(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;
        };
 
index 84e500c54d6054ebfd368cf984d027b42cc0aa28..a9e714cea7bf245b9bc536f87221ffbcfa57a183 100644 (file)
@@ -2667,7 +2667,7 @@ impl<Signer: Sign, M: Deref, T: Deref, K: Deref, F: Deref, L: Deref> 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(),