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 f66f48c50499daf83bc4b1ab4669ff9ddc76078c..d1479dd1bca575a5d9f1bbf977c5a56952e24d92 100644 (file)
--- 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 07f7cd31d6e4b04941c3387f3a8222e2d9c61814..7c8ad46941e882df5ff18c92bbca3948ee665351 100644 (file)
--- 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 5b18acfe3b34c2779f3199435b213f1117df79f4..4d6f1f00b568017edd3d0933dd5923dc48f50b79 100644 (file)
--- 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),