Track htlc hold time

Record a timestamp when the htlc is sent out and record the hold
duration alongside the failure reason.

Author: joostjager

lightning/src/ln/channel.rs

@@ -68,6 +68,7 @@ use crate::util::scid_utils::scid_from_parts;
 
 use crate::io;
 use crate::prelude::*;
+use core::time::Duration;
 use core::{cmp,mem,fmt};
 use core::ops::Deref;
 #[cfg(any(test, fuzzing, debug_assertions))]
@@ -323,6 +324,7 @@ struct OutboundHTLCOutput {
 	source: HTLCSource,
 	blinding_point: Option<PublicKey>,
 	skimmed_fee_msat: Option<u64>,
+	send_timestamp: Option<Duration>,
 }
 
 /// See AwaitingRemoteRevoke ChannelState for more info
@@ -6095,10 +6097,16 @@ impl<SP: Deref> FundedChannel<SP> where
 					false
 				} else { true }
 			});
+			let now = duration_since_epoch();
 			pending_outbound_htlcs.retain(|htlc| {
 				if let &OutboundHTLCState::AwaitingRemovedRemoteRevoke(ref outcome) = &htlc.state {
 					log_trace!(logger, " ...removing outbound AwaitingRemovedRemoteRevoke {}", &htlc.payment_hash);
-					if let OutboundHTLCOutcome::Failure(reason) = outcome.clone() { // We really want take() here, but, again, non-mut ref :(
+					if let OutboundHTLCOutcome::Failure(mut reason) = outcome.clone() { // We really want take() here, but, again, non-mut ref :(
+						if let (Some(timestamp), Some(now)) = (htlc.send_timestamp, now) {
+							let hold_time = u32::try_from(now.saturating_sub(timestamp).as_millis()).unwrap_or(u32::MAX);
+							reason.set_hold_time(hold_time);
+						}
+
 						revoked_htlcs.push((htlc.source.clone(), htlc.payment_hash, reason));
 					} else {
 						finalized_claimed_htlcs.push(htlc.source.clone());
@@ -8667,6 +8675,13 @@ impl<SP: Deref> FundedChannel<SP> where
 			return Ok(None);
 		}
 
+		// Record the approximate time when the HTLC is sent to the peer. This timestamp is later used to calculate the
+		// htlc hold time for reporting back to the sender. There is some freedom to report a time including or
+		// excluding our own processing time. What we choose here doesn't matter all that much, because it will probably
+		// just shift sender-applied penalties between our incoming and outgoing side. So we choose measuring points
+		// that are simple to implement, and we do it on the outgoing side because then the failure message that encodes
+		// the hold time still needs to be built in channel manager.
+		let timestamp = duration_since_epoch();
 		self.context.pending_outbound_htlcs.push(OutboundHTLCOutput {
 			htlc_id: self.context.next_holder_htlc_id,
 			amount_msat,
@@ -8676,6 +8691,7 @@ impl<SP: Deref> FundedChannel<SP> where
 			source,
 			blinding_point,
 			skimmed_fee_msat,
+			send_timestamp: timestamp,
 		});
 
 		let res = msgs::UpdateAddHTLC {
@@ -10674,6 +10690,7 @@ impl<'a, 'b, 'c, ES: Deref, SP: Deref> ReadableArgs<(&'a ES, &'b SP, &'c Channel
 				},
 				skimmed_fee_msat: None,
 				blinding_point: None,
+				send_timestamp: None,
 			});
 		}
 
@@ -11192,6 +11209,18 @@ impl<'a, 'b, 'c, ES: Deref, SP: Deref> ReadableArgs<(&'a ES, &'b SP, &'c Channel
 	}
 }
 
+fn duration_since_epoch() -> Option<Duration> {
+	#[cfg(not(feature = "std"))]
+	let now = None;
+
+	#[cfg(feature = "std")]
+	let now = Some(std::time::SystemTime::now()
+		.duration_since(std::time::SystemTime::UNIX_EPOCH)
+		.expect("SystemTime::now() should come after SystemTime::UNIX_EPOCH"));
+
+	now
+}
+
 #[cfg(test)]
 mod tests {
 	use std::cmp;
@@ -11427,6 +11456,7 @@ mod tests {
 			},
 			skimmed_fee_msat: None,
 			blinding_point: None,
+			send_timestamp: None,
 		});
 
 		// Make sure when Node A calculates their local commitment transaction, none of the HTLCs pass
@@ -11811,6 +11841,7 @@ mod tests {
 			source: dummy_htlc_source.clone(),
 			skimmed_fee_msat: None,
 			blinding_point: None,
+			send_timestamp: None,
 		};
 		let mut pending_outbound_htlcs = vec![dummy_outbound_output.clone(); 10];
 		for (idx, htlc) in pending_outbound_htlcs.iter_mut().enumerate() {
@@ -12133,6 +12164,7 @@ mod tests {
 				source: HTLCSource::dummy(),
 				skimmed_fee_msat: None,
 				blinding_point: None,
+				send_timestamp: None,
 			};
 			out.payment_hash.0 = Sha256::hash(&<Vec<u8>>::from_hex("0202020202020202020202020202020202020202020202020202020202020202").unwrap()).to_byte_array();
 			out
@@ -12147,6 +12179,7 @@ mod tests {
 				source: HTLCSource::dummy(),
 				skimmed_fee_msat: None,
 				blinding_point: None,
+				send_timestamp: None,
 			};
 			out.payment_hash.0 = Sha256::hash(&<Vec<u8>>::from_hex("0303030303030303030303030303030303030303030303030303030303030303").unwrap()).to_byte_array();
 			out
@@ -12559,6 +12592,7 @@ mod tests {
 				source: HTLCSource::dummy(),
 				skimmed_fee_msat: None,
 				blinding_point: None,
+				send_timestamp: None,
 			};
 			out.payment_hash.0 = Sha256::hash(&<Vec<u8>>::from_hex("0505050505050505050505050505050505050505050505050505050505050505").unwrap()).to_byte_array();
 			out
@@ -12573,6 +12607,7 @@ mod tests {
 				source: HTLCSource::dummy(),
 				skimmed_fee_msat: None,
 				blinding_point: None,
+				send_timestamp: None,
 			};
 			out.payment_hash.0 = Sha256::hash(&<Vec<u8>>::from_hex("0505050505050505050505050505050505050505050505050505050505050505").unwrap()).to_byte_array();
 			out

lightning/src/ln/onion_utils.rs

@@ -1365,10 +1365,21 @@ pub(super) struct HTLCFailReason(HTLCFailReasonRepr);
 #[derive(Clone)] // See Channel::revoke_and_ack for why, tl;dr: Rust bug
 #[cfg_attr(test, derive(PartialEq))]
 enum HTLCFailReasonRepr {
-	LightningError { err: msgs::OnionErrorPacket },
+	LightningError { err: msgs::OnionErrorPacket, hold_time: Option<u32> },
 	Reason { failure_code: u16, data: Vec<u8> },
 }
 
+impl HTLCFailReason {
+	pub fn set_hold_time(&mut self, hold_time: u32) {
+		match self.0 {
+			HTLCFailReasonRepr::LightningError { hold_time: ref mut current_hold_time, .. } => {
+				*current_hold_time = Some(hold_time);
+			},
+			_ => {},
+		}
+	}
+}
+
 impl core::fmt::Debug for HTLCFailReason {
 	fn fmt(&self, f: &mut core::fmt::Formatter) -> Result<(), core::fmt::Error> {
 		match self.0 {
@@ -1409,6 +1420,7 @@ impl_writeable_tlv_based_enum!(HTLCFailReasonRepr,
 				None
 			})
 		),
+		(3, hold_time, option),
 		(_unused, err, (static_value, msgs::OnionErrorPacket { data: data.ok_or(DecodeError::InvalidValue)?, attribution_data })),
 	},
 	(1, Reason) => {
@@ -1471,6 +1483,7 @@ impl HTLCFailReason {
 				data: msg.reason.clone(),
 				attribution_data: msg.attribution_data.clone(),
 			},
+			hold_time: None,
 		})
 	}
 
@@ -1495,7 +1508,7 @@ impl HTLCFailReason {
 					build_failure_packet(incoming_packet_shared_secret, *failure_code, &data[..])
 				}
 			},
-			HTLCFailReasonRepr::LightningError { ref err } => {
+			HTLCFailReasonRepr::LightningError { ref err, .. } => {
 				let mut err = err.clone();
 
 				crypt_failure_packet(incoming_packet_shared_secret, &mut err);
@@ -1512,7 +1525,7 @@ impl HTLCFailReason {
 		L::Target: Logger,
 	{
 		match self.0 {
-			HTLCFailReasonRepr::LightningError { ref err } => {
+			HTLCFailReasonRepr::LightningError { ref err, .. } => {
 				process_onion_failure(secp_ctx, logger, &htlc_source, err.clone())
 			},
 			#[allow(unused)]