test: increase ping timeout when running in debug mode

[rust-lightning] / lightning-background-processor / src / lib.rs

diff --git a/lightning-background-processor/src/lib.rs b/lightning-background-processor/src/lib.rs
index 55ac14c048c412e8a9d0a7f17318d62b7569b3f6..a0751a9d0f4b3055fdb605a95c46033f55ce0e2b 100644 (file)
--- a/lightning-background-processor/src/lib.rs
+++ b/lightning-background-processor/src/lib.rs
@@ -39,6 +39,7 @@ use std::ops::Deref;
 /// then there is a risk of channels force-closing on startup when the manager realizes it's
 /// outdated. However, as long as `ChannelMonitor` backups are sound, no funds besides those used
 /// for unilateral chain closure fees are at risk.
+#[must_use = "BackgroundProcessor will immediately stop on drop. It should be stored until shutdown."]
 pub struct BackgroundProcessor {
        stop_thread: Arc<AtomicBool>,
        thread_handle: Option<JoinHandle<Result<(), std::io::Error>>>,
@@ -49,6 +50,14 @@ const FRESHNESS_TIMER: u64 = 60;
 #[cfg(test)]
 const FRESHNESS_TIMER: u64 = 1;
 
+#[cfg(not(debug_assertions))]
+const PING_TIMER: u64 = 5;
+/// Signature operations take a lot longer without compiler optimisations.
+/// Increasing the ping timer allows for this but slower devices will be disconnected if the
+/// timeout is reached.
+#[cfg(debug_assertions)]
+const PING_TIMER: u64 = 30;
+
 /// Trait which handles persisting a [`ChannelManager`] to disk.
 ///
 /// [`ChannelManager`]: lightning::ln::channelmanager::ChannelManager
@@ -137,7 +146,11 @@ impl BackgroundProcessor {
                let stop_thread = Arc::new(AtomicBool::new(false));
                let stop_thread_clone = stop_thread.clone();
                let handle = thread::spawn(move || -> Result<(), std::io::Error> {
-                       let mut current_time = Instant::now();
+                       log_trace!(logger, "Calling ChannelManager's timer_tick_occurred on startup");
+                       channel_manager.timer_tick_occurred();
+
+                       let mut last_freshness_call = Instant::now();
+                       let mut last_ping_call = Instant::now();
                        loop {
                                peer_manager.process_events();
                                channel_manager.process_pending_events(&event_handler);
@@ -152,11 +165,27 @@ impl BackgroundProcessor {
                                        log_trace!(logger, "Terminating background processor.");
                                        return Ok(());
                                }
-                               if current_time.elapsed().as_secs() > FRESHNESS_TIMER {
-                                       log_trace!(logger, "Calling ChannelManager's and PeerManager's timer_tick_occurred");
+                               if last_freshness_call.elapsed().as_secs() > FRESHNESS_TIMER {
+                                       log_trace!(logger, "Calling ChannelManager's timer_tick_occurred");
                                        channel_manager.timer_tick_occurred();
+                                       last_freshness_call = Instant::now();
+                               }
+                               if last_ping_call.elapsed().as_secs() > PING_TIMER * 2 {
+                                       // On various platforms, we may be starved of CPU cycles for several reasons.
+                                       // E.g. on iOS, if we've been in the background, we will be entirely paused.
+                                       // Similarly, if we're on a desktop platform and the device has been asleep, we
+                                       // may not get any cycles.
+                                       // In any case, if we've been entirely paused for more than double our ping
+                                       // timer, we should have disconnected all sockets by now (and they're probably
+                                       // dead anyway), so disconnect them by calling `timer_tick_occurred()` twice.
+                                       log_trace!(logger, "Awoke after more than double our ping timer, disconnecting peers.");
+                                       peer_manager.timer_tick_occurred();
+                                       peer_manager.timer_tick_occurred();
+                                       last_ping_call = Instant::now();
+                               } else if last_ping_call.elapsed().as_secs() > PING_TIMER {
+                                       log_trace!(logger, "Calling PeerManager's timer_tick_occurred");
                                        peer_manager.timer_tick_occurred();
-                                       current_time = Instant::now();
+                                       last_ping_call = Instant::now();
                                }
                        }
                });
@@ -223,7 +252,7 @@ mod tests {
        use lightning::get_event_msg;
        use lightning::ln::channelmanager::{BREAKDOWN_TIMEOUT, ChainParameters, ChannelManager, SimpleArcChannelManager};
        use lightning::ln::features::InitFeatures;
-       use lightning::ln::msgs::ChannelMessageHandler;
+       use lightning::ln::msgs::{ChannelMessageHandler, Init};
        use lightning::ln::peer_handler::{PeerManager, MessageHandler, SocketDescriptor};
        use lightning::util::config::UserConfig;
        use lightning::util::events::{Event, MessageSendEventsProvider, MessageSendEvent};
@@ -297,6 +326,14 @@ mod tests {
                        let node = Node { node: manager, peer_manager, chain_monitor, persister, tx_broadcaster, logger, best_block };
                        nodes.push(node);
                }
+
+               for i in 0..num_nodes {
+                       for j in (i+1)..num_nodes {
+                               nodes[i].node.peer_connected(&nodes[j].node.get_our_node_id(), &Init { features: InitFeatures::known() });
+                               nodes[j].node.peer_connected(&nodes[i].node.get_our_node_id(), &Init { features: InitFeatures::known() });
+                       }
+               }
+
                nodes
        }
 
@@ -440,8 +477,10 @@ mod tests {
                let bg_processor = BackgroundProcessor::start(persister, event_handler, nodes[0].chain_monitor.clone(), nodes[0].node.clone(), nodes[0].peer_manager.clone(), nodes[0].logger.clone());
                loop {
                        let log_entries = nodes[0].logger.lines.lock().unwrap();
-                       let desired_log = "Calling ChannelManager's and PeerManager's timer_tick_occurred".to_string();
-                       if log_entries.get(&("lightning_background_processor".to_string(), desired_log)).is_some() {
+                       let desired_log = "Calling ChannelManager's timer_tick_occurred".to_string();
+                       let second_desired_log = "Calling PeerManager's timer_tick_occurred".to_string();
+                       if log_entries.get(&("lightning_background_processor".to_string(), desired_log)).is_some() &&
+                                       log_entries.get(&("lightning_background_processor".to_string(), second_desired_log)).is_some() {
                                break
                        }
                }