f - missed logging sites plus some clean-up

Author: jkczyz

lightning/src/ln/channelmanager.rs

@@ -1884,7 +1884,10 @@ macro_rules! handle_error {
 					}
 				}
 
-				log_error!(WithContext::from(&$self.logger, Some($counterparty_node_id), chan_id.map(|(cid, _)| cid)), "{}", err.err);
+				let logger = WithContext::from(
+					&$self.logger, Some($counterparty_node_id), chan_id.map(|(chan_id, _)| chan_id)
+				);
+				log_error!(logger, "{}", err.err);
 				if let msgs::ErrorAction::IgnoreError = err.action {
 				} else {
 					msg_events.push(events::MessageSendEvent::HandleError {
@@ -2836,7 +2839,7 @@ where
 			} else {
 				ClosureReason::HolderForceClosed
 			};
-			let logger = WithContext::from(&self.logger, Some(*peer_node_id), Some(channel_id.clone()));
+			let logger = WithContext::from(&self.logger, Some(*peer_node_id), Some(*channel_id));
 			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);
 				self.issue_channel_close_events(&chan_phase_entry.get().context(), closure_reason);
@@ -3157,7 +3160,8 @@ where
 		if chan.context.get_short_channel_id().is_none() {
 			return Err(LightningError{err: "Channel not yet established".to_owned(), action: msgs::ErrorAction::IgnoreError});
 		}
-		log_trace!(WithChannelContext::from(&self.logger, &chan.context), "Attempting to generate broadcast channel update for channel {}", &chan.context.channel_id());
+		let logger = WithChannelContext::from(&self.logger, &chan.context);
+		log_trace!(logger, "Attempting to generate broadcast channel update for channel {}", &chan.context.channel_id());
 		self.get_channel_update_for_unicast(chan)
 	}
 
@@ -3173,7 +3177,8 @@ where
 	/// [`channel_update`]: msgs::ChannelUpdate
 	/// [`internal_closing_signed`]: Self::internal_closing_signed
 	fn get_channel_update_for_unicast(&self, chan: &Channel<SP>) -> Result<msgs::ChannelUpdate, LightningError> {
-		log_trace!(self.logger, "Attempting to generate channel update for channel {}", log_bytes!(chan.context.channel_id().0));
+		let logger = WithChannelContext::from(&self.logger, &chan.context);
+		log_trace!(logger, "Attempting to generate channel update for channel {}", log_bytes!(chan.context.channel_id().0));
 		let short_channel_id = match chan.context.get_short_channel_id().or(chan.context.latest_inbound_scid_alias()) {
 			None => return Err(LightningError{err: "Channel not yet established".to_owned(), action: msgs::ErrorAction::IgnoreError}),
 			Some(id) => id,
@@ -3183,7 +3188,8 @@ where
 	}
 
 	fn get_channel_update_for_onion(&self, short_channel_id: u64, chan: &Channel<SP>) -> Result<msgs::ChannelUpdate, LightningError> {
-		log_trace!(self.logger, "Generating channel update for channel {}", log_bytes!(chan.context.channel_id().0));
+		let logger = WithChannelContext::from(&self.logger, &chan.context);
+		log_trace!(logger, "Generating channel update for channel {}", log_bytes!(chan.context.channel_id().0));
 		let were_node_one = self.our_network_pubkey.serialize()[..] < chan.context.get_counterparty_node_id().serialize()[..];
 
 		let enabled = chan.context.is_usable() && match chan.channel_update_status() {
@@ -4716,7 +4722,8 @@ where
 			| {
 				context.maybe_expire_prev_config();
 				if unfunded_context.should_expire_unfunded_channel() {
-					log_error!(self.logger,
+					let logger = WithChannelContext::from(&self.logger, context);
+					log_error!(logger,
 						"Force-closing pending channel with ID {} for not establishing in a timely manner", chan_id);
 					update_maps_on_chan_removal!(self, &context);
 					self.issue_channel_close_events(&context, ClosureReason::HolderForceClosed);
@@ -4830,7 +4837,8 @@ where
 
 					for (chan_id, req) in peer_state.inbound_channel_request_by_id.iter_mut() {
 						if { req.ticks_remaining -= 1 ; req.ticks_remaining } <= 0 {
-							log_error!(self.logger, "Force-closing unaccepted inbound channel {} for not accepting in a timely manner", &chan_id);
+							let logger = WithContext::from(&self.logger, Some(counterparty_node_id), Some(*chan_id));
+							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 {
 									node_id: counterparty_node_id,
@@ -5742,7 +5750,8 @@ where
 				pending.retain(|upd| upd.update_id > highest_applied_update_id);
 				pending.len()
 			} else { 0 };
-		log_trace!(WithChannelContext::from(&self.logger, &channel.context), "ChannelMonitor updated to {}. Current highest is {}. {} pending in-flight updates.",
+		let logger = WithChannelContext::from(&self.logger, &channel.context);
+		log_trace!(logger, "ChannelMonitor updated to {}. Current highest is {}. {} pending in-flight updates.",
 			highest_applied_update_id, channel.context.get_latest_monitor_update_id(),
 			remaining_in_flight);
 		if !channel.is_awaiting_monitor_update() || channel.context.get_latest_monitor_update_id() != highest_applied_update_id {
@@ -6129,7 +6138,8 @@ where
 							}
 							Ok(())
 						} else {
-							log_error!(self.logger, "Persisting initial ChannelMonitor failed, implying the funding outpoint was duplicated");
+							let logger = WithChannelContext::from(&self.logger, &chan.context);
+							log_error!(logger, "Persisting initial ChannelMonitor failed, implying the funding outpoint was duplicated");
 							let channel_id = match funding_msg_opt {
 								Some(msg) => msg.channel_id,
 								None => chan.context.channel_id(),
@@ -6441,7 +6451,8 @@ where
 					if let ChannelPhase::Funded(chan) = chan_phase_entry.get_mut() {
 						let res = try_chan_phase_entry!(self, chan.update_fulfill_htlc(&msg), chan_phase_entry);
 						if let HTLCSource::PreviousHopData(prev_hop) = &res.0 {
-							log_trace!(self.logger,
+							let logger = WithChannelContext::from(&self.logger, &chan.context);
+							log_trace!(logger,
 								"Holding the next revoke_and_ack from {} until the preimage is durably persisted in the inbound edge's ChannelMonitor",
 								msg.channel_id);
 							peer_state.actions_blocking_raa_monitor_updates.entry(msg.channel_id)
@@ -6593,7 +6604,8 @@ where
 											prev_short_channel_id, prev_funding_outpoint, prev_htlc_id, prev_user_channel_id, forward_info });
 									},
 									hash_map::Entry::Occupied(_) => {
-										log_info!(WithContext::from(&self.logger, None, Some(prev_funding_outpoint.to_channel_id())), "Failed to forward incoming HTLC: detected duplicate intercepted payment over short channel id {}", scid);
+										let logger = WithContext::from(&self.logger, None, Some(prev_funding_outpoint.to_channel_id()));
+										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,
 											user_channel_id: Some(prev_user_channel_id),
@@ -7748,12 +7760,14 @@ where
 	/// operation. It will double-check that nothing *else* is also blocking the same channel from
 	/// making progress and then let any blocked [`ChannelMonitorUpdate`]s fly.
 	fn handle_monitor_update_release(&self, counterparty_node_id: PublicKey, channel_funding_outpoint: OutPoint, mut completed_blocker: Option<RAAMonitorUpdateBlockingAction>) {
+		let logger = WithContext::from(
+			&self.logger, Some(counterparty_node_id), Some(channel_funding_outpoint.to_channel_id())
+		);
 		loop {
 			let per_peer_state = self.per_peer_state.read().unwrap();
 			if let Some(peer_state_mtx) = per_peer_state.get(&counterparty_node_id) {
 				let mut peer_state_lck = peer_state_mtx.lock().unwrap();
 				let peer_state = &mut *peer_state_lck;
-				let logger = WithContext::from(&self.logger, Some(counterparty_node_id), Some(channel_funding_outpoint.to_channel_id()));
 				if let Some(blocker) = completed_blocker.take() {
 					// Only do this on the first iteration of the loop.
 					if let Some(blockers) = peer_state.actions_blocking_raa_monitor_updates
@@ -7775,7 +7789,6 @@ where
 
 				if let hash_map::Entry::Occupied(mut chan_phase_entry) = peer_state.channel_by_id.entry(channel_funding_outpoint.to_channel_id()) {
 					if let ChannelPhase::Funded(chan) = chan_phase_entry.get_mut() {
-						let logger = WithChannelContext::from(&self.logger, &chan.context);
 						debug_assert_eq!(chan.context.get_funding_txo().unwrap(), channel_funding_outpoint);
 						if let Some((monitor_update, further_update_exists)) = chan.unblock_next_blocked_monitor_update() {
 							log_debug!(logger, "Unlocking monitor updating for channel {} and updating monitor",
@@ -7794,7 +7807,6 @@ where
 					}
 				}
 			} else {
-				let logger = WithContext::from(&self.logger, Some(counterparty_node_id), Some(channel_funding_outpoint.to_channel_id()));
 				log_debug!(logger,
 					"Got a release post-RAA monitor update for peer {} but the channel is gone",
 					log_pubkey!(counterparty_node_id));
@@ -8552,7 +8564,10 @@ where
 					timed_out_htlcs.push((prev_hop_data, htlc.forward_info.payment_hash,
 							HTLCFailReason::from_failure_code(0x2000 | 2),
 							HTLCDestination::InvalidForward { requested_forward_scid }));
-					log_trace!(self.logger, "Timing out intercepted HTLC with requested forward scid {}", requested_forward_scid);
+					let logger = WithContext::from(
+						&self.logger, None, Some(htlc.prev_funding_outpoint.to_channel_id())
+					);
+					log_trace!(logger, "Timing out intercepted HTLC with requested forward scid {}", requested_forward_scid);
 					false
 				} else { true }
 			});
@@ -8859,8 +8874,11 @@ where
 		let mut failed_channels = Vec::new();
 		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), "Marking channels with {} disconnected and generating channel_updates.",
-				log_pubkey!(counterparty_node_id));
+			log_debug!(
+				WithContext::from(&self.logger, Some(*counterparty_node_id), None),
+				"Marking channels with {} disconnected and generating channel_updates.",
+				log_pubkey!(counterparty_node_id)
+			);
 			if let Some(peer_state_mutex) = per_peer_state.get(counterparty_node_id) {
 				let mut peer_state_lock = peer_state_mutex.lock().unwrap();
 				let peer_state = &mut *peer_state_lock;