Explicitly log a warning when a payment failed on the first hop

[rust-lightning] / lightning / src / routing / scoring.rs

diff --git a/lightning/src/routing/scoring.rs b/lightning/src/routing/scoring.rs
index 89de0deffde5651d58276f85df50e559a15ecc90..0e04c63903392b8ccfc36d72c3fa87109b86c17b 100644 (file)
--- a/lightning/src/routing/scoring.rs
+++ b/lightning/src/routing/scoring.rs
@@ -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;
@@ -790,22 +791,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 +856,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 +876,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 +884,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 +895,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 +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)
-                                       .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);
                        }
                }
        }