From: Matt Corallo Date: Thu, 11 Apr 2024 21:53:44 +0000 (+0000) Subject: Debug-log monitor update starts and completions in `ChainMonitor` X-Git-Tag: v0.0.123-rc1~8^2 X-Git-Url: http://git.bitcoin.ninja/index.cgi?p=rust-lightning;a=commitdiff_plain;h=93e77632d61481e912d2630395c30ff9ec71ead6 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 14544754..6e824d1e 100644 --- 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