Add PaymentId to logging Records

While `PaymentHash`es are great for searching logs, in the case of
BOLT 12 the hash isn't selected until well into the payment
process. Thus, its important that we allow for filtering by
`PaymentId` as well to ensure payment-related logs are always
reliably searchable.

Author: TheBlueMatt

lightning/src/ln/channelmanager.rs

@@ -5192,6 +5192,13 @@ where
 		let prng_seed = self.entropy_source.get_secure_random_bytes();
 		let session_priv = SecretKey::from_slice(&session_priv_bytes[..]).expect("RNG is busted");
 
+		let logger = WithContext::for_payment(
+			&self.logger,
+			path.hops.first().map(|hop| hop.pubkey),
+			None,
+			Some(*payment_hash),
+			payment_id,
+		);
 		let (onion_packet, htlc_msat, htlc_cltv) = onion_utils::create_payment_onion(
 			&self.secp_ctx,
 			&path,
@@ -5205,8 +5212,6 @@ where
 			prng_seed,
 		)
 		.map_err(|e| {
-			let first_hop_key = Some(path.hops.first().unwrap().pubkey);
-			let logger = WithContext::from(&self.logger, first_hop_key, None, Some(*payment_hash));
 			log_error!(logger, "Failed to build an onion for path");
 			e
 		})?;
@@ -5217,9 +5222,6 @@ where
 
 			let (counterparty_node_id, id) = match first_chan {
 				None => {
-					let first_hop_key = Some(path.hops.first().unwrap().pubkey);
-					let logger =
-						WithContext::from(&self.logger, first_hop_key, None, Some(*payment_hash));
 					log_error!(logger, "Failed to find first-hop for payment hash {payment_hash}");
 					return Err(APIError::ChannelUnavailable {
 						err: "No channel available with first hop!".to_owned(),
@@ -5228,12 +5230,9 @@ where
 				Some((cp_id, chan_id)) => (cp_id, chan_id),
 			};
 
-			let logger = WithContext::from(
-				&self.logger,
-				Some(counterparty_node_id),
-				Some(id),
-				Some(*payment_hash),
-			);
+			// Add the channel id to the logger that already has the rest filled in.
+			let logger_ref = &logger;
+			let logger = WithContext::from(&logger_ref, None, Some(id), None);
 			log_trace!(
 				logger,
 				"Attempting to send payment along path with next hop {first_chan_scid}"
@@ -5256,11 +5255,6 @@ where
 							});
 						}
 						let funding_txo = chan.funding.get_funding_txo().unwrap();
-						let logger = WithChannelContext::from(
-							&self.logger,
-							&chan.context,
-							Some(*payment_hash),
-						);
 						let htlc_source = HTLCSource::OutboundRoute {
 							path: path.clone(),
 							session_priv: session_priv.clone(),
@@ -5354,7 +5348,8 @@ where
 		});
 		if route.route_params.is_none() { route.route_params = Some(route_params.clone()); }
 		let router = FixedRouter::new(route);
-		let logger = WithContext::from(&self.logger, None, None, Some(payment_hash));
+		let logger =
+			WithContext::for_payment(&self.logger, None, None, Some(payment_hash), payment_id);
 		self.pending_outbound_payments
 			.send_payment(payment_hash, recipient_onion, payment_id, Retry::Attempts(0),
 				route_params, &&router, self.list_usable_channels(), || self.compute_inflight_htlcs(),
@@ -5419,7 +5414,7 @@ where
 			best_block_height,
 			&self.pending_events,
 			|args| self.send_payment_along_path(args),
-			&WithContext::from(&self.logger, None, None, Some(payment_hash)),
+			&WithContext::for_payment(&self.logger, None, None, Some(payment_hash), payment_id),
 		)
 	}
 
@@ -5504,6 +5499,7 @@ where
 	) -> Result<(), Bolt11PaymentError> {
 		let best_block_height = self.best_block.read().unwrap().height;
 		let _persistence_guard = PersistenceNotifierGuard::notify_on_drop(self);
+		let payment_hash = invoice.payment_hash();
 		self.pending_outbound_payments.pay_for_bolt11_invoice(
 			invoice,
 			payment_id,
@@ -5518,7 +5514,7 @@ where
 			best_block_height,
 			&self.pending_events,
 			|args| self.send_payment_along_path(args),
-			&WithContext::from(&self.logger, None, None, Some(invoice.payment_hash())),
+			&WithContext::for_payment(&self.logger, None, None, Some(payment_hash), payment_id),
 		)
 	}
 
@@ -5571,7 +5567,7 @@ where
 			best_block_height,
 			&self.pending_events,
 			|args| self.send_payment_along_path(args),
-			&WithContext::from(&self.logger, None, None, None),
+			&WithContext::for_payment(&self.logger, None, None, None, payment_id),
 		)
 	}
 
@@ -5628,6 +5624,7 @@ where
 	) -> Result<(), Bolt12PaymentError> {
 		let mut res = Ok(());
 		PersistenceNotifierGuard::optionally_notify(self, || {
+			let logger = WithContext::for_payment(&self.logger, None, None, None, payment_id);
 			let best_block_height = self.best_block.read().unwrap().height;
 			let features = self.bolt12_invoice_features();
 			let outbound_pmts_res = self.pending_outbound_payments.static_invoice_received(
@@ -5660,7 +5657,7 @@ where
 					self.send_payment_for_static_invoice_no_persist(payment_id, channels, true)
 				{
 					log_trace!(
-						self.logger,
+						logger,
 						"Failed to send held HTLC with payment id {}: {:?}",
 						payment_id,
 						e
@@ -5752,7 +5749,7 @@ where
 			best_block_height,
 			&self.pending_events,
 			|args| self.send_payment_along_path(args),
-			&WithContext::from(&self.logger, None, None, None),
+			&WithContext::for_payment(&self.logger, None, None, None, payment_id),
 		)
 	}
 
@@ -5846,7 +5843,7 @@ where
 			best_block_height,
 			&self.pending_events,
 			|args| self.send_payment_along_path(args),
-			&WithContext::from(&self.logger, None, None, payment_hash),
+			&WithContext::for_payment(&self.logger, None, None, payment_hash, payment_id),
 		)
 	}
 
@@ -8652,7 +8649,13 @@ where
 		// being fully configured. See the docs for `ChannelManagerReadArgs` for more.
 		match source {
 			HTLCSource::OutboundRoute { ref path, ref session_priv, ref payment_id, .. } => {
-				let logger = WithContext::from(&self.logger, None, None, Some(*payment_hash));
+				let logger = WithContext::for_payment(
+					&self.logger,
+					path.hops.first().map(|hop| hop.pubkey),
+					None,
+					Some(*payment_hash),
+					*payment_id,
+				);
 				self.pending_outbound_payments.fail_htlc(
 					source,
 					payment_hash,
@@ -9346,6 +9349,13 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 						counterparty_node_id: path.hops[0].pubkey,
 					})
 				};
+				let logger = WithContext::for_payment(
+					&self.logger,
+					path.hops.first().map(|hop| hop.pubkey),
+					None,
+					Some(payment_preimage.into()),
+					payment_id,
+				);
 				self.pending_outbound_payments.claim_htlc(
 					payment_id,
 					payment_preimage,
@@ -9355,7 +9365,7 @@ This indicates a bug inside LDK. Please report this error at https://github.com/
 					from_onchain,
 					&mut ev_completion_action,
 					&self.pending_events,
-					&WithContext::from(&self.logger, None, None, Some(payment_preimage.into())),
+					&logger,
 				);
 				// If an event was generated, `claim_htlc` set `ev_completion_action` to None, if
 				// not, we should go ahead and run it now (as the claim was duplicative), at least
@@ -16118,8 +16128,8 @@ where
 					Err(()) => return None,
 				};
 
-				let logger = WithContext::from(
-					&self.logger, None, None, Some(invoice.payment_hash()),
+				let logger = WithContext::for_payment(
+					&self.logger, None, None, Some(invoice.payment_hash()), payment_id,
 				);
 
 				if self.config.read().unwrap().manually_handle_bolt12_invoices {

lightning/src/ln/outbound_payment.rs

@@ -1365,6 +1365,9 @@ impl OutboundPayments {
 			}
 			core::mem::drop(outbounds);
 			if let Some((payment_hash, payment_id, route_params)) = retry_id_route_params {
+				let logger =
+					WithContext::for_payment(&logger, None, None, Some(payment_hash), payment_id);
+				let logger = &logger;
 				self.find_route_and_send_payment(
 					payment_hash,
 					payment_id,
@@ -1810,7 +1813,7 @@ impl OutboundPayments {
 	#[rustfmt::skip]
 	pub(super) fn send_probe<ES: Deref, NS: Deref, F>(
 		&self, path: Path, probing_cookie_secret: [u8; 32], entropy_source: &ES, node_signer: &NS,
-		best_block_height: u32, send_payment_along_path: F
+		best_block_height: u32, send_payment_along_path: F,
 	) -> Result<(PaymentHash, PaymentId), ProbeSendFailure>
 	where
 		ES::Target: EntropySource,

lightning/src/util/logger.rs

@@ -21,6 +21,7 @@ use core::fmt::Display;
 use core::fmt::Write;
 use core::ops::Deref;
 
+use crate::ln::channelmanager::PaymentId;
 use crate::ln::types::ChannelId;
 #[cfg(c_bindings)]
 use crate::prelude::*; // Needed for String
@@ -124,12 +125,18 @@ pub struct Record<$($args)?> {
 	pub file: &'static str,
 	/// The line containing the message.
 	pub line: u32,
-	/// The payment hash. Since payment_hash is not repeated in the message body, include it in the log output so
-	/// entries remain clear.
+	/// The payment hash.
 	///
-	/// Note that this is only filled in for logs pertaining to a specific payment, and will be
-	/// `None` for logs which are not directly related to a payment.
+	/// Since payment_hash is generally not repeated in the message body, you should ensure you log
+	/// it so that entries remain clear.
+	///
+	/// Note that payments don't always have a [`PaymentHash`] immediately - when paying BOLT 12
+	/// offers the [`PaymentHash`] is only selected a ways into the payment process. Thus, when
+	/// searching your logs for specific payments you should also search for the relevant
+	/// [`Self::payment_id`].
 	pub payment_hash: Option<PaymentHash>,
+	/// The payment id if the log pertained to a payment with an ID.
+	pub payment_id: Option<PaymentId>,
 }
 
 impl<$($args)?> Record<$($args)?> {
@@ -138,22 +145,22 @@ impl<$($args)?> Record<$($args)?> {
 	/// This is not exported to bindings users as fmt can't be used in C
 	#[inline]
 	pub fn new<$($nonstruct_args)?>(
-		level: Level, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
-		args: fmt::Arguments<'a>, module_path: &'static str, file: &'static str, line: u32,
-		payment_hash: Option<PaymentHash>
+		level: Level, args: fmt::Arguments<'a>, module_path: &'static str, file: &'static str,
+		line: u32,
 	) -> Record<$($args)?> {
 		Record {
 			level,
-			peer_id,
-			channel_id,
+			peer_id: None,
+			channel_id: None,
 			#[cfg(not(c_bindings))]
 			args,
 			#[cfg(c_bindings)]
 			args: format!("{}", args),
 			module_path,
 			file,
 			line,
-			payment_hash,
+			payment_hash: None,
+			payment_id: None,
 		}
 	}
 }
@@ -295,14 +302,11 @@ pub struct WithContext<'a, L: Deref>
 where
 	L::Target: Logger,
 {
-	/// The logger to delegate to after adding context to the record.
 	logger: &'a L,
-	/// The node id of the peer pertaining to the logged record.
 	peer_id: Option<PublicKey>,
-	/// The channel id of the channel pertaining to the logged record.
 	channel_id: Option<ChannelId>,
-	/// The payment hash of the payment pertaining to the logged record.
 	payment_hash: Option<PaymentHash>,
+	payment_id: Option<PaymentId>,
 }
 
 impl<'a, L: Deref> Logger for WithContext<'a, L>
@@ -319,6 +323,9 @@ where
 		if self.payment_hash.is_some() {
 			record.payment_hash = self.payment_hash;
 		}
+		if self.payment_id.is_some() {
+			record.payment_id = self.payment_id;
+		}
 		self.logger.log(record)
 	}
 }
@@ -332,7 +339,16 @@ where
 		logger: &'a L, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
 		payment_hash: Option<PaymentHash>,
 	) -> Self {
-		WithContext { logger, peer_id, channel_id, payment_hash }
+		WithContext { logger, peer_id, channel_id, payment_hash, payment_id: None }
+	}
+
+	/// Wraps the given logger, providing additional context to any logged records.
+	pub fn for_payment(
+		logger: &'a L, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
+		payment_hash: Option<PaymentHash>, payment_id: PaymentId,
+	) -> Self {
+		let payment_id = Some(payment_id);
+		WithContext { logger, peer_id, channel_id, payment_hash, payment_id }
 	}
 }
 

lightning/src/util/macro_logger.rs

@@ -175,7 +175,7 @@ macro_rules! log_spendable {
 #[macro_export]
 macro_rules! log_given_level {
 	($logger: expr, $lvl:expr, $($arg:tt)+) => (
-		$logger.log($crate::util::logger::Record::new($lvl, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None))
+		$logger.log($crate::util::logger::Record::new($lvl, format_args!($($arg)+), module_path!(), file!(), line!()))
 	);
 }