Skip to content

Minor Logging tweaks #2895

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Feb 14, 2024
Merged

Minor Logging tweaks #2895

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
96b141c
Make peers sending gossip out of order logging less scary
TheBlueMatt Feb 13, 2024
aab5b10
Drop some "Channel does not qualify for a feerate change" logs
TheBlueMatt Feb 13, 2024
9125de2
Opportunistically skip log in `update_claims_view_from_requests`
TheBlueMatt Feb 13, 2024
8910153
Opportunistically skip log in `update_claims_view_from_matched_txn`
TheBlueMatt Feb 13, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
27 changes: 24 additions & 3 deletions lightning/src/chain/onchaintx.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -726,7 +726,10 @@ impl<ChannelSigner: WriteableEcdsaChannelSigner> OnchainTxHandler<ChannelSigner>
B::Target: BroadcasterInterface,
F::Target: FeeEstimator,
{
log_debug!(logger, "Updating claims view at height {} with {} claim requests", cur_height, requests.len());
if !requests.is_empty() {
log_debug!(logger, "Updating claims view at height {} with {} claim requests", cur_height, requests.len());
}

Comment on lines +729 to +732
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Consider removing the debug log if it does not provide significant value. Excessive logging, especially at debug level, can clutter log files without offering substantial insights.

let mut preprocessed_requests = Vec::with_capacity(requests.len());
let mut aggregated_request = None;

Expand Down Expand Up @@ -772,6 +775,12 @@ impl<ChannelSigner: WriteableEcdsaChannelSigner> OnchainTxHandler<ChannelSigner>

// 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",
cur_height,
self.locktimed_packages.len());
}
Comment on lines +778 to +783
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This debug log could potentially generate a lot of output if there are many locked packages. Evaluate if this level of verbosity is necessary or if it could be condensed or removed.

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);
preprocessed_requests.append(&mut entry);
Expand Down Expand Up @@ -852,8 +861,15 @@ impl<ChannelSigner: WriteableEcdsaChannelSigner> OnchainTxHandler<ChannelSigner>
B::Target: BroadcasterInterface,
F::Target: FeeEstimator,
{
log_debug!(logger, "Updating claims view at height {} with {} matched transactions in block {}", cur_height, txn_matched.len(), conf_height);
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);
have_logged_intro = true;
}
};
let mut bump_candidates = new_hash_map();
if !txn_matched.is_empty() { maybe_log_intro(); }
for tx in txn_matched {
// Scan all input to verify is one of the outpoint spent is of interest for us
let mut claimed_outputs_material = Vec::new();
Expand Down Expand Up @@ -946,6 +962,7 @@ impl<ChannelSigner: WriteableEcdsaChannelSigner> OnchainTxHandler<ChannelSigner>
self.onchain_events_awaiting_threshold_conf.drain(..).collect::<Vec<_>>();
for entry in onchain_events_awaiting_threshold_conf {
if entry.has_reached_confirmation_threshold(cur_height) {
maybe_log_intro();
match entry.event {
OnchainEvent::Claim { claim_id } => {
// We may remove a whole set of claim outpoints here, as these one may have
Expand Down Expand Up @@ -983,7 +1000,11 @@ impl<ChannelSigner: WriteableEcdsaChannelSigner> OnchainTxHandler<ChannelSigner>
}

// Build, bump and rebroadcast tx accordingly
log_trace!(logger, "Bumping {} candidates", bump_candidates.len());
if !bump_candidates.is_empty() {
maybe_log_intro();
log_trace!(logger, "Bumping {} candidates", bump_candidates.len());
}

Comment on lines +1003 to +1007
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Similar to previous comments on logging, ensure that this trace log provides value. If the information is not actionable or does not significantly aid in debugging, consider removing or reducing the verbosity.

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, &*fee_estimator, &*logger,
Expand Down
4 changes: 0 additions & 4 deletions lightning/src/ln/channelmanager.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4833,10 +4833,6 @@ where

// If the feerate has decreased by less than half, don't bother
if new_feerate <= chan.context.get_feerate_sat_per_1000_weight() && new_feerate * 2 > chan.context.get_feerate_sat_per_1000_weight() {
if new_feerate != chan.context.get_feerate_sat_per_1000_weight() {
log_trace!(logger, "Channel {} does not qualify for a feerate change from {} to {}.",
chan_id, chan.context.get_feerate_sat_per_1000_weight(), new_feerate);
}
return NotifyOption::SkipPersistNoEvents;
}
if !chan.context.is_live() {
Comment on lines 4833 to 4838
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

📝 NOTE
This review was outside the diff hunks, and no overlapping diff hunk was found. Original lines [3-6]

Consider merging the two if conditions into a single compound condition to improve readability and potentially performance by reducing the number of conditional checks.

-		if new_feerate <= chan.context.get_feerate_sat_per_1000_weight() && new_feerate * 2 > chan.context.get_feerate_sat_per_1000_weight() {
-			return NotifyOption::SkipPersistNoEvents;
-		}
-		if !chan.context.is_live() {
+		if (new_feerate <= chan.context.get_feerate_sat_per_1000_weight() && new_feerate * 2 > chan.context.get_feerate_sat_per_1000_weight()) || !chan.context.is_live() {
+			return NotifyOption::SkipPersistNoEvents;
+		}

Expand Down
6 changes: 4 additions & 2 deletions lightning/src/ln/peer_handler.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ use crate::onion_message::offers::{OffersMessage, OffersMessageHandler};
use crate::onion_message::packet::OnionMessageContents;
use crate::routing::gossip::{NodeId, NodeAlias};
use crate::util::atomic_counter::AtomicCounter;
use crate::util::logger::{Logger, WithContext};
use crate::util::logger::{Level, Logger, WithContext};
use crate::util::string::PrintableString;

use crate::prelude::*;
Expand Down Expand Up @@ -1329,7 +1329,9 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
return Err(PeerHandleError { });
},
msgs::ErrorAction::IgnoreAndLog(level) => {
log_given_level!(logger, level, "Error handling message{}; ignoring: {}", OptionalFromDebugger(&peer_node_id), e.err);
log_given_level!(logger, level, "Error handling {}message{}; ignoring: {}",
if level == Level::Gossip { "gossip " } else { "" },
OptionalFromDebugger(&peer_node_id), e.err);
continue
},
msgs::ErrorAction::IgnoreDuplicateGossip => continue, // Don't even bother logging these
Expand Down
5 changes: 4 additions & 1 deletion lightning/src/routing/gossip.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1925,7 +1925,10 @@ impl<L: Deref> NetworkGraph<L> where L::Target: Logger {
None => {
core::mem::drop(channels);
self.pending_checks.check_hold_pending_channel_update(msg, full_msg)?;
return Err(LightningError{err: "Couldn't find channel for update".to_owned(), action: ErrorAction::IgnoreError});
return Err(LightningError {
err: "Couldn't find channel for update".to_owned(),
action: ErrorAction::IgnoreAndLog(Level::Gossip),
});
Comment on lines +1928 to +1931
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The error message "Couldn't find channel for update" could be more descriptive by including the short channel ID in the message.

- Err(LightningError{err: "Couldn't find channel for update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)})
+ Err(LightningError{err: format!("Couldn't find channel for update: {}", msg.short_channel_id), action: ErrorAction::IgnoreAndLog(Level::Gossip)})
Committable suggestion

‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation.

Suggested change
return Err(LightningError {
err: "Couldn't find channel for update".to_owned(),
action: ErrorAction::IgnoreAndLog(Level::Gossip),
});
return Err(LightningError {
err: format!("Couldn't find channel for update: {}", msg.short_channel_id),
action: ErrorAction::IgnoreAndLog(Level::Gossip),
});

},
Some(channel) => {
if msg.htlc_maximum_msat > MAX_VALUE_MSAT {
Expand Down