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 593f84a90898534742f5dbd0c0458ea3f53cf059..39ecc316a5a88c858144ed6d3b65a8ee3889997a 100644 (file)
--- 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 71b0b3e506456d36ec16345b70e10f8e1cf12746..3c8f9bb561b2456c7c3822f123efdd0f6539b67f 100644 (file)
--- 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 0ae3ff29d87ed82e5c26beecc225c25401658fad..dd717ca2f69fd485713e9c875eb4c98aa684e403 100644 (file)
--- 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); };