Improve logging for ignored candiate hops

Previously, we barely gave any hints why we excluded certain hops during
pathfinding. Here, we introduce more verbose logging by a) accounting
how much candidates we ignored for which reasons and b) logging any
first/last/blinded hops we end up ignoring.

Fixes #1646.

diff --git a/lightning/src/routing/router.rs b/lightning/src/routing/router.rs
index caba139103249179228738a6aa7bca3c0e54c378..3419f122e7ddfa907ffde3b44c2ee89f47ca6518 100644 (file)
--- a/lightning/src/routing/router.rs
+++ b/lightning/src/routing/router.rs
@@ -1333,6 +1333,14 @@ impl<'a> fmt::Display for LoggedCandidateHop<'a> {
                                " and blinding point ".fmt(f)?;
                                hint.1.blinding_point.fmt(f)
                        },
+                       CandidateRouteHop::FirstHop { .. } => {
+                               "first hop with SCID ".fmt(f)?;
+                               self.0.short_channel_id().unwrap().fmt(f)
+                       },
+                       CandidateRouteHop::PrivateHop { .. } => {
+                               "route hint with SCID ".fmt(f)?;
+                               self.0.short_channel_id().unwrap().fmt(f)
+                       },
                        _ => {
                                "SCID ".fmt(f)?;
                                self.0.short_channel_id().unwrap().fmt(f)
@@ -1640,6 +1648,12 @@ where L::Target: Logger {
        log_trace!(logger, "Building path from {} to payer {} for value {} msat.",
                LoggedPayeePubkey(payment_params.payee.node_id()), our_node_pubkey, final_value_msat);
 
+       // Remember how many candidates we ignored to allow for some logging afterwards.
+       let mut num_ignored_value_contribution = 0;
+       let mut num_ignored_path_length_limit = 0;
+       let mut num_ignored_cltv_delta_limit = 0;
+       let mut num_ignored_previously_failed = 0;
+
        macro_rules! add_entry {
                // Adds entry which goes from $src_node_id to $dest_node_id over the $candidate hop.
                // $next_hops_fee_msat represents the fees paid for using all the channels *after* this one,
@@ -1714,13 +1728,37 @@ where L::Target: Logger {
                                        let payment_failed_on_this_channel = scid_opt.map_or(false,
                                                |scid| payment_params.previously_failed_channels.contains(&scid));
 
+                                       let should_log_candidate = match $candidate {
+                                               CandidateRouteHop::FirstHop { .. } => true,
+                                               CandidateRouteHop::PrivateHop { .. } => true,
+                                               CandidateRouteHop::Blinded { .. } => true,
+                                               _ => false,
+                                       };
+
                                        // If HTLC minimum is larger than the amount we're going to transfer, we shouldn't
                                        // bother considering this channel. If retrying with recommended_value_msat may
                                        // allow us to hit the HTLC minimum limit, set htlc_minimum_limit so that we go
                                        // around again with a higher amount.
-                                       if !contributes_sufficient_value || exceeds_max_path_length ||
-                                               exceeds_cltv_delta_limit || payment_failed_on_this_channel {
-                                               // Path isn't useful, ignore it and move on.
+                                       if !contributes_sufficient_value {
+                                               if should_log_candidate {
+                                                       log_trace!(logger, "Ignoring {} due to insufficient value contribution.", LoggedCandidateHop(&$candidate));
+                                               }
+                                               num_ignored_value_contribution += 1;
+                                       } else if exceeds_max_path_length {
+                                               if should_log_candidate {
+                                                       log_trace!(logger, "Ignoring {} due to exceeding maximum path length limit.", LoggedCandidateHop(&$candidate));
+                                               }
+                                               num_ignored_path_length_limit += 1;
+                                       } else if exceeds_cltv_delta_limit {
+                                               if should_log_candidate {
+                                                       log_trace!(logger, "Ignoring {} due to exceeding CLTV delta limit.", LoggedCandidateHop(&$candidate));
+                                               }
+                                               num_ignored_cltv_delta_limit += 1;
+                                       } else if payment_failed_on_this_channel {
+                                               if should_log_candidate {
+                                                       log_trace!(logger, "Ignoring {} due to a failed previous payment attempt.", LoggedCandidateHop(&$candidate));
+                                               }
+                                               num_ignored_previously_failed += 1;
                                        } else if may_overpay_to_meet_path_minimum_msat {
                                                hit_minimum_limit = true;
                                        } else if over_path_minimum_msat {
@@ -2322,6 +2360,12 @@ where L::Target: Logger {
                }
        }
 
+       let num_ignored_total = num_ignored_value_contribution + num_ignored_path_length_limit +
+               num_ignored_cltv_delta_limit + num_ignored_previously_failed;
+       if num_ignored_total > 0 {
+               log_trace!(logger, "Ignored {} candidate hops due to insufficient value contribution, {} due to path length limit, {} due to CLTV delta limit, {} due to previous payment failure. Total: {} ignored candidates.", num_ignored_value_contribution, num_ignored_path_length_limit, num_ignored_cltv_delta_limit, num_ignored_previously_failed, num_ignored_total);
+       }
+
        // Step (5).
        if payment_paths.len() == 0 {
                return Err(LightningError{err: "Failed to find a path to the given destination".to_owned(), action: ErrorAction::IgnoreError});