From: Matt Corallo <git@bluematt.me>
Date: Sat, 25 Feb 2023 02:46:01 +0000 (+0000)
Subject: Some additional logging in `ChannelMonitor` update completion
X-Git-Url: http://git.bitcoin.ninja/?a=commitdiff_plain;h=refs%2Fheads%2F2023-02-better-chain-monitor-logging;p=rust-lightning

Some additional logging in `ChannelMonitor` update completion
---

diff --git a/lightning/src/chain/chainmonitor.rs b/lightning/src/chain/chainmonitor.rs
index 9a74f891b..5d0dfd22b 100644
--- a/lightning/src/chain/chainmonitor.rs
+++ b/lightning/src/chain/chainmonitor.rs
@@ -45,7 +45,7 @@ use core::ops::Deref;
 use core::sync::atomic::{AtomicBool, AtomicUsize, Ordering};
 use bitcoin::secp256k1::PublicKey;
 
-#[derive(Clone, Copy, Hash, PartialEq, Eq)]
+#[derive(Clone, Copy, Debug, Hash, PartialEq, Eq)]
 /// A specific update's ID stored in a `MonitorUpdateId`, separated out to make the contents
 /// entirely opaque.
 enum UpdateOrigin {
@@ -441,6 +441,8 @@ where C::Target: chain::Filter,
 		let mut pending_monitor_updates = monitor_data.pending_monitor_updates.lock().unwrap();
 		pending_monitor_updates.retain(|update_id| *update_id != completed_update_id);
 
+		log_trace!(self.logger, "Received a channel_monitor_updated for id: {:?}",
+			completed_update_id.contents);
 		match completed_update_id {
 			MonitorUpdateId { contents: UpdateOrigin::OffChain(_) } => {
 				// Note that we only check for `UpdateOrigin::OffChain` failures here - if
@@ -457,6 +459,9 @@ where C::Target: chain::Filter,
 					// If there are still monitor updates pending (or an old monitor update
 					// finished after a later one perm-failed), we cannot yet construct an
 					// Completed event.
+					log_debug!(self.logger,
+						"Have pending monitor update for channel {:?}, refusing to generate a Completed event",
+						funding_txo);
 					return Ok(());
 				}
 				self.pending_monitor_events.lock().unwrap().push((funding_txo, vec![MonitorEvent::Completed {
@@ -699,6 +704,8 @@ where C::Target: chain::Filter,
 
 	fn release_pending_monitor_events(&self) -> Vec<(OutPoint, Vec<MonitorEvent>, Option<PublicKey>)> {
 		let mut pending_monitor_events = self.pending_monitor_events.lock().unwrap().split_off(0);
+		log_trace!(self.logger, "Got {} monitor events from ChainMonitor for release.",
+			pending_monitor_events.len());
 		for monitor_state in self.monitors.read().unwrap().values() {
 			let is_pending_monitor_update = monitor_state.has_pending_chainsync_updates(&monitor_state.pending_monitor_updates.lock().unwrap());
 			if is_pending_monitor_update &&
@@ -724,8 +731,10 @@ where C::Target: chain::Filter,
 					log_error!(self.logger, "   This may cause duplicate payment events to be generated.");
 				}
 				let monitor_events = monitor_state.monitor.get_and_clear_pending_monitor_events();
+				let monitor_outpoint = monitor_state.monitor.get_funding_txo().0;
+				log_trace!(self.logger, "Got {} monitor events from ChannelMonitor {:?}",
+					monitor_events.len(), monitor_outpoint);
 				if monitor_events.len() > 0 {
-					let monitor_outpoint = monitor_state.monitor.get_funding_txo().0;
 					let counterparty_node_id = monitor_state.monitor.get_counterparty_node_id();
 					pending_monitor_events.push((monitor_outpoint, monitor_events, counterparty_node_id));
 				}
diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs
index 61de296c1..49cd27881 100644
--- a/lightning/src/ln/channelmanager.rs
+++ b/lightning/src/ln/channelmanager.rs
@@ -4173,23 +4173,38 @@ where
 				let id_to_peer = self.id_to_peer.lock().unwrap();
 				match id_to_peer.get(&funding_txo.to_channel_id()) {
 					Some(cp_id) => cp_id.clone(),
-					None => return,
+					None => {
+						log_debug!(self.logger,
+							"Got a monitor update completion for a since-closed channel: {:?}",
+							funding_txo);
+						return
+					},
 				}
 			}
 		};
 		let per_peer_state = self.per_peer_state.read().unwrap();
 		let mut peer_state_lock;
 		let peer_state_mutex_opt = per_peer_state.get(&counterparty_node_id);
-		if peer_state_mutex_opt.is_none() { return }
+		if peer_state_mutex_opt.is_none() {
+			log_debug!(self.logger,
+				"Got a monitor update completion for a peer we have no channels with anymore: {}",
+				counterparty_node_id);
+			return;
+		}
 		peer_state_lock = peer_state_mutex_opt.unwrap().lock().unwrap();
 		let peer_state = &mut *peer_state_lock;
 		let mut channel = {
 			match peer_state.channel_by_id.entry(funding_txo.to_channel_id()){
 				hash_map::Entry::Occupied(chan) => chan,
-				hash_map::Entry::Vacant(_) => return,
+				hash_map::Entry::Vacant(_) => {
+					log_debug!(self.logger,
+						"Got a monitor update completion for a channel we have since closed: {:?}",
+						funding_txo);
+					return;
+				},
 			}
 		};
-		log_trace!(self.logger, "ChannelMonitor updated to {}. Current highest is {}",
+		log_debug!(self.logger, "ChannelMonitor updated to {}. Current highest is {}",
 			highest_applied_update_id, channel.get().get_latest_monitor_update_id());
 		if !channel.get().is_awaiting_monitor_update() || channel.get().get_latest_monitor_update_id() != highest_applied_update_id {
 			return;
@@ -5105,6 +5120,8 @@ where
 	fn process_pending_monitor_events(&self) -> bool {
 		let mut failed_channels = Vec::new();
 		let mut pending_monitor_events = self.chain_monitor.release_pending_monitor_events();
+		log_trace!(self.logger, "Got {} monitor events from ChainMonitor",
+			pending_monitor_events.len());
 		let has_pending_monitor_events = !pending_monitor_events.is_empty();
 		for (funding_outpoint, mut monitor_events, counterparty_node_id) in pending_monitor_events.drain(..) {
 			for monitor_event in monitor_events.drain(..) {