From: Matt Corallo <git@bluematt.me>
Date: Mon, 4 Oct 2021 03:11:36 +0000 (+0000)
Subject: Log before+after ChannelMonitor/Manager updates for visibility
X-Git-Tag: v0.0.104~41^2
X-Git-Url: http://git.bitcoin.ninja/?a=commitdiff_plain;h=refs%2Fheads%2F2021-10-log-persist-time;p=rust-lightning

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.
---

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); };