Merge pull request #1461 from TheBlueMatt/2022-05-unconf-0-not-half
[rust-lightning] / lightning / src / routing / scoring.rs
index 89de0deffde5651d58276f85df50e559a15ecc90..3d10a14c6f2cf7c7d63403ef07f70f8c05ee2e59 100644 (file)
@@ -61,6 +61,7 @@ use util::ser::{Readable, ReadableArgs, Writeable, Writer};
 use util::logger::Logger;
 
 use prelude::*;
+use core::fmt;
 use core::cell::{RefCell, RefMut};
 use core::ops::{Deref, DerefMut};
 use core::time::Duration;
@@ -622,6 +623,33 @@ impl<G: Deref<Target = NetworkGraph>, L: Deref, T: Time> ProbabilisticScorerUsin
                assert!(self.channel_liquidities.insert(short_channel_id, liquidity).is_none());
                self
        }
+
+       /// Dump the contents of this scorer into the configured logger.
+       ///
+       /// Note that this writes roughly one line per channel for which we have a liquidity estimate,
+       /// which may be a substantial amount of log output.
+       pub fn debug_log_liquidity_stats(&self) {
+               let graph = self.network_graph.read_only();
+               for (scid, liq) in self.channel_liquidities.iter() {
+                       if let Some(chan_debug) = graph.channels().get(scid) {
+                               let log_direction = |source, target| {
+                                       if let Some((directed_info, _)) = chan_debug.as_directed_to(target) {
+                                               let amt = directed_info.effective_capacity().as_msat();
+                                               let dir_liq = liq.as_directed(source, target, amt, self.params.liquidity_offset_half_life);
+                                               log_debug!(self.logger, "Liquidity from {:?} to {:?} via {} is in the range ({}, {})",
+                                                       source, target, scid, dir_liq.min_liquidity_msat(), dir_liq.max_liquidity_msat());
+                                       } else {
+                                               log_debug!(self.logger, "No amount known for SCID {} from {:?} to {:?}", scid, source, target);
+                                       }
+                               };
+
+                               log_direction(&chan_debug.node_one, &chan_debug.node_two);
+                               log_direction(&chan_debug.node_two, &chan_debug.node_one);
+                       } else {
+                               log_debug!(self.logger, "No network graph entry for SCID {}", scid);
+                       }
+               }
+       }
 }
 
 impl ProbabilisticScoringParameters {
@@ -790,22 +818,29 @@ impl<L: Deref<Target = u64>, T: Time, U: Deref<Target = T>> DirectedChannelLiqui
 
 impl<L: DerefMut<Target = u64>, T: Time, U: DerefMut<Target = T>> DirectedChannelLiquidity<L, T, U> {
        /// Adjusts the channel liquidity balance bounds when failing to route `amount_msat`.
-       fn failed_at_channel(&mut self, amount_msat: u64) {
+       fn failed_at_channel<Log: Deref>(&mut self, amount_msat: u64, chan_descr: fmt::Arguments, logger: &Log) where Log::Target: Logger {
                if amount_msat < self.max_liquidity_msat() {
+                       log_debug!(logger, "Setting max liquidity of {} to {}", chan_descr, amount_msat);
                        self.set_max_liquidity_msat(amount_msat);
+               } else {
+                       log_trace!(logger, "Max liquidity of {} already more than {}", chan_descr, amount_msat);
                }
        }
 
        /// Adjusts the channel liquidity balance bounds when failing to route `amount_msat` downstream.
-       fn failed_downstream(&mut self, amount_msat: u64) {
+       fn failed_downstream<Log: Deref>(&mut self, amount_msat: u64, chan_descr: fmt::Arguments, logger: &Log) where Log::Target: Logger {
                if amount_msat > self.min_liquidity_msat() {
+                       log_debug!(logger, "Setting min liquidity of {} to {}", chan_descr, amount_msat);
                        self.set_min_liquidity_msat(amount_msat);
+               } else {
+                       log_trace!(logger, "Min liquidity of {} already less than {}", chan_descr, amount_msat);
                }
        }
 
        /// Adjusts the channel liquidity balance bounds when successfully routing `amount_msat`.
-       fn successful(&mut self, amount_msat: u64) {
+       fn successful<Log: Deref>(&mut self, amount_msat: u64, chan_descr: fmt::Arguments, logger: &Log) where Log::Target: Logger {
                let max_liquidity_msat = self.max_liquidity_msat().checked_sub(amount_msat).unwrap_or(0);
+               log_debug!(logger, "Subtracting {} from max liquidity of {} (setting it to {})", amount_msat, chan_descr, max_liquidity_msat);
                self.set_max_liquidity_msat(max_liquidity_msat);
        }
 
@@ -848,13 +883,18 @@ impl<G: Deref<Target = NetworkGraph>, L: Deref, T: Time> Score for Probabilistic
        fn payment_path_failed(&mut self, path: &[&RouteHop], short_channel_id: u64) {
                let amount_msat = path.split_last().map(|(hop, _)| hop.fee_msat).unwrap_or(0);
                let liquidity_offset_half_life = self.params.liquidity_offset_half_life;
+               log_trace!(self.logger, "Scoring path through to SCID {} as having failed at {} msat", short_channel_id, amount_msat);
                let network_graph = self.network_graph.read_only();
-               for hop in path {
+               for (hop_idx, hop) in path.iter().enumerate() {
                        let target = NodeId::from_pubkey(&hop.pubkey);
                        let channel_directed_from_source = network_graph.channels()
                                .get(&hop.short_channel_id)
                                .and_then(|channel| channel.as_directed_to(&target));
 
+                       if hop.short_channel_id == short_channel_id && hop_idx == 0 {
+                               log_warn!(self.logger, "Payment failed at the first hop - we do not attempt to learn channel info in such cases as we can directly observe local state.\n\tBecause we know the local state, we should generally not see failures here - this may be an indication that your channel peer on channel {} is broken and you may wish to close the channel.", hop.short_channel_id);
+                       }
+
                        // Only score announced channels.
                        if let Some((channel, source)) = channel_directed_from_source {
                                let capacity_msat = channel.effective_capacity().as_msat();
@@ -863,7 +903,7 @@ impl<G: Deref<Target = NetworkGraph>, L: Deref, T: Time> Score for Probabilistic
                                                .entry(hop.short_channel_id)
                                                .or_insert_with(ChannelLiquidity::new)
                                                .as_directed_mut(source, &target, capacity_msat, liquidity_offset_half_life)
-                                               .failed_at_channel(amount_msat);
+                                               .failed_at_channel(amount_msat, format_args!("SCID {}, towards {:?}", hop.short_channel_id, target), &self.logger);
                                        break;
                                }
 
@@ -871,7 +911,10 @@ impl<G: Deref<Target = NetworkGraph>, L: Deref, T: Time> Score for Probabilistic
                                        .entry(hop.short_channel_id)
                                        .or_insert_with(ChannelLiquidity::new)
                                        .as_directed_mut(source, &target, capacity_msat, liquidity_offset_half_life)
-                                       .failed_downstream(amount_msat);
+                                       .failed_downstream(amount_msat, format_args!("SCID {}, towards {:?}", hop.short_channel_id, target), &self.logger);
+                       } else {
+                               log_debug!(self.logger, "Not able to penalize channel with SCID {} as we do not have graph info for it (likely a route-hint last-hop).",
+                                       hop.short_channel_id);
                        }
                }
        }
@@ -879,6 +922,8 @@ impl<G: Deref<Target = NetworkGraph>, L: Deref, T: Time> Score for Probabilistic
        fn payment_path_successful(&mut self, path: &[&RouteHop]) {
                let amount_msat = path.split_last().map(|(hop, _)| hop.fee_msat).unwrap_or(0);
                let liquidity_offset_half_life = self.params.liquidity_offset_half_life;
+               log_trace!(self.logger, "Scoring path through SCID {} as having succeeded at {} msat.",
+                       path.split_last().map(|(hop, _)| hop.short_channel_id).unwrap_or(0), amount_msat);
                let network_graph = self.network_graph.read_only();
                for hop in path {
                        let target = NodeId::from_pubkey(&hop.pubkey);
@@ -893,7 +938,10 @@ impl<G: Deref<Target = NetworkGraph>, L: Deref, T: Time> Score for Probabilistic
                                        .entry(hop.short_channel_id)
                                        .or_insert_with(ChannelLiquidity::new)
                                        .as_directed_mut(source, &target, capacity_msat, liquidity_offset_half_life)
-                                       .successful(amount_msat);
+                                       .successful(amount_msat, format_args!("SCID {}, towards {:?}", hop.short_channel_id, target), &self.logger);
+                       } else {
+                               log_debug!(self.logger, "Not able to learn for channel with SCID {} as we do not have graph info for it (likely a route-hint last-hop).",
+                                       hop.short_channel_id);
                        }
                }
        }