From 9e6992272972aa378677d9fd9f3bfa9628b84ff2 Mon Sep 17 00:00:00 2001 From: Matt Corallo Date: Wed, 23 Aug 2023 02:57:35 +0000 Subject: [PATCH] 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). --- lightning/src/ln/channel.rs | 5 ++++- lightning/src/ln/channelmanager.rs | 4 +++- lightning/src/ln/outbound_payment.rs | 18 +++++++++++++++--- 3 files changed, 22 insertions(+), 5 deletions(-) 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 Channel 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 Channel 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::>()), 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), -- 2.39.5