Channel logging improvements

lightning/src/ln/channel.rs

@@ -8905,8 +8905,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

@@ -9440,8 +9440,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);
@@ -9450,44 +9453,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,
@@ -9497,7 +9523,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,
@@ -9508,8 +9535,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),
@@ -9526,12 +9553,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 {
@@ -9543,7 +9576,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,
@@ -17109,17 +17144,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,