From: Matt Corallo <649246+TheBlueMatt@users.noreply.github.com> Date: Thu, 28 Apr 2022 02:43:04 +0000 (+0000) Subject: Merge pull request #1435 from TheBlueMatt/2022-04-1126-first-step X-Git-Tag: v0.0.107~51 X-Git-Url: http://git.bitcoin.ninja/index.cgi?a=commitdiff_plain;h=62edee568985e3362bd1609c6089d05428023925;hp=61629bc00ef7d64b56b3dad18d40d29c8037e068;p=rust-lightning Merge pull request #1435 from TheBlueMatt/2022-04-1126-first-step --- diff --git a/lightning-background-processor/src/lib.rs b/lightning-background-processor/src/lib.rs index 6beee915..e23737c0 100644 --- a/lightning-background-processor/src/lib.rs +++ b/lightning-background-processor/src/lib.rs @@ -203,10 +203,22 @@ impl BackgroundProcessor { let mut have_pruned = false; loop { - peer_manager.process_events(); // Note that this may block on ChannelManager's locking channel_manager.process_pending_events(&event_handler); chain_monitor.process_pending_events(&event_handler); + // Note that the PeerManager::process_events may block on ChannelManager's locks, + // hence it comes last here. When the ChannelManager finishes whatever it's doing, + // we want to ensure we get into `persist_manager` as quickly as we can, especially + // without running the normal event processing above and handing events to users. + // + // Specifically, on an *extremely* slow machine, we may see ChannelManager start + // processing a message effectively at any point during this loop. In order to + // minimize the time between such processing completing and persisting the updated + // ChannelManager, we want to minimize methods blocking on a ChannelManager + // generally, and as a fallback place such blocking only immediately before + // persistence. + peer_manager.process_events(); + // We wait up to 100ms, but track how long it takes to detect being put to sleep, // see `await_start`'s use below. let await_start = Instant::now(); @@ -335,10 +347,9 @@ mod tests { use bitcoin::blockdata::constants::genesis_block; use bitcoin::blockdata::transaction::{Transaction, TxOut}; use bitcoin::network::constants::Network; - use lightning::chain::chaininterface::{BroadcasterInterface, FeeEstimator}; - use lightning::chain::{BestBlock, Confirm, chainmonitor, self}; + use lightning::chain::{BestBlock, Confirm, chainmonitor}; use lightning::chain::channelmonitor::ANTI_REORG_DELAY; - use lightning::chain::keysinterface::{InMemorySigner, Recipient, KeysInterface, KeysManager, Sign}; + use lightning::chain::keysinterface::{InMemorySigner, Recipient, KeysInterface, KeysManager}; use lightning::chain::transaction::OutPoint; use lightning::get_event_msg; use lightning::ln::channelmanager::{BREAKDOWN_TIMEOUT, ChainParameters, ChannelManager, SimpleArcChannelManager}; @@ -348,15 +359,13 @@ mod tests { use lightning::routing::network_graph::{NetworkGraph, NetGraphMsgHandler}; use lightning::util::config::UserConfig; use lightning::util::events::{Event, MessageSendEventsProvider, MessageSendEvent}; - use lightning::util::logger::Logger; use lightning::util::ser::Writeable; use lightning::util::test_utils; use lightning::util::persist::KVStorePersister; use lightning_invoice::payment::{InvoicePayer, RetryAttempts}; use lightning_invoice::utils::DefaultRouter; use lightning_persister::FilesystemPersister; - use std::fs::{self, File}; - use std::ops::Deref; + use std::fs; use std::path::PathBuf; use std::sync::{Arc, Mutex}; use std::time::Duration; @@ -399,7 +408,6 @@ mod tests { } struct Persister { - data_dir: String, graph_error: Option<(std::io::ErrorKind, &'static str)>, manager_error: Option<(std::io::ErrorKind, &'static str)>, filesystem_persister: FilesystemPersister, @@ -408,7 +416,7 @@ mod tests { impl Persister { fn new(data_dir: String) -> Self { let filesystem_persister = FilesystemPersister::new(data_dir.clone()); - Self { data_dir, graph_error: None, manager_error: None, filesystem_persister } + Self { graph_error: None, manager_error: None, filesystem_persister } } fn with_graph_error(self, error: std::io::ErrorKind, message: &'static str) -> Self { diff --git a/lightning-block-sync/src/init.rs b/lightning-block-sync/src/init.rs index f5d839d2..b3f745bd 100644 --- a/lightning-block-sync/src/init.rs +++ b/lightning-block-sync/src/init.rs @@ -4,7 +4,7 @@ use crate::{BlockSource, BlockSourceResult, Cache, ChainNotifier}; use crate::poll::{ChainPoller, Validate, ValidatedBlockHeader}; -use bitcoin::blockdata::block::{Block, BlockHeader}; +use bitcoin::blockdata::block::BlockHeader; use bitcoin::hash_types::BlockHash; use bitcoin::network::constants::Network; @@ -203,7 +203,7 @@ impl<'a, C: Cache> Cache for ReadOnlyCache<'a, C> { struct DynamicChainListener<'a, L: chain::Listen + ?Sized>(&'a L); impl<'a, L: chain::Listen + ?Sized> chain::Listen for DynamicChainListener<'a, L> { - fn block_connected(&self, _block: &Block, _height: u32) { + fn filtered_block_connected(&self, _header: &BlockHeader, _txdata: &chain::transaction::TransactionData, _height: u32) { unreachable!() } @@ -216,10 +216,10 @@ impl<'a, L: chain::Listen + ?Sized> chain::Listen for DynamicChainListener<'a, L struct ChainListenerSet<'a, L: chain::Listen + ?Sized>(Vec<(u32, &'a L)>); impl<'a, L: chain::Listen + ?Sized> chain::Listen for ChainListenerSet<'a, L> { - fn block_connected(&self, block: &Block, height: u32) { + fn filtered_block_connected(&self, header: &BlockHeader, txdata: &chain::transaction::TransactionData, height: u32) { for (starting_height, chain_listener) in self.0.iter() { if height > *starting_height { - chain_listener.block_connected(block, height); + chain_listener.filtered_block_connected(header, txdata, height); } } } diff --git a/lightning-block-sync/src/test_utils.rs b/lightning-block-sync/src/test_utils.rs index fe57c0c6..c101d4bd 100644 --- a/lightning-block-sync/src/test_utils.rs +++ b/lightning-block-sync/src/test_utils.rs @@ -166,7 +166,7 @@ impl BlockSource for Blockchain { pub struct NullChainListener; impl chain::Listen for NullChainListener { - fn block_connected(&self, _block: &Block, _height: u32) {} + fn filtered_block_connected(&self, _header: &BlockHeader, _txdata: &chain::transaction::TransactionData, _height: u32) {} fn block_disconnected(&self, _header: &BlockHeader, _height: u32) {} } @@ -195,13 +195,13 @@ impl MockChainListener { } impl chain::Listen for MockChainListener { - fn block_connected(&self, block: &Block, height: u32) { + fn filtered_block_connected(&self, header: &BlockHeader, _txdata: &chain::transaction::TransactionData, height: u32) { match self.expected_blocks_connected.borrow_mut().pop_front() { None => { - panic!("Unexpected block connected: {:?}", block.block_hash()); + panic!("Unexpected block connected: {:?}", header.block_hash()); }, Some(expected_block) => { - assert_eq!(block.block_hash(), expected_block.header.block_hash()); + assert_eq!(header.block_hash(), expected_block.header.block_hash()); assert_eq!(height, expected_block.height); }, } diff --git a/lightning-persister/src/util.rs b/lightning-persister/src/util.rs index 25bd00f5..4adbb33e 100644 --- a/lightning-persister/src/util.rs +++ b/lightning-persister/src/util.rs @@ -84,7 +84,6 @@ mod tests { use super::{write_to_file}; use std::fs; use std::io; - use std::io::Write; use std::path::PathBuf; struct TestWriteable{} diff --git a/lightning/src/chain/chainmonitor.rs b/lightning/src/chain/chainmonitor.rs index 19095fa2..aae260e7 100644 --- a/lightning/src/chain/chainmonitor.rs +++ b/lightning/src/chain/chainmonitor.rs @@ -23,7 +23,7 @@ //! events. The remote server would make use of [`ChainMonitor`] for block processing and for //! servicing [`ChannelMonitor`] updates from the client. -use bitcoin::blockdata::block::{Block, BlockHeader}; +use bitcoin::blockdata::block::BlockHeader; use bitcoin::hash_types::Txid; use chain; @@ -501,9 +501,7 @@ where L::Target: Logger, P::Target: Persist, { - fn block_connected(&self, block: &Block, height: u32) { - let header = &block.header; - let txdata: Vec<_> = block.txdata.iter().enumerate().collect(); + fn filtered_block_connected(&self, header: &BlockHeader, txdata: &TransactionData, height: u32) { log_debug!(self.logger, "New best block {} at height {} provided via block_connected", header.block_hash(), height); self.process_chain_data(header, Some(height), &txdata, |monitor, txdata| { monitor.block_connected( diff --git a/lightning/src/chain/channelmonitor.rs b/lightning/src/chain/channelmonitor.rs index fb2cbadd..681d895f 100644 --- a/lightning/src/chain/channelmonitor.rs +++ b/lightning/src/chain/channelmonitor.rs @@ -20,7 +20,7 @@ //! security-domain-separated system design, you should consider having multiple paths for //! ChannelMonitors to get out of the HSM and onto monitoring devices. -use bitcoin::blockdata::block::{Block, BlockHeader}; +use bitcoin::blockdata::block::BlockHeader; use bitcoin::blockdata::transaction::{TxOut,Transaction}; use bitcoin::blockdata::script::{Script, Builder}; use bitcoin::blockdata::opcodes; @@ -3007,9 +3007,8 @@ where F::Target: FeeEstimator, L::Target: Logger, { - fn block_connected(&self, block: &Block, height: u32) { - let txdata: Vec<_> = block.txdata.iter().enumerate().collect(); - self.0.block_connected(&block.header, &txdata, height, &*self.1, &*self.2, &*self.3); + fn filtered_block_connected(&self, header: &BlockHeader, txdata: &TransactionData, height: u32) { + self.0.block_connected(header, txdata, height, &*self.1, &*self.2, &*self.3); } fn block_disconnected(&self, header: &BlockHeader, height: u32) { diff --git a/lightning/src/chain/mod.rs b/lightning/src/chain/mod.rs index 25e5a97d..24eb09e7 100644 --- a/lightning/src/chain/mod.rs +++ b/lightning/src/chain/mod.rs @@ -87,9 +87,20 @@ pub trait Access { /// sourcing chain data using a block-oriented API should prefer this interface over [`Confirm`]. /// Such clients fetch the entire header chain whereas clients using [`Confirm`] only fetch headers /// when needed. +/// +/// By using [`Listen::filtered_block_connected`] this interface supports clients fetching the +/// entire header chain and only blocks with matching transaction data using BIP 157 filters or +/// other similar filtering. pub trait Listen { + /// Notifies the listener that a block was added at the given height, with the transaction data + /// possibly filtered. + fn filtered_block_connected(&self, header: &BlockHeader, txdata: &TransactionData, height: u32); + /// Notifies the listener that a block was added at the given height. - fn block_connected(&self, block: &Block, height: u32); + fn block_connected(&self, block: &Block, height: u32) { + let txdata: Vec<_> = block.txdata.iter().enumerate().collect(); + self.filtered_block_connected(&block.header, &txdata, height); + } /// Notifies the listener that a block was removed at the given height. fn block_disconnected(&self, header: &BlockHeader, height: u32); @@ -355,8 +366,8 @@ pub struct WatchedOutput { } impl Listen for core::ops::Deref { - fn block_connected(&self, block: &Block, height: u32) { - (**self).block_connected(block, height); + fn filtered_block_connected(&self, header: &BlockHeader, txdata: &TransactionData, height: u32) { + (**self).filtered_block_connected(header, txdata, height); } fn block_disconnected(&self, header: &BlockHeader, height: u32) { @@ -369,9 +380,9 @@ where T::Target: Listen, U::Target: Listen, { - fn block_connected(&self, block: &Block, height: u32) { - self.0.block_connected(block, height); - self.1.block_connected(block, height); + fn filtered_block_connected(&self, header: &BlockHeader, txdata: &TransactionData, height: u32) { + self.0.filtered_block_connected(header, txdata, height); + self.1.filtered_block_connected(header, txdata, height); } fn block_disconnected(&self, header: &BlockHeader, height: u32) { diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs index 4ac575ff..d7f2aeb6 100644 --- a/lightning/src/ln/channelmanager.rs +++ b/lightning/src/ln/channelmanager.rs @@ -18,7 +18,7 @@ //! imply it needs to fail HTLCs/payments/channels it manages). //! -use bitcoin::blockdata::block::{Block, BlockHeader}; +use bitcoin::blockdata::block::BlockHeader; use bitcoin::blockdata::transaction::Transaction; use bitcoin::blockdata::constants::genesis_block; use bitcoin::network::constants::Network; @@ -5310,18 +5310,17 @@ where F::Target: FeeEstimator, L::Target: Logger, { - fn block_connected(&self, block: &Block, height: u32) { + fn filtered_block_connected(&self, header: &BlockHeader, txdata: &TransactionData, height: u32) { { let best_block = self.best_block.read().unwrap(); - assert_eq!(best_block.block_hash(), block.header.prev_blockhash, + assert_eq!(best_block.block_hash(), header.prev_blockhash, "Blocks must be connected in chain-order - the connected header must build on the last connected header"); assert_eq!(best_block.height(), height - 1, "Blocks must be connected in chain-order - the connected block height must be one greater than the previous height"); } - let txdata: Vec<_> = block.txdata.iter().enumerate().collect(); - self.transactions_confirmed(&block.header, &txdata, height); - self.best_block_updated(&block.header, height); + self.transactions_confirmed(header, txdata, height); + self.best_block_updated(header, height); } fn block_disconnected(&self, header: &BlockHeader, height: u32) { diff --git a/lightning/src/ln/peer_handler.rs b/lightning/src/ln/peer_handler.rs index d12f8c06..c09df175 100644 --- a/lightning/src/ln/peer_handler.rs +++ b/lightning/src/ln/peer_handler.rs @@ -1707,7 +1707,11 @@ fn is_gossip_msg(type_id: u16) -> bool { match type_id { msgs::ChannelAnnouncement::TYPE | msgs::ChannelUpdate::TYPE | - msgs::NodeAnnouncement::TYPE => true, + msgs::NodeAnnouncement::TYPE | + msgs::QueryChannelRange::TYPE | + msgs::ReplyChannelRange::TYPE | + msgs::QueryShortChannelIds::TYPE | + msgs::ReplyShortChannelIdsEnd::TYPE => true, _ => false } } diff --git a/lightning/src/routing/router.rs b/lightning/src/routing/router.rs index 2d7e1d20..816dfaad 100644 --- a/lightning/src/routing/router.rs +++ b/lightning/src/routing/router.rs @@ -5352,8 +5352,9 @@ mod tests { let payment_params = PaymentParameters::from_node_id(dst); let amt = seed as u64 % 200_000_000; let params = ProbabilisticScoringParameters::default(); - let scorer = ProbabilisticScorer::new(params, &graph); - if get_route(src, &payment_params, &graph.read_only(), None, amt, 42, &test_utils::TestLogger::new(), &scorer, &random_seed_bytes).is_ok() { + let logger = test_utils::TestLogger::new(); + let scorer = ProbabilisticScorer::new(params, &graph, &logger); + if get_route(src, &payment_params, &graph.read_only(), None, amt, 42, &logger, &scorer, &random_seed_bytes).is_ok() { continue 'load_endpoints; } } @@ -5388,8 +5389,9 @@ mod tests { let payment_params = PaymentParameters::from_node_id(dst).with_features(InvoiceFeatures::known()); let amt = seed as u64 % 200_000_000; let params = ProbabilisticScoringParameters::default(); - let scorer = ProbabilisticScorer::new(params, &graph); - if get_route(src, &payment_params, &graph.read_only(), None, amt, 42, &test_utils::TestLogger::new(), &scorer, &random_seed_bytes).is_ok() { + let logger = test_utils::TestLogger::new(); + let scorer = ProbabilisticScorer::new(params, &graph, &logger); + if get_route(src, &payment_params, &graph.read_only(), None, amt, 42, &logger, &scorer, &random_seed_bytes).is_ok() { continue 'load_endpoints; } } @@ -5435,6 +5437,7 @@ mod benches { use ln::features::{InitFeatures, InvoiceFeatures}; use routing::scoring::{FixedPenaltyScorer, ProbabilisticScorer, ProbabilisticScoringParameters, Scorer}; use util::logger::{Logger, Record}; + use util::test_utils::TestLogger; use test::Bencher; @@ -5519,17 +5522,19 @@ mod benches { #[bench] fn generate_routes_with_probabilistic_scorer(bench: &mut Bencher) { + let logger = TestLogger::new(); let network_graph = read_network_graph(); let params = ProbabilisticScoringParameters::default(); - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); generate_routes(bench, &network_graph, scorer, InvoiceFeatures::empty()); } #[bench] fn generate_mpp_routes_with_probabilistic_scorer(bench: &mut Bencher) { + let logger = TestLogger::new(); let network_graph = read_network_graph(); let params = ProbabilisticScoringParameters::default(); - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); generate_routes(bench, &network_graph, scorer, InvoiceFeatures::known()); } diff --git a/lightning/src/routing/scoring.rs b/lightning/src/routing/scoring.rs index 206cc0a8..0e04c639 100644 --- a/lightning/src/routing/scoring.rs +++ b/lightning/src/routing/scoring.rs @@ -33,14 +33,14 @@ //! # //! // Use the default channel penalties. //! let params = ProbabilisticScoringParameters::default(); -//! let scorer = ProbabilisticScorer::new(params, &network_graph); +//! let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); //! //! // Or use custom channel penalties. //! let params = ProbabilisticScoringParameters { //! liquidity_penalty_multiplier_msat: 2 * 1000, //! ..ProbabilisticScoringParameters::default() //! }; -//! let scorer = ProbabilisticScorer::new(params, &network_graph); +//! let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); //! # let random_seed_bytes = [42u8; 32]; //! //! let route = find_route(&payer, &route_params, &network_graph, None, &logger, &scorer, &random_seed_bytes); @@ -58,8 +58,10 @@ use ln::msgs::DecodeError; use routing::network_graph::{NetworkGraph, NodeId}; use routing::router::RouteHop; 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; @@ -503,14 +505,15 @@ impl Readable for ChannelFailure { /// behavior. /// /// [1]: https://arxiv.org/abs/2107.05322 -pub type ProbabilisticScorer = ProbabilisticScorerUsingTime::; +pub type ProbabilisticScorer = ProbabilisticScorerUsingTime::; /// Probabilistic [`Score`] implementation. /// /// (C-not exported) generally all users should use the [`ProbabilisticScorer`] type alias. -pub struct ProbabilisticScorerUsingTime, T: Time> { +pub struct ProbabilisticScorerUsingTime, L: Deref, T: Time> where L::Target: Logger { params: ProbabilisticScoringParameters, network_graph: G, + logger: L, // TODO: Remove entries of closed channels. channel_liquidities: HashMap>, } @@ -603,13 +606,14 @@ struct DirectedChannelLiquidity, T: Time, U: Deref, T: Time> ProbabilisticScorerUsingTime { +impl, L: Deref, T: Time> ProbabilisticScorerUsingTime where L::Target: Logger { /// Creates a new scorer using the given scoring parameters for sending payments from a node /// through a network graph. - pub fn new(params: ProbabilisticScoringParameters, network_graph: G) -> Self { + pub fn new(params: ProbabilisticScoringParameters, network_graph: G, logger: L) -> Self { Self { params, network_graph, + logger, channel_liquidities: HashMap::new(), } } @@ -787,22 +791,29 @@ impl, T: Time, U: Deref> DirectedChannelLiqui impl, T: Time, U: DerefMut> DirectedChannelLiquidity { /// 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(&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(&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(&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); } @@ -829,7 +840,7 @@ impl, T: Time, U: DerefMut> DirectedChanne } } -impl, T: Time> Score for ProbabilisticScorerUsingTime { +impl, L: Deref, T: Time> Score for ProbabilisticScorerUsingTime where L::Target: Logger { fn channel_penalty_msat( &self, short_channel_id: u64, amount_msat: u64, capacity_msat: u64, source: &NodeId, target: &NodeId @@ -845,13 +856,18 @@ impl, T: Time> Score for ProbabilisticScorerUsin 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(); @@ -860,7 +876,7 @@ impl, T: Time> Score for ProbabilisticScorerUsin .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; } @@ -868,7 +884,10 @@ impl, T: Time> Score for ProbabilisticScorerUsin .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); } } } @@ -876,6 +895,8 @@ impl, T: Time> Score for ProbabilisticScorerUsin 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); @@ -890,7 +911,10 @@ impl, T: Time> Score for ProbabilisticScorerUsin .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); } } } @@ -1206,7 +1230,7 @@ mod approx { } } -impl, T: Time> Writeable for ProbabilisticScorerUsingTime { +impl, L: Deref, T: Time> Writeable for ProbabilisticScorerUsingTime where L::Target: Logger { #[inline] fn write(&self, w: &mut W) -> Result<(), io::Error> { write_tlv_fields!(w, { @@ -1216,13 +1240,13 @@ impl, T: Time> Writeable for ProbabilisticScorer } } -impl, T: Time> -ReadableArgs<(ProbabilisticScoringParameters, G)> for ProbabilisticScorerUsingTime { +impl, L: Deref, T: Time> +ReadableArgs<(ProbabilisticScoringParameters, G, L)> for ProbabilisticScorerUsingTime where L::Target: Logger { #[inline] fn read( - r: &mut R, args: (ProbabilisticScoringParameters, G) + r: &mut R, args: (ProbabilisticScoringParameters, G, L) ) -> Result { - let (params, network_graph) = args; + let (params, network_graph, logger) = args; let mut channel_liquidities = HashMap::new(); read_tlv_fields!(r, { (0, channel_liquidities, required) @@ -1230,6 +1254,7 @@ ReadableArgs<(ProbabilisticScoringParameters, G)> for ProbabilisticScorerUsingTi Ok(Self { params, network_graph, + logger, channel_liquidities, }) } @@ -1351,6 +1376,7 @@ mod tests { use routing::network_graph::{NetworkGraph, NodeId}; use routing::router::RouteHop; use util::ser::{Readable, ReadableArgs, Writeable}; + use util::test_utils::TestLogger; use bitcoin::blockdata::constants::genesis_block; use bitcoin::hashes::Hash; @@ -1695,7 +1721,7 @@ mod tests { // `ProbabilisticScorer` tests /// A probabilistic scorer for testing with time that can be manually advanced. - type ProbabilisticScorer<'a> = ProbabilisticScorerUsingTime::<&'a NetworkGraph, SinceEpoch>; + type ProbabilisticScorer<'a> = ProbabilisticScorerUsingTime::<&'a NetworkGraph, &'a TestLogger, SinceEpoch>; fn sender_privkey() -> SecretKey { SecretKey::from_slice(&[41; 32]).unwrap() @@ -1821,10 +1847,11 @@ mod tests { #[test] fn liquidity_bounds_directed_from_lowest_node_id() { + let logger = TestLogger::new(); let last_updated = SinceEpoch::now(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters::default(); - let mut scorer = ProbabilisticScorer::new(params, &network_graph) + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger) .with_channel(42, ChannelLiquidity { min_liquidity_offset_msat: 700, max_liquidity_offset_msat: 100, last_updated @@ -1895,10 +1922,11 @@ mod tests { #[test] fn resets_liquidity_upper_bound_when_crossed_by_lower_bound() { + let logger = TestLogger::new(); let last_updated = SinceEpoch::now(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters::default(); - let mut scorer = ProbabilisticScorer::new(params, &network_graph) + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger) .with_channel(42, ChannelLiquidity { min_liquidity_offset_msat: 200, max_liquidity_offset_msat: 400, last_updated @@ -1952,10 +1980,11 @@ mod tests { #[test] fn resets_liquidity_lower_bound_when_crossed_by_upper_bound() { + let logger = TestLogger::new(); let last_updated = SinceEpoch::now(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters::default(); - let mut scorer = ProbabilisticScorer::new(params, &network_graph) + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger) .with_channel(42, ChannelLiquidity { min_liquidity_offset_msat: 200, max_liquidity_offset_msat: 400, last_updated @@ -2009,12 +2038,13 @@ mod tests { #[test] fn increased_penalty_nearing_liquidity_upper_bound() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); @@ -2034,13 +2064,14 @@ mod tests { #[test] fn constant_penalty_outside_liquidity_bounds() { + let logger = TestLogger::new(); let last_updated = SinceEpoch::now(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let scorer = ProbabilisticScorer::new(params, &network_graph) + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger) .with_channel(42, ChannelLiquidity { min_liquidity_offset_msat: 40, max_liquidity_offset_msat: 40, last_updated @@ -2056,12 +2087,13 @@ mod tests { #[test] fn does_not_further_penalize_own_channel() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let sender = sender_node_id(); let source = source_node_id(); let failed_path = payment_path_for_amount(500); @@ -2078,12 +2110,13 @@ mod tests { #[test] fn sets_liquidity_lower_bound_on_downstream_failure() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); let path = payment_path_for_amount(500); @@ -2101,12 +2134,13 @@ mod tests { #[test] fn sets_liquidity_upper_bound_on_failure() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); let path = payment_path_for_amount(500); @@ -2124,12 +2158,13 @@ mod tests { #[test] fn reduces_liquidity_upper_bound_along_path_on_success() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let sender = sender_node_id(); let source = source_node_id(); let target = target_node_id(); @@ -2149,13 +2184,14 @@ mod tests { #[test] fn decays_liquidity_bounds_over_time() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, liquidity_offset_half_life: Duration::from_secs(10), ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); @@ -2201,13 +2237,14 @@ mod tests { #[test] fn decays_liquidity_bounds_without_shift_overflow() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, liquidity_offset_half_life: Duration::from_secs(10), ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); assert_eq!(scorer.channel_penalty_msat(42, 256, 1_024, &source, &target), 125); @@ -2226,13 +2263,14 @@ mod tests { #[test] fn restricts_liquidity_bounds_after_decay() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, liquidity_offset_half_life: Duration::from_secs(10), ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); @@ -2264,13 +2302,14 @@ mod tests { #[test] fn restores_persisted_liquidity_bounds() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, liquidity_offset_half_life: Duration::from_secs(10), ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); @@ -2288,19 +2327,20 @@ mod tests { let mut serialized_scorer = io::Cursor::new(&serialized_scorer); let deserialized_scorer = - ::read(&mut serialized_scorer, (params, &network_graph)).unwrap(); + ::read(&mut serialized_scorer, (params, &network_graph, &logger)).unwrap(); assert_eq!(deserialized_scorer.channel_penalty_msat(42, 500, 1_000, &source, &target), 300); } #[test] fn decays_persisted_liquidity_bounds() { + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters { liquidity_penalty_multiplier_msat: 1_000, liquidity_offset_half_life: Duration::from_secs(10), ..ProbabilisticScoringParameters::zero_penalty() }; - let mut scorer = ProbabilisticScorer::new(params, &network_graph); + let mut scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); @@ -2314,7 +2354,7 @@ mod tests { let mut serialized_scorer = io::Cursor::new(&serialized_scorer); let deserialized_scorer = - ::read(&mut serialized_scorer, (params, &network_graph)).unwrap(); + ::read(&mut serialized_scorer, (params, &network_graph, &logger)).unwrap(); assert_eq!(deserialized_scorer.channel_penalty_msat(42, 500, 1_000, &source, &target), 473); scorer.payment_path_failed(&payment_path_for_amount(250).iter().collect::>(), 43); @@ -2328,9 +2368,10 @@ mod tests { fn scores_realistic_payments() { // Shows the scores of "realistic" sends of 100k sats over channels of 1-10m sats (with a // 50k sat reserve). + let logger = TestLogger::new(); let network_graph = network_graph(); let params = ProbabilisticScoringParameters::default(); - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); let source = source_node_id(); let target = target_node_id(); @@ -2349,6 +2390,7 @@ mod tests { #[test] fn adds_base_penalty_to_liquidity_penalty() { + let logger = TestLogger::new(); let network_graph = network_graph(); let source = source_node_id(); let target = target_node_id(); @@ -2357,18 +2399,19 @@ mod tests { liquidity_penalty_multiplier_msat: 1_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); assert_eq!(scorer.channel_penalty_msat(42, 128, 1_024, &source, &target), 58); let params = ProbabilisticScoringParameters { base_penalty_msat: 500, liquidity_penalty_multiplier_msat: 1_000, ..Default::default() }; - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); assert_eq!(scorer.channel_penalty_msat(42, 128, 1_024, &source, &target), 558); } #[test] fn adds_amount_penalty_to_liquidity_penalty() { + let logger = TestLogger::new(); let network_graph = network_graph(); let source = source_node_id(); let target = target_node_id(); @@ -2378,7 +2421,7 @@ mod tests { amount_penalty_multiplier_msat: 0, ..ProbabilisticScoringParameters::zero_penalty() }; - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); assert_eq!(scorer.channel_penalty_msat(42, 512_000, 1_024_000, &source, &target), 300); let params = ProbabilisticScoringParameters { @@ -2386,12 +2429,13 @@ mod tests { amount_penalty_multiplier_msat: 256, ..ProbabilisticScoringParameters::zero_penalty() }; - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); assert_eq!(scorer.channel_penalty_msat(42, 512_000, 1_024_000, &source, &target), 337); } #[test] fn calculates_log10_without_overflowing_u64_max_value() { + let logger = TestLogger::new(); let network_graph = network_graph(); let source = source_node_id(); let target = target_node_id(); @@ -2400,7 +2444,7 @@ mod tests { liquidity_penalty_multiplier_msat: 40_000, ..ProbabilisticScoringParameters::zero_penalty() }; - let scorer = ProbabilisticScorer::new(params, &network_graph); + let scorer = ProbabilisticScorer::new(params, &network_graph, &logger); assert_eq!( scorer.channel_penalty_msat(42, u64::max_value(), u64::max_value(), &source, &target), 80_000,