Debug-log monitor update starts and completions in `ChainMonitor`

When a `ChannelMonitor[Update]` persistence completes, we rely on
logging in `ChannelManager` to hear about it. However, this won't
happen at all if there's still pending updates as no `MonitorEvent`
will be generated.

Thus, here, we add logging directly in `ChainMonitor`, ensuring we
can deduce when individual updates completed from debug logs.

diff --git a/lightning/src/chain/chainmonitor.rs b/lightning/src/chain/chainmonitor.rs
index 14544754318ad5945622c42bd0300679aef6a6de..6e824d1e111e5b288277f008547a30afb7bcf3e8 100644 (file)
--- a/lightning/src/chain/chainmonitor.rs
+++ b/lightning/src/chain/chainmonitor.rs
@@ -363,8 +363,9 @@ where C::Target: chain::Filter,
                let mut txn_outputs;
                {
                        txn_outputs = process(monitor, txdata);
+                       let chain_sync_update_id = self.sync_persistence_id.get_increment();
                        let update_id = MonitorUpdateId {
-                               contents: UpdateOrigin::ChainSync(self.sync_persistence_id.get_increment()),
+                               contents: UpdateOrigin::ChainSync(chain_sync_update_id),
                        };
                        let mut pending_monitor_updates = monitor_state.pending_monitor_updates.lock().unwrap();
                        if let Some(height) = best_height {
@@ -376,10 +377,16 @@ where C::Target: chain::Filter,
                                }
                        }
 
-                       log_trace!(logger, "Syncing Channel Monitor for channel {}", log_funding_info!(monitor));
+                       log_trace!(logger, "Syncing Channel Monitor for channel {} for block-data update_id {}",
+                               log_funding_info!(monitor),
+                               chain_sync_update_id
+                       );
                        match self.persister.update_persisted_channel(*funding_outpoint, None, monitor, update_id) {
                                ChannelMonitorUpdateStatus::Completed =>
-                                       log_trace!(logger, "Finished syncing Channel Monitor for channel {}", log_funding_info!(monitor)),
+                                       log_trace!(logger, "Finished syncing Channel Monitor for channel {} for block-data update_id {}",
+                                               log_funding_info!(monitor),
+                                               chain_sync_update_id
+                                       ),
                                ChannelMonitorUpdateStatus::InProgress => {
                                        log_debug!(logger, "Channel Monitor sync for channel {} in progress, holding events until completion!", log_funding_info!(monitor));
                                        pending_monitor_updates.push(update_id);
@@ -526,7 +533,7 @@ where C::Target: chain::Filter,
                pending_monitor_updates.retain(|update_id| *update_id != completed_update_id);
 
                match completed_update_id {
-                       MonitorUpdateId { contents: UpdateOrigin::OffChain(_) } => {
+                       MonitorUpdateId { contents: UpdateOrigin::OffChain(completed_update_id) } => {
                                // Note that we only check for `UpdateOrigin::OffChain` failures here - if
                                // we're being told that a `UpdateOrigin::OffChain` monitor update completed,
                                // we only care about ensuring we don't tell the `ChannelManager` to restore
@@ -537,6 +544,14 @@ where C::Target: chain::Filter,
                                // `MonitorEvent`s from the monitor back to the `ChannelManager` until they
                                // complete.
                                let monitor_is_pending_updates = monitor_data.has_pending_offchain_updates(&pending_monitor_updates);
+                               log_debug!(self.logger, "Completed off-chain monitor update {} for channel with funding outpoint {:?}, {}",
+                                       completed_update_id,
+                                       funding_txo,
+                                       if monitor_is_pending_updates {
+                                               "still have pending off-chain updates"
+                                       } else {
+                                               "all off-chain updates complete, returning a MonitorEvent"
+                                       });
                                if monitor_is_pending_updates {
                                        // If there are still monitor updates pending, we cannot yet construct a
                                        // Completed event.
@@ -547,8 +562,18 @@ where C::Target: chain::Filter,
                                        monitor_update_id: monitor_data.monitor.get_latest_update_id(),
                                }], monitor_data.monitor.get_counterparty_node_id()));
                        },
-                       MonitorUpdateId { contents: UpdateOrigin::ChainSync(_) } => {
-                               if !monitor_data.has_pending_chainsync_updates(&pending_monitor_updates) {
+                       MonitorUpdateId { contents: UpdateOrigin::ChainSync(completed_update_id) } => {
+                               let monitor_has_pending_updates =
+                                       monitor_data.has_pending_chainsync_updates(&pending_monitor_updates);
+                               log_debug!(self.logger, "Completed chain sync monitor update {} for channel with funding outpoint {:?}, {}",
+                                       completed_update_id,
+                                       funding_txo,
+                                       if monitor_has_pending_updates {
+                                               "still have pending chain sync updates"
+                                       } else {
+                                               "all chain sync updates complete, releasing pending MonitorEvents"
+                                       });
+                               if !monitor_has_pending_updates {
                                        monitor_data.last_chain_persist_height.store(self.highest_chain_height.load(Ordering::Acquire), Ordering::Release);
                                        // The next time release_pending_monitor_events is called, any events for this
                                        // ChannelMonitor will be returned.
@@ -771,7 +796,7 @@ where C::Target: chain::Filter,
                        Some(monitor_state) => {
                                let monitor = &monitor_state.monitor;
                                let logger = WithChannelMonitor::from(&self.logger, &monitor);
-                               log_trace!(logger, "Updating ChannelMonitor for channel {}", log_funding_info!(monitor));
+                               log_trace!(logger, "Updating ChannelMonitor to id {} for channel {}", update.update_id, log_funding_info!(monitor));
                                let update_res = monitor.update_monitor(update, &self.broadcaster, &self.fee_estimator, &self.logger);
 
                                let update_id = MonitorUpdateId::from_monitor_update(update);
@@ -790,10 +815,18 @@ where C::Target: chain::Filter,
                                match persist_res {
                                        ChannelMonitorUpdateStatus::InProgress => {
                                                pending_monitor_updates.push(update_id);
-                                               log_debug!(logger, "Persistence of ChannelMonitorUpdate for channel {} in progress", log_funding_info!(monitor));
+                                               log_debug!(logger,
+                                                       "Persistence of ChannelMonitorUpdate id {:?} for channel {} in progress",
+                                                       update_id,
+                                                       log_funding_info!(monitor)
+                                               );
                                        },
                                        ChannelMonitorUpdateStatus::Completed => {
-                                               log_debug!(logger, "Persistence of ChannelMonitorUpdate for channel {} completed", log_funding_info!(monitor));
+                                               log_debug!(logger,
+                                                       "Persistence of ChannelMonitorUpdate id {:?} for channel {} completed",
+                                                       update_id,
+                                                       log_funding_info!(monitor)
+                                               );
                                        },
                                        ChannelMonitorUpdateStatus::UnrecoverableError => {
                                                // Take the monitors lock for writing so that we poison it and any future