From: Matt Corallo <git@bluematt.me>
Date: Wed, 23 Aug 2023 02:57:35 +0000 (+0000)
Subject: Include payment hash in more early payment logs
X-Git-Tag: v0.0.117-alpha1~43^2~1
X-Git-Url: http://git.bitcoin.ninja/?a=commitdiff_plain;h=9e6992272972aa378677d9fd9f3bfa9628b84ff2;p=rust-lightning

Include payment hash in more early payment logs

If a user has issues with a payment, the most obvious thing they'll
do is check logs for the payment hash. Thus, we should ensure our
logs that show a payment's lifecycle include the payment hash and
are emitted (a) as soon as LDK learns of the payment, (b) once the
payment goes out to the peer (which is already reasonably covered
in the commitment transaction building logs) and (c) when the
payment ultimately is fulfilled or fails.

Here we improve our logs for both (a) and (c).
---

diff --git a/lightning/src/ln/channel.rs b/lightning/src/ln/channel.rs
index f66f48c50..d1479dd1b 100644
--- a/lightning/src/ln/channel.rs
+++ b/lightning/src/ln/channel.rs
@@ -2217,6 +2217,8 @@ impl<SP: Deref> Channel<SP> where
 		for (idx, htlc) in self.context.pending_inbound_htlcs.iter().enumerate() {
 			if htlc.htlc_id == htlc_id_arg {
 				assert_eq!(htlc.payment_hash, payment_hash_calc);
+				log_debug!(logger, "Claiming inbound HTLC id {} with payment hash {} with preimage {}",
+					htlc.htlc_id, htlc.payment_hash, payment_preimage_arg);
 				match htlc.state {
 					InboundHTLCState::Committed => {},
 					InboundHTLCState::LocalRemoved(ref reason) => {
@@ -5210,7 +5212,8 @@ impl<SP: Deref> Channel<SP> where
 		}
 
 		let need_holding_cell = (self.context.channel_state & (ChannelState::AwaitingRemoteRevoke as u32 | ChannelState::MonitorUpdateInProgress as u32)) != 0;
-		log_debug!(logger, "Pushing new outbound HTLC for {} msat {}", amount_msat,
+		log_debug!(logger, "Pushing new outbound HTLC with hash {} for {} msat {}",
+			payment_hash, amount_msat,
 			if force_holding_cell { "into holding cell" }
 			else if need_holding_cell { "into holding cell as we're awaiting an RAA or monitor" }
 			else { "to peer" });
diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs
index 07f7cd31d..7c8ad4694 100644
--- a/lightning/src/ln/channelmanager.rs
+++ b/lightning/src/ln/channelmanager.rs
@@ -3210,7 +3210,9 @@ where
 		// The top-level caller should hold the total_consistency_lock read lock.
 		debug_assert!(self.total_consistency_lock.try_write().is_err());
 
-		log_trace!(self.logger, "Attempting to send payment for path with next hop {}", path.hops.first().unwrap().short_channel_id);
+		log_trace!(self.logger,
+			"Attempting to send payment with payment hash {} along path with next hop {}",
+			payment_hash, path.hops.first().unwrap().short_channel_id);
 		let prng_seed = self.entropy_source.get_secure_random_bytes();
 		let session_priv = SecretKey::from_slice(&session_priv_bytes[..]).expect("RNG is busted");
 
diff --git a/lightning/src/ln/outbound_payment.rs b/lightning/src/ln/outbound_payment.rs
index 5b18acfe3..4d6f1f00b 100644
--- a/lightning/src/ln/outbound_payment.rs
+++ b/lightning/src/ln/outbound_payment.rs
@@ -722,6 +722,8 @@ impl OutboundPayments {
 	{
 		#[cfg(feature = "std")] {
 			if has_expired(&route_params) {
+				log_error!(logger, "Payment with id {} and hash {} had expired before we started paying",
+					payment_id, payment_hash);
 				return Err(RetryableSendFailure::PaymentExpired)
 			}
 		}
@@ -730,16 +732,25 @@ impl OutboundPayments {
 			&node_signer.get_node_id(Recipient::Node).unwrap(), &route_params,
 			Some(&first_hops.iter().collect::<Vec<_>>()), inflight_htlcs(),
 			payment_hash, payment_id,
-		).map_err(|_| RetryableSendFailure::RouteNotFound)?;
+		).map_err(|_| {
+			log_error!(logger, "Failed to find route for payment with id {} and hash {}",
+				payment_id, payment_hash);
+			RetryableSendFailure::RouteNotFound
+		})?;
 
 		let onion_session_privs = self.add_new_pending_payment(payment_hash,
 			recipient_onion.clone(), payment_id, keysend_preimage, &route, Some(retry_strategy),
 			Some(route_params.payment_params.clone()), entropy_source, best_block_height)
-			.map_err(|_| RetryableSendFailure::DuplicatePayment)?;
+			.map_err(|_| {
+				log_error!(logger, "Payment with id {} is already pending. New payment had payment hash {}",
+					payment_id, payment_hash);
+				RetryableSendFailure::DuplicatePayment
+			})?;
 
 		let res = self.pay_route_internal(&route, payment_hash, recipient_onion, keysend_preimage, payment_id, None,
 			onion_session_privs, node_signer, best_block_height, &send_payment_along_path);
-		log_info!(logger, "Result sending payment with id {}: {:?}", &payment_id, res);
+		log_info!(logger, "Sending payment with id {} and hash {} returned {:?}",
+			payment_id, payment_hash, res);
 		if let Err(e) = res {
 			self.handle_pay_route_err(e, payment_id, payment_hash, route, route_params, router, first_hops, &inflight_htlcs, entropy_source, node_signer, best_block_height, logger, pending_events, &send_payment_along_path);
 		}
@@ -1188,6 +1199,7 @@ impl OutboundPayments {
 		if let hash_map::Entry::Occupied(mut payment) = outbounds.entry(payment_id) {
 			if !payment.get().is_fulfilled() {
 				let payment_hash = PaymentHash(Sha256::hash(&payment_preimage.0).into_inner());
+				log_info!(logger, "Payment with id {} and hash {} sent!", payment_id, payment_hash);
 				let fee_paid_msat = payment.get().get_pending_fee_msat();
 				pending_events.push_back((events::Event::PaymentSent {
 					payment_id: Some(payment_id),