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

Author: TheBlueMatt

lightning/src/ln/channel.rs

@@ -2213,6 +2213,8 @@ impl<Signer: WriteableEcdsaChannelSigner> Channel<Signer> {
 		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) => {
@@ -5188,7 +5190,8 @@ impl<Signer: WriteableEcdsaChannelSigner> Channel<Signer> {
 		}
 
 		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

@@ -3208,7 +3208,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),