Merge pull request #4242 from joostjager/extra-logs

Channel logging improvements

Author: valentinewallace

lightning/src/ln/channel.rs

@@ -8931,8 +8931,8 @@ where
 					);
 					return_with_htlcs_to_fail!(htlcs_to_fail);
 				} else {
-					log_debug!(logger, "Received a valid revoke_and_ack with no reply necessary. {} monitor update.",
-						release_state_str);
+					log_debug!(logger, "Received a valid revoke_and_ack with no reply necessary. {} monitor update {}.",
+						release_state_str, monitor_update.update_id);
 
 					self.monitor_updating_paused(
 						false,

lightning/src/ln/channelmanager.rs

@@ -9480,8 +9480,11 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 		}
 	}
 
-	#[rustfmt::skip]
-	fn handle_monitor_update_completion_actions<I: IntoIterator<Item=MonitorUpdateCompletionAction>>(&self, actions: I) {
+	fn handle_monitor_update_completion_actions<
+		I: IntoIterator<Item = MonitorUpdateCompletionAction>,
+	>(
+		&self, actions: I,
+	) {
 		debug_assert_ne!(self.pending_events.held_by_thread(), LockHeldState::HeldByThread);
 		debug_assert_ne!(self.claimable_payments.held_by_thread(), LockHeldState::HeldByThread);
 		debug_assert_ne!(self.per_peer_state.held_by_thread(), LockHeldState::HeldByThread);
@@ -9490,44 +9493,67 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 
 		for action in actions.into_iter() {
 			match action {
-				MonitorUpdateCompletionAction::PaymentClaimed { payment_hash, pending_mpp_claim } => {
-					if let Some((counterparty_node_id, chan_id, claim_ptr)) = pending_mpp_claim {
+				MonitorUpdateCompletionAction::PaymentClaimed {
+					payment_hash,
+					pending_mpp_claim,
+				} => {
+					let (peer_id, chan_id) = pending_mpp_claim
+						.as_ref()
+						.map(|c| (Some(c.0), Some(c.1)))
+						.unwrap_or_default();
+					let logger =
+						WithContext::from(&self.logger, peer_id, chan_id, Some(payment_hash));
+					log_trace!(logger, "Handling PaymentClaimed monitor update completion action");
+
+					if let Some((cp_node_id, chan_id, claim_ptr)) = pending_mpp_claim {
 						let per_peer_state = self.per_peer_state.read().unwrap();
-						per_peer_state.get(&counterparty_node_id).map(|peer_state_mutex| {
+						per_peer_state.get(&cp_node_id).map(|peer_state_mutex| {
 							let mut peer_state = peer_state_mutex.lock().unwrap();
-							let blockers_entry = peer_state.actions_blocking_raa_monitor_updates.entry(chan_id);
+							let blockers_entry =
+								peer_state.actions_blocking_raa_monitor_updates.entry(chan_id);
 							if let btree_map::Entry::Occupied(mut blockers) = blockers_entry {
-								blockers.get_mut().retain(|blocker|
-									if let &RAAMonitorUpdateBlockingAction::ClaimedMPPPayment { pending_claim } = &blocker {
-										if *pending_claim == claim_ptr {
-											let mut pending_claim_state_lock = pending_claim.0.lock().unwrap();
-											let pending_claim_state = &mut *pending_claim_state_lock;
-											pending_claim_state.channels_without_preimage.retain(|(cp, cid)| {
-												let this_claim =
-													*cp == counterparty_node_id && *cid == chan_id;
-												if this_claim {
-													pending_claim_state.channels_with_preimage.push((*cp, *cid));
-													false
-												} else { true }
-											});
-											if pending_claim_state.channels_without_preimage.is_empty() {
-												for (cp, cid) in pending_claim_state.channels_with_preimage.iter() {
-													let freed_chan = (*cp, *cid, blocker.clone());
-													freed_channels.push(freed_chan);
-												}
-											}
-											!pending_claim_state.channels_without_preimage.is_empty()
-										} else { true }
-									} else { true }
-								);
+								blockers.get_mut().retain(|blocker| {
+									let pending_claim = match &blocker {
+										RAAMonitorUpdateBlockingAction::ClaimedMPPPayment {
+											pending_claim,
+										} => pending_claim,
+										_ => return true,
+									};
+									if *pending_claim != claim_ptr {
+										return true;
+									}
+									let mut claim_state_lock = pending_claim.0.lock().unwrap();
+									let claim_state = &mut *claim_state_lock;
+									claim_state.channels_without_preimage.retain(|(cp, cid)| {
+										let this_claim = *cp == cp_node_id && *cid == chan_id;
+										if this_claim {
+											claim_state.channels_with_preimage.push((*cp, *cid));
+											false
+										} else {
+											true
+										}
+									});
+									if claim_state.channels_without_preimage.is_empty() {
+										for (cp, cid) in claim_state.channels_with_preimage.iter() {
+											let freed_chan = (*cp, *cid, blocker.clone());
+											freed_channels.push(freed_chan);
+										}
+									}
+									!claim_state.channels_without_preimage.is_empty()
+								});
 								if blockers.get().is_empty() {
 									blockers.remove();
 								}
 							}
 						});
 					}
 
-					let payment = self.claimable_payments.lock().unwrap().pending_claiming_payments.remove(&payment_hash);
+					let payment = self
+						.claimable_payments
+						.lock()
+						.unwrap()
+						.pending_claiming_payments
+						.remove(&payment_hash);
 					if let Some(ClaimingPayment {
 						amount_msat,
 						payment_purpose: purpose,
@@ -9537,7 +9563,8 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 						onion_fields,
 						payment_id,
 						durable_preimage_channel,
-					}) = payment {
+					}) = payment
+					{
 						let event = events::Event::PaymentClaimed {
 							payment_hash,
 							purpose,
@@ -9548,8 +9575,8 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 							onion_fields,
 							payment_id,
 						};
-						let action = if let Some((outpoint, counterparty_node_id, channel_id))
-							= durable_preimage_channel
+						let action = if let Some((outpoint, counterparty_node_id, channel_id)) =
+							durable_preimage_channel
 						{
 							Some(EventCompletionAction::ReleaseRAAChannelMonitorUpdate {
 								channel_funding_outpoint: Some(outpoint),
@@ -9566,12 +9593,18 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 						// `payment_id` should suffice to ensure we never spuriously drop a second
 						// event for a duplicate payment.
 						if !pending_events.contains(&event_action) {
+							log_trace!(
+								logger,
+								"Queuing PaymentClaimed event with event completion action {:?}",
+								event_action.1
+							);
 							pending_events.push_back(event_action);
 						}
 					}
 				},
 				MonitorUpdateCompletionAction::EmitEventAndFreeOtherChannel {
-					event, downstream_counterparty_and_funding_outpoint
+					event,
+					downstream_counterparty_and_funding_outpoint,
 				} => {
 					self.pending_events.lock().unwrap().push_back((event, None));
 					if let Some(unblocked) = downstream_counterparty_and_funding_outpoint {
@@ -9583,7 +9616,9 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 					}
 				},
 				MonitorUpdateCompletionAction::FreeOtherChannelImmediately {
-					downstream_counterparty_node_id, downstream_channel_id, blocking_action,
+					downstream_counterparty_node_id,
+					downstream_channel_id,
+					blocking_action,
 				} => {
 					self.handle_monitor_update_release(
 						downstream_counterparty_node_id,
@@ -17145,17 +17180,18 @@ where
 
 				let logger = WithChannelMonitor::from(&args.logger, monitor, None);
 				let channel_id = monitor.channel_id();
-				log_info!(
-					logger,
-					"Queueing monitor update to ensure missing channel is force closed",
-				);
 				let monitor_update = ChannelMonitorUpdate {
 					update_id: monitor.get_latest_update_id().saturating_add(1),
 					updates: vec![ChannelMonitorUpdateStep::ChannelForceClosed {
 						should_broadcast: true,
 					}],
 					channel_id: Some(monitor.channel_id()),
 				};
+				log_info!(
+					logger,
+					"Queueing monitor update {} to ensure missing channel is force closed",
+					monitor_update.update_id
+				);
 				let funding_txo = monitor.get_funding_txo();
 				let update = BackgroundEvent::MonitorUpdateRegeneratedOnStartup {
 					counterparty_node_id,