Merge pull request #2515 from TheBlueMatt/2023-08-earlier-payment-has…

…h-log

Include payment hash in more early payment logs

lightning/src/ln/channel.rs

@@ -2206,8 +2206,6 @@ impl<SP: Deref> Channel<SP> where
 		}
 		assert_eq!(self.context.channel_state & ChannelState::ShutdownComplete as u32, 0);
 
-		let payment_hash_calc = PaymentHash(Sha256::hash(&payment_preimage_arg.0[..]).into_inner());
-
 		// ChannelManager may generate duplicate claims/fails due to HTLC update events from
 		// on-chain ChannelsMonitors during block rescan. Ideally we'd figure out a way to drop
 		// these, but for now we just have to treat them as normal.
@@ -2216,7 +2214,9 @@ impl<SP: Deref> Channel<SP> where
 		let mut htlc_value_msat = 0;
 		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);
+				debug_assert_eq!(htlc.payment_hash, PaymentHash(Sha256::hash(&payment_preimage_arg.0[..]).into_inner()));
+				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) => {
@@ -5216,7 +5216,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" });

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");
 

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),