From 1db53a9d734593860f89e6af87bb9e3f70758809 Mon Sep 17 00:00:00 2001
From: Elias Rohrer <dev@tnull.de>
Date: Tue, 18 Jul 2023 13:23:20 +0200
Subject: [PATCH] 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.
---
 lightning/src/routing/router.rs | 50 +++++++++++++++++++++++++++++++--
 1 file changed, 47 insertions(+), 3 deletions(-)

diff --git a/lightning/src/routing/router.rs b/lightning/src/routing/router.rs
index caba1391..3419f122 100644
--- 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});
-- 
2.30.2