Add PaymentHash to Record

    Adding the `payment_hash` to `Record` so we are able to track it
    in logs.

Author: jbesraa

lightning/src/chain/chainmonitor.rs

@@ -790,7 +790,7 @@ where C::Target: chain::Filter,
 		let monitors = self.monitors.read().unwrap();
 		match monitors.get(&funding_txo) {
 			None => {
-				let logger = WithContext::from(&self.logger, update.counterparty_node_id, Some(channel_id));
+				let logger = WithContext::from(&self.logger, update.counterparty_node_id, Some(channel_id), None);
 				log_error!(logger, "Failed to update channel monitor: no such monitor registered");
 
 				// We should never ever trigger this from within ChannelManager. Technically a

lightning/src/ln/channel.rs

@@ -896,12 +896,14 @@ pub(super) struct WithChannelContext<'a, L: Deref> where L::Target: Logger {
 	pub logger: &'a L,
 	pub peer_id: Option<PublicKey>,
 	pub channel_id: Option<ChannelId>,
+	pub payment_hash: Option<PaymentHash>,
 }
 
 impl<'a, L: Deref> Logger for WithChannelContext<'a, L> where L::Target: Logger {
 	fn log(&self, mut record: Record) {
 		record.peer_id = self.peer_id;
 		record.channel_id = self.channel_id;
+		record.payment_hash = self.payment_hash;
 		self.logger.log(record)
 	}
 }
@@ -915,6 +917,7 @@ where L::Target: Logger {
 			logger,
 			peer_id: Some(context.counterparty_node_id),
 			channel_id: Some(context.channel_id),
+			payment_hash: None
 		}
 	}
 }
@@ -1540,7 +1543,7 @@ impl<SP: Deref> ChannelContext<SP> where SP::Target: SignerProvider  {
 			L::Target: Logger,
 			SP::Target: SignerProvider,
 	{
-		let logger = WithContext::from(logger, Some(counterparty_node_id), Some(open_channel_fields.temporary_channel_id));
+		let logger = WithContext::from(logger, Some(counterparty_node_id), Some(open_channel_fields.temporary_channel_id), None);
 		let announced_channel = if (open_channel_fields.channel_flags & 1) == 1 { true } else { false };
 
 		let channel_value_satoshis = our_funding_satoshis.saturating_add(open_channel_fields.funding_satoshis);
@@ -7703,7 +7706,7 @@ impl<SP: Deref> InboundV1Channel<SP> where SP::Target: SignerProvider {
 			  F::Target: FeeEstimator,
 			  L::Target: Logger,
 	{
-		let logger = WithContext::from(logger, Some(counterparty_node_id), Some(msg.common_fields.temporary_channel_id));
+		let logger = WithContext::from(logger, Some(counterparty_node_id), Some(msg.common_fields.temporary_channel_id), None);
 
 		// First check the channel type is known, failing before we do anything else if we don't
 		// support this channel type.

lightning/src/ln/channelmanager.rs

@@ -2011,7 +2011,7 @@ macro_rules! handle_error {
 					let counterparty_node_id = shutdown_res.counterparty_node_id;
 					let channel_id = shutdown_res.channel_id;
 					let logger = WithContext::from(
-						&$self.logger, Some(counterparty_node_id), Some(channel_id),
+						&$self.logger, Some(counterparty_node_id), Some(channel_id), None
 					);
 					log_error!(logger, "Force-closing channel: {}", err.err);
 
@@ -2891,7 +2891,7 @@ where
 		}
 
 		let logger = WithContext::from(
-			&self.logger, Some(shutdown_res.counterparty_node_id), Some(shutdown_res.channel_id),
+			&self.logger, Some(shutdown_res.counterparty_node_id), Some(shutdown_res.channel_id), None
 		);
 
 		log_debug!(logger, "Finishing closure of channel due to {} with {} HTLCs to fail",
@@ -2967,7 +2967,7 @@ where
 			} else {
 				ClosureReason::HolderForceClosed
 			};
-			let logger = WithContext::from(&self.logger, Some(*peer_node_id), Some(*channel_id));
+			let logger = WithContext::from(&self.logger, Some(*peer_node_id), Some(*channel_id), None);
 			if let hash_map::Entry::Occupied(chan_phase_entry) = peer_state.channel_by_id.entry(channel_id.clone()) {
 				log_error!(logger, "Force-closing channel {}", channel_id);
 				let mut chan_phase = remove_channel_phase!(self, chan_phase_entry);
@@ -3098,7 +3098,7 @@ where
 			($msg: expr, $err_code: expr, $data: expr) => {
 				{
 					log_info!(
-						WithContext::from(&self.logger, Some(*counterparty_node_id), Some(msg.channel_id)),
+						WithContext::from(&self.logger, Some(*counterparty_node_id), Some(msg.channel_id), Some(msg.payment_hash)),
 						"Failed to accept/forward incoming HTLC: {}", $msg
 					);
 					// If `msg.blinding_point` is set, we must always fail with malformed.
@@ -3262,7 +3262,7 @@ where
 		macro_rules! return_err {
 			($msg: expr, $err_code: expr, $data: expr) => {
 				{
-					let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), Some(msg.channel_id));
+					let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), Some(msg.channel_id), Some(msg.payment_hash));
 					log_info!(logger, "Failed to accept/forward incoming HTLC: {}", $msg);
 					if msg.blinding_point.is_some() {
 						return PendingHTLCStatus::Fail(HTLCFailureMsg::Malformed(
@@ -3417,22 +3417,22 @@ where
 			&self.secp_ctx, &path, &session_priv, total_value, recipient_onion, cur_height,
 			payment_hash, keysend_preimage, prng_seed
 		).map_err(|e| {
-			let logger = WithContext::from(&self.logger, Some(path.hops.first().unwrap().pubkey), None);
+			let logger = WithContext::from(&self.logger, Some(path.hops.first().unwrap().pubkey), None, Some(*payment_hash));
 			log_error!(logger, "Failed to build an onion for path for payment hash {}", payment_hash);
 			e
 		})?;
 
 		let err: Result<(), _> = loop {
 			let (counterparty_node_id, id) = match self.short_to_chan_info.read().unwrap().get(&path.hops.first().unwrap().short_channel_id) {
 				None => {
-					let logger = WithContext::from(&self.logger, Some(path.hops.first().unwrap().pubkey), None);
+					let logger = WithContext::from(&self.logger, Some(path.hops.first().unwrap().pubkey), None, Some(*payment_hash));
 					log_error!(logger, "Failed to find first-hop for payment hash {}", payment_hash);
 					return Err(APIError::ChannelUnavailable{err: "No channel available with first hop!".to_owned()})
 				},
 				Some((cp_id, chan_id)) => (cp_id.clone(), chan_id.clone()),
 			};
 
-			let logger = WithContext::from(&self.logger, Some(counterparty_node_id), Some(id));
+			let logger = WithContext::from(&self.logger, Some(counterparty_node_id), Some(id), Some(*payment_hash));
 			log_trace!(logger,
 				"Attempting to send payment with payment hash {} along path with next hop {}",
 				payment_hash, path.hops.first().unwrap().short_channel_id);
@@ -4204,7 +4204,7 @@ where
 				None => {
 					let error = format!("Channel with id {} not found for the passed counterparty node_id {}",
 						next_hop_channel_id, next_node_id);
-					let logger = WithContext::from(&self.logger, Some(next_node_id), Some(*next_hop_channel_id));
+					let logger = WithContext::from(&self.logger, Some(next_node_id), Some(*next_hop_channel_id), None);
 					log_error!(logger, "{} when attempting to forward intercepted HTLC", error);
 					return Err(APIError::ChannelUnavailable {
 						err: error
@@ -4309,7 +4309,7 @@ where
 									}) => {
 										macro_rules! failure_handler {
 											($msg: expr, $err_code: expr, $err_data: expr, $phantom_ss: expr, $next_hop_unknown: expr) => {
-												let logger = WithContext::from(&self.logger, forwarding_counterparty, Some(prev_channel_id));
+												let logger = WithContext::from(&self.logger, forwarding_counterparty, Some(prev_channel_id), Some(payment_hash));
 												log_info!(logger, "Failed to accept/forward incoming HTLC: {}", $msg);
 
 												let htlc_source = HTLCSource::PreviousHopData(HTLCPreviousHopData {
@@ -5081,7 +5081,7 @@ where
 
 					for (chan_id, req) in peer_state.inbound_channel_request_by_id.iter_mut() {
 						if { req.ticks_remaining -= 1 ; req.ticks_remaining } <= 0 {
-							let logger = WithContext::from(&self.logger, Some(counterparty_node_id), Some(*chan_id));
+							let logger = WithContext::from(&self.logger, Some(counterparty_node_id), Some(*chan_id), None);
 							log_error!(logger, "Force-closing unaccepted inbound channel {} for not accepting in a timely manner", &chan_id);
 							peer_state.pending_msg_events.push(
 								events::MessageSendEvent::HandleError {
@@ -5362,7 +5362,7 @@ where
 				ref phantom_shared_secret, outpoint: _, ref blinded_failure, ref channel_id, ..
 			}) => {
 				log_trace!(
-					WithContext::from(&self.logger, None, Some(*channel_id)),
+					WithContext::from(&self.logger, None, Some(*channel_id), Some(*payment_hash)),
 					"Failing {}HTLC with payment_hash {} backwards from us: {:?}",
 					if blinded_failure.is_some() { "blinded " } else { "" }, &payment_hash, onion_error
 				);
@@ -5558,7 +5558,7 @@ where
 					if let msgs::ErrorAction::IgnoreError = err.err.action {
 						// We got a temporary failure updating monitor, but will claim the
 						// HTLC when the monitor updating is restored (or on chain).
-						let logger = WithContext::from(&self.logger, None, Some(prev_hop_chan_id));
+						let logger = WithContext::from(&self.logger, None, Some(prev_hop_chan_id), Some(payment_hash));
 						log_error!(logger, "Temporary failure claiming HTLC, treating as success: {}", err.err.err);
 					} else { errs.push((pk, err)); }
 				}
@@ -5710,7 +5710,7 @@ where
 				// with a preimage we *must* somehow manage to propagate it to the upstream
 				// channel, or we must have an ability to receive the same event and try
 				// again on restart.
-				log_error!(WithContext::from(&self.logger, None, Some(prev_hop.channel_id)),
+				log_error!(WithContext::from(&self.logger, None, Some(prev_hop.channel_id), None),
 					"Critical error: failed to update channel monitor with preimage {:?}: {:?}",
 					payment_preimage, update_res);
 			}
@@ -6091,7 +6091,7 @@ where
 
 	fn do_accept_inbound_channel(&self, temporary_channel_id: &ChannelId, counterparty_node_id: &PublicKey, accept_0conf: bool, user_channel_id: u128) -> Result<(), APIError> {
 
-		let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), Some(*temporary_channel_id));
+		let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), Some(*temporary_channel_id), None);
 		let _persistence_guard = PersistenceNotifierGuard::notify_on_drop(self);
 
 		let peers_without_funded_channels =
@@ -6527,7 +6527,8 @@ where
 					let logger = WithContext::from(
 						&self.logger,
 						Some(chan.context.get_counterparty_node_id()),
-						Some(chan.context.channel_id())
+						Some(chan.context.channel_id()),
+						None
 					);
 					let res =
 						chan.funding_signed(&msg, best_block, &self.signer_provider, &&logger);
@@ -6738,7 +6739,7 @@ where
 		};
 		if let Some(broadcast_tx) = tx {
 			let channel_id = chan_option.as_ref().map(|channel| channel.context().channel_id());
-			log_info!(WithContext::from(&self.logger, Some(*counterparty_node_id), channel_id), "Broadcasting {}", log_tx!(broadcast_tx));
+			log_info!(WithContext::from(&self.logger, Some(*counterparty_node_id), channel_id, None), "Broadcasting {}", log_tx!(broadcast_tx));
 			self.tx_broadcaster.broadcast_transactions(&[&broadcast_tx]);
 		}
 		if let Some(ChannelPhase::Funded(chan)) = chan_option {
@@ -7013,7 +7014,7 @@ where
 											prev_short_channel_id, prev_funding_outpoint, prev_channel_id, prev_htlc_id, prev_user_channel_id, forward_info });
 									},
 									hash_map::Entry::Occupied(_) => {
-										let logger = WithContext::from(&self.logger, None, Some(prev_channel_id));
+										let logger = WithContext::from(&self.logger, None, Some(prev_channel_id), Some(forward_info.payment_hash));
 										log_info!(logger, "Failed to forward incoming HTLC: detected duplicate intercepted payment over short channel id {}", scid);
 										let htlc_source = HTLCSource::PreviousHopData(HTLCPreviousHopData {
 											short_channel_id: prev_short_channel_id,
@@ -7277,7 +7278,7 @@ where
 						msg.channel_id
 					)
 				})?;
-			let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), Some(msg.channel_id));
+			let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), Some(msg.channel_id), None);
 			let mut peer_state_lock = peer_state_mutex.lock().unwrap();
 			let peer_state = &mut *peer_state_lock;
 			match peer_state.channel_by_id.entry(msg.channel_id) {
@@ -7379,7 +7380,7 @@ where
 			for monitor_event in monitor_events.drain(..) {
 				match monitor_event {
 					MonitorEvent::HTLCEvent(htlc_update) => {
-						let logger = WithContext::from(&self.logger, counterparty_node_id, Some(channel_id));
+						let logger = WithContext::from(&self.logger, counterparty_node_id, Some(channel_id), Some(htlc_update.payment_hash));
 						if let Some(preimage) = htlc_update.payment_preimage {
 							log_trace!(logger, "Claiming HTLC with preimage {} from our monitor", preimage);
 							self.claim_funds_internal(htlc_update.source, preimage,
@@ -8261,7 +8262,7 @@ where
 		mut completed_blocker: Option<RAAMonitorUpdateBlockingAction>) {
 
 		let logger = WithContext::from(
-			&self.logger, Some(counterparty_node_id), Some(channel_id),
+			&self.logger, Some(counterparty_node_id), Some(channel_id), None
 		);
 		loop {
 			let per_peer_state = self.per_peer_state.read().unwrap();
@@ -8733,7 +8734,7 @@ where
 							HTLCFailReason::from_failure_code(0x2000 | 2),
 							HTLCDestination::InvalidForward { requested_forward_scid }));
 					let logger = WithContext::from(
-						&self.logger, None, Some(htlc.prev_channel_id)
+						&self.logger, None, Some(htlc.prev_channel_id), Some(htlc.forward_info.payment_hash)
 					);
 					log_trace!(logger, "Timing out intercepted HTLC with requested forward scid {}", requested_forward_scid);
 					false
@@ -9043,7 +9044,7 @@ where
 		let mut per_peer_state = self.per_peer_state.write().unwrap();
 		let remove_peer = {
 			log_debug!(
-				WithContext::from(&self.logger, Some(*counterparty_node_id), None),
+				WithContext::from(&self.logger, Some(*counterparty_node_id), None, None),
 				"Marking channels with {} disconnected and generating channel_updates.",
 				log_pubkey!(counterparty_node_id)
 			);
@@ -9151,7 +9152,7 @@ where
 	}
 
 	fn peer_connected(&self, counterparty_node_id: &PublicKey, init_msg: &msgs::Init, inbound: bool) -> Result<(), ()> {
-		let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), None);
+		let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), None, None);
 		if !init_msg.features.supports_static_remote_key() {
 			log_debug!(logger, "Peer {} does not support static remote key, disconnecting", log_pubkey!(counterparty_node_id));
 			return Err(());
@@ -10950,7 +10951,7 @@ where
 		if let Some(in_flight_upds) = in_flight_monitor_updates {
 			for ((counterparty_id, funding_txo), mut chan_in_flight_updates) in in_flight_upds {
 				let channel_id = funding_txo_to_channel_id.get(&funding_txo).copied();
-				let logger = WithContext::from(&args.logger, Some(counterparty_id), channel_id);
+				let logger = WithContext::from(&args.logger, Some(counterparty_id), channel_id, None);
 				if let Some(monitor) = args.channel_monitors.get(&funding_txo) {
 					// Now that we've removed all the in-flight monitor updates for channels that are
 					// still open, we need to replay any monitor updates that are for closed channels,
@@ -11314,7 +11315,7 @@ where
 		for (node_id, monitor_update_blocked_actions) in monitor_update_blocked_actions_per_peer.unwrap() {
 			if let Some(peer_state) = per_peer_state.get(&node_id) {
 				for (channel_id, actions) in monitor_update_blocked_actions.iter() {
-					let logger = WithContext::from(&args.logger, Some(node_id), Some(*channel_id));
+					let logger = WithContext::from(&args.logger, Some(node_id), Some(*channel_id), None);
 					for action in actions.iter() {
 						if let MonitorUpdateCompletionAction::EmitEventAndFreeOtherChannel {
 							downstream_counterparty_and_funding_outpoint:
@@ -11342,7 +11343,7 @@ where
 				}
 				peer_state.lock().unwrap().monitor_update_blocked_actions = monitor_update_blocked_actions;
 			} else {
-				log_error!(WithContext::from(&args.logger, Some(node_id), None), "Got blocked actions without a per-peer-state for {}", node_id);
+				log_error!(WithContext::from(&args.logger, Some(node_id), None, None), "Got blocked actions without a per-peer-state for {}", node_id);
 				return Err(DecodeError::InvalidValue);
 			}
 		}