Add WaitingOnPeer/MonitorPersist spans to inbound HTLCs

Author: wvanlint

lightning/src/ln/channel.rs

@@ -322,17 +322,48 @@ impl InboundHTLCOutput where {
 	}
 
 	fn set_state<L: Deref>(&mut self, state: InboundHTLCState, logger: &L) where L::Target: Logger {
+		mem::drop(self.state_wrapper.waiting_on_peer_span.take());
+		mem::drop(self.state_wrapper.waiting_on_monitor_persist_span.take());
 		mem::drop(self.state_wrapper.span.take());
 		self.state_wrapper = InboundHTLCStateWrapper::new(
 			state,
 			self.span.as_user_span_ref::<L>(),
 			logger,
 		);
 	}
+
+	fn waiting_on_peer<L: Deref>(&mut self, logger: &L) where L::Target: Logger {
+		self.state_wrapper.waiting_on_peer_span = Some(BoxedSpan::new(logger.start(
+			Span::WaitingOnPeer,
+			self.state_wrapper.span.as_ref().map(|s| s.as_user_span_ref::<L>()).flatten(),
+		)));
+	}
+
+	fn peer_responded(&mut self) {
+		if self.state_wrapper.waiting_on_peer_span.is_some() {
+			mem::drop(self.state_wrapper.waiting_on_peer_span.take());
+		}
+	}
+
+	fn waiting_on_monitor_persist<L: Deref>(&mut self, logger: &L) where L::Target: Logger {
+		self.state_wrapper.waiting_on_monitor_persist_span = Some(BoxedSpan::new(logger.start(
+			Span::WaitingOnMonitorPersist,
+			self.state_wrapper.span.as_ref().map(|s| s.as_user_span_ref::<L>()).flatten(),
+		)));
+	}
+
+	fn monitor_persisted(&mut self) {
+		if self.state_wrapper.waiting_on_monitor_persist_span.is_some() {
+			mem::drop(self.state_wrapper.waiting_on_monitor_persist_span.take());
+		}
+	}
 }
 
 struct InboundHTLCStateWrapper {
 	state: InboundHTLCState,
+	waiting_on_peer_span: Option<BoxedSpan>,
+	waiting_on_monitor_persist_span: Option<BoxedSpan>,
+	// Drop full span last.
 	span: Option<BoxedSpan>,
 }
 
@@ -349,6 +380,8 @@ impl InboundHTLCStateWrapper {
 		InboundHTLCStateWrapper {
 			state,
 			span: Some(BoxedSpan::new(state_span)),
+			waiting_on_peer_span: None,
+			waiting_on_monitor_persist_span: None,
 		}
 	}
 }
@@ -5656,6 +5689,7 @@ impl<SP: Deref> FundedChannel<SP> where
 				InboundHTLCState::LocalRemoved(InboundHTLCRemovalReason::Fulfill(payment_preimage_arg.clone())),
 				logger,
 			);
+			htlc.waiting_on_monitor_persist(logger);
 		}
 
 		UpdateFulfillFetch::NewClaim {
@@ -6009,7 +6043,7 @@ impl<SP: Deref> FundedChannel<SP> where
 
 		// Now update local state:
 		self.context.next_counterparty_htlc_id += 1;
-		self.context.pending_inbound_htlcs.push(InboundHTLCOutput::new(
+		let mut output = InboundHTLCOutput::new(
 			self.context.channel_id(),
 			InboundHTLCOutputParams {
 				htlc_id: msg.htlc_id,
@@ -6021,7 +6055,9 @@ impl<SP: Deref> FundedChannel<SP> where
 				}),
 			},
 			logger,
-		));
+		);
+		output.waiting_on_peer(logger);
+		self.context.pending_inbound_htlcs.push(output);
 
 		Ok(())
 	}
@@ -6241,6 +6277,9 @@ impl<SP: Deref> FundedChannel<SP> where
 					InboundHTLCState::AwaitingRemoteRevokeToAnnounce(htlc_resolution.clone()),
 					logger,
 				);
+				if self.context.channel_state.is_awaiting_remote_revoke() {
+					htlc.waiting_on_peer(logger);
+				}
 				need_commitment = true;
 			}
 		}
@@ -6622,6 +6661,7 @@ impl<SP: Deref> FundedChannel<SP> where
 					if let InboundHTLCState::AwaitingRemoteRevokeToAnnounce(resolution) = state {
 						log_trace!(logger, " ...promoting inbound AwaitingRemoteRevokeToAnnounce {} to AwaitingAnnouncedRemoteRevoke", &htlc.payment_hash);
 						htlc.set_state(InboundHTLCState::AwaitingAnnouncedRemoteRevoke(resolution), logger);
+						htlc.waiting_on_monitor_persist(logger);
 						require_commitment = true;
 					} else if let InboundHTLCState::AwaitingAnnouncedRemoteRevoke(resolution) = state {
 						match resolution {
@@ -7074,6 +7114,17 @@ impl<SP: Deref> FundedChannel<SP> where
 		assert!(self.context.channel_state.is_monitor_update_in_progress());
 		self.context.channel_state.clear_monitor_update_in_progress();
 
+		for htlc in self.context.pending_inbound_htlcs.iter_mut() {
+			match htlc.state() {
+				InboundHTLCState::AwaitingAnnouncedRemoteRevoke(_) |
+				InboundHTLCState::LocalRemoved(_) => {
+					htlc.monitor_persisted();
+					htlc.waiting_on_peer(logger);
+				},
+				_ => {},
+			}
+		}
+
 		// If we're past (or at) the AwaitingChannelReady stage on an outbound (or V2-established) channel,
 		// try to (re-)broadcast the funding transaction as we may have declined to broadcast it when we
 		// first received the funding_signed.
@@ -9385,6 +9436,7 @@ impl<SP: Deref> FundedChannel<SP> where
 			if let Some(state) = new_state {
 				log_trace!(logger, " ...promoting inbound AwaitingRemoteRevokeToAnnounce {} to AwaitingAnnouncedRemoteRevoke", &htlc.payment_hash);
 				htlc.set_state(state, logger);
+				htlc.waiting_on_monitor_persist(logger);
 			}
 		}
 		for htlc in self.context.pending_outbound_htlcs.iter_mut() {

lightning/src/ln/functional_tests.rs

@@ -11721,6 +11721,11 @@ pub fn test_payment_traces() {
 			Span::InboundHTLCState { state: None },
 			Some(Span::InboundHTLC { channel_id: channel_id_1, htlc_id: 0 }),
 		),
+		TestSpanBoundary::Start(
+			Span::WaitingOnPeer,
+			Some(Span::InboundHTLCState { state: None }),
+		),
+		TestSpanBoundary::End(Span::WaitingOnPeer),
 		TestSpanBoundary::End(Span::InboundHTLCState { state: None }),
 		TestSpanBoundary::Start(
 			Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToAdd) },
@@ -11731,6 +11736,16 @@ pub fn test_payment_traces() {
 			Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToAdd) },
 			Some(Span::InboundHTLC { channel_id: channel_id_1, htlc_id: 0 }),
 		),
+		TestSpanBoundary::Start(
+			Span::WaitingOnMonitorPersist,
+			Some(Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToAdd) }),
+		),
+		TestSpanBoundary::End(Span::WaitingOnMonitorPersist),
+		TestSpanBoundary::Start(
+			Span::WaitingOnPeer,
+			Some(Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToAdd) }),
+		),
+		TestSpanBoundary::End(Span::WaitingOnPeer),
 		TestSpanBoundary::End(Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToAdd) }),
 		TestSpanBoundary::Start(
 			Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::Committed) },
@@ -11757,6 +11772,15 @@ pub fn test_payment_traces() {
 			Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToRemoveFulfill) },
 			Some(Span::InboundHTLC { channel_id: channel_id_1, htlc_id: 0 }),
 		),
+		TestSpanBoundary::Start(
+			Span::WaitingOnMonitorPersist,
+			Some(Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToRemoveFulfill) }),
+		),
+		TestSpanBoundary::End(Span::WaitingOnMonitorPersist),
+		TestSpanBoundary::Start(
+			Span::WaitingOnPeer,
+			Some(Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToRemoveFulfill) }),
+		),
 		TestSpanBoundary::End(Span::OutboundHTLCState { state: OutboundHTLCStateDetails::Committed }),
 		TestSpanBoundary::Start(
 			Span::OutboundHTLCState { state: OutboundHTLCStateDetails::AwaitingRemoteRevokeToRemoveSuccess },
@@ -11770,6 +11794,7 @@ pub fn test_payment_traces() {
 		TestSpanBoundary::End(Span::OutboundHTLCState { state: OutboundHTLCStateDetails::AwaitingRemoteRevokeToRemoveSuccess }),
 		TestSpanBoundary::End(Span::OutboundHTLC { channel_id: channel_id_2, htlc_id: 0 }),
 		TestSpanBoundary::End(Span::Forward),
+		TestSpanBoundary::End(Span::WaitingOnPeer),
 		TestSpanBoundary::End(Span::InboundHTLCState { state: Some(InboundHTLCStateDetails::AwaitingRemoteRevokeToRemoveFulfill) }),
 		TestSpanBoundary::End(Span::InboundHTLC { channel_id: channel_id_1, htlc_id: 0 })
 	]);

lightning/src/util/logger.rs

@@ -204,6 +204,10 @@ pub enum Span {
 		/// The state.
 		state: OutboundHTLCStateDetails,
 	},
+	/// Span representing the wait time until a peer responds.
+	WaitingOnPeer,
+	/// Span representing the wait time until a channel monitor persists.
+	WaitingOnMonitorPersist,
 	/// Span representing sending an outbound Ping and receiving an inbound Pong.
 	PingPong {
 		/// The node id of the counterparty.