Log available liquidity on each channel when starting routefinding 2024-03-log-outbound-channels
authorMatt Corallo <git@bluematt.me>
Tue, 12 Mar 2024 14:29:45 +0000 (14:29 +0000)
committerMatt Corallo <git@bluematt.me>
Thu, 30 May 2024 15:11:07 +0000 (15:11 +0000)
One of the most common first-steps in troubleshooting routefinding
issues is we ask for the local channel state to determine what the
available HTLC bounds are. While we log first-hop channel details
when we decline to use them, this doesn't tell us if we have
missing channels, and thus here we log all first-hop channels at
the start.

We also take this opportunity to log the limits that were violated
any time we log that we're not using a channel, rather than only
when its a first-hop.

lightning/src/routing/router.rs

index b4b238e820b2c6d4ad0f1e9f0ccf096010bd21ec..4212ab68345977b89e60596a36eb7f2a3e6cc467 100644 (file)
@@ -2014,13 +2014,29 @@ where L::Target: Logger {
 
        let max_total_routing_fee_msat = route_params.max_total_routing_fee_msat.unwrap_or(u64::max_value());
 
+       let first_hop_count = first_hops.map(|hops| hops.len()).unwrap_or(0);
        log_trace!(logger, "Searching for a route from payer {} to {} {} MPP and {} first hops {}overriding the network graph of {} nodes and {} channels with a fee limit of {} msat",
                our_node_pubkey, LoggedPayeePubkey(payment_params.payee.node_id()),
                if allow_mpp { "with" } else { "without" },
-               first_hops.map(|hops| hops.len()).unwrap_or(0), if first_hops.is_some() { "" } else { "not " },
+               first_hop_count, if first_hops.is_some() { "" } else { "not " },
                network_graph.nodes().len(), network_graph.channels().len(),
                max_total_routing_fee_msat);
 
+       if first_hop_count < 10 {
+               if let Some(hops) = first_hops {
+                       for hop in hops {
+                               log_trace!(
+                                       logger,
+                                       " First hop through {}/{} can send between {}msat and {}msat (inclusive).",
+                                       hop.counterparty.node_id,
+                                       hop.get_outbound_payment_scid().unwrap_or(0),
+                                       hop.next_outbound_htlc_minimum_msat,
+                                       hop.next_outbound_htlc_limit_msat
+                               );
+                       }
+               }
+       }
+
        // Step (1).
        // Prepare the data we'll use for payee-to-payer search by
        // inserting first hops suggested by the caller as targets.
@@ -2227,14 +2243,9 @@ where L::Target: Logger {
                                        // around again with a higher amount.
                                        if !contributes_sufficient_value {
                                                if should_log_candidate {
-                                                       log_trace!(logger, "Ignoring {} due to insufficient value contribution.", LoggedCandidateHop(&$candidate));
-
-                                                       if let Some(details) = first_hop_details {
-                                                               log_trace!(logger,
-                                                                       "First hop candidate next_outbound_htlc_limit_msat: {}",
-                                                                       details.next_outbound_htlc_limit_msat,
-                                                               );
-                                                       }
+                                                       log_trace!(logger, "Ignoring {} due to insufficient value contribution (channel max {:?}).",
+                                                               LoggedCandidateHop(&$candidate),
+                                                               effective_capacity);
                                                }
                                                num_ignored_value_contribution += 1;
                                        } else if exceeds_max_path_length {
@@ -2263,15 +2274,8 @@ where L::Target: Logger {
                                        } else if may_overpay_to_meet_path_minimum_msat {
                                                if should_log_candidate {
                                                        log_trace!(logger,
-                                                               "Ignoring {} to avoid overpaying to meet htlc_minimum_msat limit.",
-                                                               LoggedCandidateHop(&$candidate));
-
-                                                       if let Some(details) = first_hop_details {
-                                                               log_trace!(logger,
-                                                                       "First hop candidate next_outbound_htlc_minimum_msat: {}",
-                                                                       details.next_outbound_htlc_minimum_msat,
-                                                               );
-                                                       }
+                                                               "Ignoring {} to avoid overpaying to meet htlc_minimum_msat limit ({}).",
+                                                               LoggedCandidateHop(&$candidate), $candidate.htlc_minimum_msat());
                                                }
                                                num_ignored_avoid_overpayment += 1;
                                                hit_minimum_limit = true;