From 8e96f6b92efb2a04e957629f281bdb491f62dc9a Mon Sep 17 00:00:00 2001 From: Matt Corallo Date: Mon, 4 Oct 2021 03:11:36 +0000 Subject: [PATCH] Log before+after ChannelMonitor/Manager updates for visibility I realized on my own node that I don't have any visibility into how long a monitor or manager persistence call takes, potentially blocking other operations. This makes it much more clear by adding a relevant log_trace!() print immediately before and immediately after persistence. --- lightning-background-processor/src/lib.rs | 2 ++ lightning/src/chain/chainmonitor.rs | 22 +++++++++---------- lightning/src/ln/chanmon_update_fail_tests.rs | 2 +- 3 files changed, 14 insertions(+), 12 deletions(-) diff --git a/lightning-background-processor/src/lib.rs b/lightning-background-processor/src/lib.rs index 593f84a90..39ecc316a 100644 --- a/lightning-background-processor/src/lib.rs +++ b/lightning-background-processor/src/lib.rs @@ -217,7 +217,9 @@ impl BackgroundProcessor { let updates_available = channel_manager.await_persistable_update_timeout(Duration::from_millis(100)); if updates_available { + log_trace!(logger, "Persisting ChannelManager..."); persister.persist_manager(&*channel_manager)?; + log_trace!(logger, "Done persisting ChannelManager."); } // Exit the loop if the background processor was requested to stop. if stop_thread.load(Ordering::Acquire) == true { diff --git a/lightning/src/chain/chainmonitor.rs b/lightning/src/chain/chainmonitor.rs index 71b0b3e50..3c8f9bb56 100644 --- a/lightning/src/chain/chainmonitor.rs +++ b/lightning/src/chain/chainmonitor.rs @@ -592,24 +592,22 @@ where C::Target: chain::Filter, return Err(ChannelMonitorUpdateErr::PermanentFailure)}, hash_map::Entry::Vacant(e) => e, }; + log_trace!(self.logger, "Got new ChannelMonitor for channel {}", log_funding_info!(monitor)); let update_id = MonitorUpdateId::from_new_monitor(&monitor); let mut pending_monitor_updates = Vec::new(); let persist_res = self.persister.persist_new_channel(funding_outpoint, &monitor, update_id); if persist_res.is_err() { - log_error!(self.logger, "Failed to persist new channel data: {:?}", persist_res); + log_error!(self.logger, "Failed to persist new ChannelMonitor for channel {}: {:?}", log_funding_info!(monitor), persist_res); + } else { + log_trace!(self.logger, "Finished persisting new ChannelMonitor for channel {}", log_funding_info!(monitor)); } if persist_res == Err(ChannelMonitorUpdateErr::PermanentFailure) { return persist_res; } else if persist_res.is_err() { pending_monitor_updates.push(update_id); } - { - let funding_txo = monitor.get_funding_txo(); - log_trace!(self.logger, "Got new Channel Monitor for channel {}", log_bytes!(funding_txo.0.to_channel_id()[..])); - - if let Some(ref chain_source) = self.chain_source { - monitor.load_outputs_to_watch(chain_source); - } + if let Some(ref chain_source) = self.chain_source { + monitor.load_outputs_to_watch(chain_source); } entry.insert(MonitorHolder { monitor, @@ -639,10 +637,10 @@ where C::Target: chain::Filter, }, Some(monitor_state) => { let monitor = &monitor_state.monitor; - log_trace!(self.logger, "Updating Channel Monitor for channel {}", log_funding_info!(monitor)); + log_trace!(self.logger, "Updating ChannelMonitor for channel {}", log_funding_info!(monitor)); let update_res = monitor.update_monitor(&update, &self.broadcaster, &self.fee_estimator, &self.logger); if let Err(e) = &update_res { - log_error!(self.logger, "Failed to update channel monitor: {:?}", e); + log_error!(self.logger, "Failed to update ChannelMonitor for channel {}: {:?}", log_funding_info!(monitor), e); } // Even if updating the monitor returns an error, the monitor's state will // still be changed. So, persist the updated monitor despite the error. @@ -655,7 +653,9 @@ where C::Target: chain::Filter, } else { monitor_state.channel_perm_failed.store(true, Ordering::Release); } - log_error!(self.logger, "Failed to persist channel monitor update: {:?}", e); + log_error!(self.logger, "Failed to persist ChannelMonitor update for channel {}: {:?}", log_funding_info!(monitor), e); + } else { + log_trace!(self.logger, "Finished persisting ChannelMonitor update for channel {}", log_funding_info!(monitor)); } if update_res.is_err() { Err(ChannelMonitorUpdateErr::PermanentFailure) diff --git a/lightning/src/ln/chanmon_update_fail_tests.rs b/lightning/src/ln/chanmon_update_fail_tests.rs index 0ae3ff29d..dd717ca2f 100644 --- a/lightning/src/ln/chanmon_update_fail_tests.rs +++ b/lightning/src/ln/chanmon_update_fail_tests.rs @@ -137,7 +137,7 @@ fn test_monitor_and_persister_update_fail() { // because the update is bogus, ultimately the error that's returned // should be a PermanentFailure. if let Err(ChannelMonitorUpdateErr::PermanentFailure) = chain_mon.chain_monitor.update_channel(outpoint, update.clone()) {} else { panic!("Expected monitor error to be permanent"); } - logger.assert_log_contains("lightning::chain::chainmonitor".to_string(), "Failed to persist channel monitor update: TemporaryFailure".to_string(), 1); + logger.assert_log_regex("lightning::chain::chainmonitor".to_string(), regex::Regex::new("Failed to persist ChannelMonitor update for channel [0-9a-f]*: TemporaryFailure").unwrap(), 1); if let Ok(_) = nodes[0].chain_monitor.update_channel(outpoint, update) {} else { assert!(false); } } else { assert!(false); } } else { assert!(false); }; -- 2.39.5