Truncate logged peer message strings

Counterparty-provided strings in network messages (Error, Warning,
TxAbort) were logged without length limits, allowing a malicious peer
to bloat log files. Some logging sites also lacked the same
sanitization used for other untrusted strings.

Add a `DebugMsg` struct and `log_msg!` macro that consistently
truncate messages to 512 characters while preserving `PrintableString`
sanitization. Replace all bare `msg.data` and ad hoc
`PrintableString(&msg.data)` usages at the 7 relevant logging sites
in `peer_handler.rs` and `channel.rs`.

Co-Authored-By: HAL 9000

Author: tnull

lightning/src/ln/channel.rs

@@ -2070,9 +2070,12 @@ where
 
 		let tx_abort = should_ack.then(|| {
 			let logger = WithChannelContext::from(logger, &self.context(), None);
-			let reason =
-				types::string::UntrustedString(String::from_utf8_lossy(&msg.data).to_string());
-			log_info!(logger, "Counterparty failed interactive transaction negotiation: {reason}");
+			let reason = String::from_utf8_lossy(&msg.data);
+			log_info!(
+				logger,
+				"Counterparty failed interactive transaction negotiation: {}",
+				log_msg!(reason)
+			);
 			msgs::TxAbort {
 				channel_id: msg.channel_id,
 				data: "Acknowledged tx_abort".to_string().into_bytes(),

lightning/src/ln/peer_handler.rs

@@ -45,7 +45,6 @@ use crate::onion_message::packet::OnionMessageContents;
 use crate::routing::gossip::{NodeAlias, NodeId};
 use crate::sign::{NodeSigner, Recipient};
 use crate::types::features::{InitFeatures, NodeFeatures};
-use crate::types::string::PrintableString;
 use crate::util::atomic_counter::AtomicCounter;
 use crate::util::logger::{Level, Logger, WithContext};
 use crate::util::ser::{VecWriter, Writeable, Writer};
@@ -2384,15 +2383,15 @@ impl<
 					logger,
 					"Got Err message from {}: {}",
 					their_node_id,
-					PrintableString(&msg.data)
+					log_msg!(msg.data)
 				);
 				self.message_handler.chan_handler.handle_error(their_node_id, &msg);
 				if msg.channel_id.is_zero() {
 					return Err(PeerHandleError {}.into());
 				}
 			},
 			Message::Warning(msg) => {
-				log_debug!(logger, "Got warning message: {}", PrintableString(&msg.data));
+				log_debug!(logger, "Got warning message: {}", log_msg!(msg.data));
 			},
 
 			Message::Ping(msg) => {
@@ -3246,7 +3245,7 @@ impl<
 								msgs::ErrorAction::DisconnectPeer { msg } => {
 									if let Some(msg) = msg.as_ref() {
 										log_trace!(logger, "Handling DisconnectPeer HandleError event in peer_handler with message {}",
-											msg.data);
+											log_msg!(msg.data));
 									} else {
 										log_trace!(logger, "Handling DisconnectPeer HandleError event in peer_handler",
 											 );
@@ -3260,7 +3259,7 @@ impl<
 								},
 								msgs::ErrorAction::DisconnectPeerWithWarning { msg } => {
 									log_trace!(logger, "Handling DisconnectPeer HandleError event in peer_handler with message {}",
-										 msg.data);
+										 log_msg!(msg.data));
 									// We do not have the peers write lock, so we just store that we're
 									// about to disconnect the peer and do it after we finish
 									// processing most messages.
@@ -3283,8 +3282,7 @@ impl<
 								},
 								msgs::ErrorAction::SendErrorMessage { msg } => {
 									log_trace!(logger, "Handling SendErrorMessage HandleError event in peer_handler with message {}",
-
-											msg.data);
+											log_msg!(msg.data));
 									let msg = Message::Error(msg);
 									self.enqueue_message(
 										&mut *get_peer_for_forwarding!(&node_id)?,
@@ -3293,8 +3291,7 @@ impl<
 								},
 								msgs::ErrorAction::SendWarningMessage { msg, ref log_level } => {
 									log_given_level!(logger, *log_level, "Handling SendWarningMessage HandleError event in peer_handler with message {}",
-
-											msg.data);
+											log_msg!(msg.data));
 									let msg = Message::Warning(msg);
 									self.enqueue_message(
 										&mut *get_peer_for_forwarding!(&node_id)?,

lightning/src/util/macro_logger.rs

@@ -169,6 +169,33 @@ macro_rules! log_spendable {
 	};
 }
 
+/// The maximum number of characters to display in a network message log entry.
+pub(crate) const LOG_MSG_MAX_LEN: usize = 512;
+
+/// Wraps a string slice for Display, truncating to [`LOG_MSG_MAX_LEN`] characters and
+/// delegating sanitization to [`crate::types::string::PrintableString`].
+/// Useful for logging counterparty-provided messages.
+pub(crate) struct DebugMsg<'a>(pub &'a str);
+impl<'a> core::fmt::Display for DebugMsg<'a> {
+	fn fmt(&self, f: &mut core::fmt::Formatter) -> Result<(), core::fmt::Error> {
+		let (msg, was_truncated) = match self.0.char_indices().nth(LOG_MSG_MAX_LEN) {
+			Some((idx, _)) => (&self.0[..idx], true),
+			None => (self.0, false),
+		};
+		core::fmt::Display::fmt(&crate::types::string::PrintableString(msg), f)?;
+		if was_truncated {
+			f.write_str("...")?;
+		}
+		Ok(())
+	}
+}
+
+macro_rules! log_msg {
+	($obj: expr) => {
+		$crate::util::macro_logger::DebugMsg(&$obj)
+	};
+}
+
 /// Create a new Record and log it. You probably don't want to use this macro directly,
 /// but it needs to be exported so `log_trace` etc can use it in external crates.
 #[doc(hidden)]
@@ -226,3 +253,61 @@ macro_rules! log_gossip {
 		$crate::log_given_level!($logger, $crate::util::logger::Level::Gossip, $($arg)*);
 	)
 }
+
+#[cfg(test)]
+mod tests {
+	use super::*;
+	use alloc::string::ToString;
+
+	#[test]
+	fn debug_msg_short_string() {
+		let s = "hello world";
+		assert_eq!(DebugMsg(s).to_string(), "hello world");
+	}
+
+	#[test]
+	fn debug_msg_truncates_at_limit() {
+		let s: String = core::iter::repeat('a').take(LOG_MSG_MAX_LEN + 100).collect();
+		let result = DebugMsg(&s).to_string();
+		// Should be exactly LOG_MSG_MAX_LEN 'a's followed by "..."
+		assert_eq!(result.len(), LOG_MSG_MAX_LEN + 3);
+		assert!(result.ends_with("..."));
+	}
+
+	#[test]
+	fn debug_msg_no_truncation_at_exact_limit() {
+		let s: String = core::iter::repeat('a').take(LOG_MSG_MAX_LEN).collect();
+		let result = DebugMsg(&s).to_string();
+		assert_eq!(result.len(), LOG_MSG_MAX_LEN);
+		assert!(!result.ends_with("..."));
+	}
+
+	#[test]
+	fn debug_msg_replaces_control_characters() {
+		let s = "hello\x00world\nfoo";
+		let result = DebugMsg(s).to_string();
+		assert_eq!(result, "hello\u{FFFD}world\u{FFFD}foo");
+	}
+
+	#[test]
+	fn debug_msg_uses_printable_string_sanitization() {
+		let s = "safe\u{202E}cipsxe.exe";
+		assert_eq!(DebugMsg(s).to_string(), crate::types::string::PrintableString(s).to_string());
+	}
+
+	#[test]
+	fn debug_msg_multibyte_unicode() {
+		// Each emoji is multiple bytes but one character
+		let s: String = core::iter::repeat('\u{1F600}').take(LOG_MSG_MAX_LEN + 10).collect();
+		let result = DebugMsg(&s).to_string();
+		let char_count: usize = result.chars().count();
+		// LOG_MSG_MAX_LEN emoji chars + 3 chars for "..."
+		assert_eq!(char_count, LOG_MSG_MAX_LEN + 3);
+		assert!(result.ends_with("..."));
+	}
+
+	#[test]
+	fn debug_msg_empty_string() {
+		assert_eq!(DebugMsg("").to_string(), "");
+	}
+}