From e2f611e91b3f6edb4345e59656affef8a3a303d0 Mon Sep 17 00:00:00 2001 From: Elias Rohrer Date: Thu, 19 Mar 2026 13:07:04 +0100 Subject: [PATCH] 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 --- lightning/src/ln/channel.rs | 9 ++-- lightning/src/ln/peer_handler.rs | 15 +++--- lightning/src/util/macro_logger.rs | 85 ++++++++++++++++++++++++++++++ 3 files changed, 97 insertions(+), 12 deletions(-) diff --git a/lightning/src/ln/channel.rs b/lightning/src/ln/channel.rs index d0fc940eb62..ab9c964e5cb 100644 --- a/lightning/src/ln/channel.rs +++ b/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(), diff --git a/lightning/src/ln/peer_handler.rs b/lightning/src/ln/peer_handler.rs index 69d0815e8f0..2cc2b9c843b 100644 --- a/lightning/src/ln/peer_handler.rs +++ b/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,7 +2383,7 @@ 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() { @@ -2392,7 +2391,7 @@ impl< } }, 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)?, diff --git a/lightning/src/util/macro_logger.rs b/lightning/src/util/macro_logger.rs index 12f4f67962e..92f6d9767dc 100644 --- a/lightning/src/util/macro_logger.rs +++ b/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(), ""); + } +}