From 3b4b74bc6643fbc87e252ad346263fdc22048e51 Mon Sep 17 00:00:00 2001 From: Elias Rohrer Date: Mon, 22 Nov 2021 18:19:08 +0100 Subject: [PATCH] Add a new log-level for gossip messages. --- lightning/Cargo.toml | 1 + lightning/src/ln/peer_handler.rs | 44 +++++++++++++++++++------- lightning/src/routing/network_graph.rs | 8 ++--- lightning/src/util/logger.rs | 15 +++++++-- lightning/src/util/macro_logger.rs | 9 ++++++ 5 files changed, 58 insertions(+), 19 deletions(-) diff --git a/lightning/Cargo.toml b/lightning/Cargo.toml index 8202219bf..61ac0125f 100644 --- a/lightning/Cargo.toml +++ b/lightning/Cargo.toml @@ -21,6 +21,7 @@ max_level_error = [] max_level_warn = [] max_level_info = [] max_level_debug = [] +max_level_trace = [] # Allow signing of local transactions that may have been revoked or will be revoked, for functional testing (e.g. justice tx handling). # This is unsafe to use in production because it may result in the counterparty publishing taking our funds. unsafe_revoked_tx_signing = [] diff --git a/lightning/src/ln/peer_handler.rs b/lightning/src/ln/peer_handler.rs index f5d106333..89f3e9ff5 100644 --- a/lightning/src/ln/peer_handler.rs +++ b/lightning/src/ln/peer_handler.rs @@ -24,6 +24,7 @@ use ln::channelmanager::{SimpleArcChannelManager, SimpleRefChannelManager}; use util::ser::{VecWriter, Writeable, Writer}; use ln::peer_channel_encryptor::{PeerChannelEncryptor,NextNoiseStep}; use ln::wire; +use ln::wire::Encode; use util::atomic_counter::AtomicCounter; use util::events::{MessageSendEvent, MessageSendEventsProvider}; use util::logger::Logger; @@ -757,7 +758,12 @@ impl P fn enqueue_message(&self, peer: &mut Peer, message: &M) { let mut buffer = VecWriter(Vec::with_capacity(2048)); wire::write(message, &mut buffer).unwrap(); // crash if the write failed - log_trace!(self.logger, "Enqueueing message {:?} to {}", message, log_pubkey!(peer.their_node_id.unwrap())); + + if is_gossip_msg(message.type_id()) { + log_gossip!(self.logger, "Enqueueing message {:?} to {}", message, log_pubkey!(peer.their_node_id.unwrap())); + } else { + log_trace!(self.logger, "Enqueueing message {:?} to {}", message, log_pubkey!(peer.their_node_id.unwrap())) + } self.enqueue_encoded_message(peer, &buffer.0); } @@ -892,7 +898,7 @@ impl P match e { msgs::DecodeError::UnknownVersion => return Err(PeerHandleError { no_connection_possible: false }), msgs::DecodeError::UnknownRequiredFeature => { - log_trace!(self.logger, "Got a channel/node announcement with an known required feature flag, you may want to update!"); + log_gossip!(self.logger, "Got a channel/node announcement with an unknown required feature flag, you may want to update!"); continue; } msgs::DecodeError::InvalidValue => { @@ -906,7 +912,7 @@ impl P msgs::DecodeError::BadLengthDescriptor => return Err(PeerHandleError { no_connection_possible: false }), msgs::DecodeError::Io(_) => return Err(PeerHandleError { no_connection_possible: false }), msgs::DecodeError::UnsupportedCompression => { - log_trace!(self.logger, "We don't support zlib-compressed message fields, ignoring message"); + log_gossip!(self.logger, "We don't support zlib-compressed message fields, ignoring message"); continue; } } @@ -953,7 +959,12 @@ impl P peer: &mut Peer, message: wire::Message<<::Target as wire::CustomMessageReader>::CustomMessage> ) -> Result::Target as wire::CustomMessageReader>::CustomMessage>>, MessageHandlingError> { - log_trace!(self.logger, "Received message {:?} from {}", message, log_pubkey!(peer.their_node_id.unwrap())); + if is_gossip_msg(message.type_id()) { + log_gossip!(self.logger, "Received message {:?} from {}", message, log_pubkey!(peer.their_node_id.unwrap())); + } else { + log_trace!(self.logger, "Received message {:?} from {}", message, log_pubkey!(peer.their_node_id.unwrap())); + } + peer.received_message_since_timer_tick = true; // Need an Init as first message @@ -1132,7 +1143,7 @@ impl P fn forward_broadcast_msg(&self, peers: &mut PeerHolder, msg: &wire::Message<<::Target as wire::CustomMessageReader>::CustomMessage>, except_node: Option<&PublicKey>) { match msg { wire::Message::ChannelAnnouncement(ref msg) => { - log_trace!(self.logger, "Sending message to all peers except {:?} or the announced channel's counterparties: {:?}", except_node, msg); + log_gossip!(self.logger, "Sending message to all peers except {:?} or the announced channel's counterparties: {:?}", except_node, msg); let encoded_msg = encode_msg!(msg); for (_, peer) in peers.peers.iter_mut() { @@ -1143,7 +1154,7 @@ impl P if peer.pending_outbound_buffer.len() > OUTBOUND_BUFFER_LIMIT_DROP_GOSSIP || peer.msgs_sent_since_pong > BUFFER_DRAIN_MSGS_PER_TICK * FORWARD_INIT_SYNC_BUFFER_LIMIT_RATIO { - log_trace!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id); + log_gossip!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id); continue; } if peer.their_node_id.as_ref() == Some(&msg.contents.node_id_1) || @@ -1157,7 +1168,7 @@ impl P } }, wire::Message::NodeAnnouncement(ref msg) => { - log_trace!(self.logger, "Sending message to all peers except {:?} or the announced node: {:?}", except_node, msg); + log_gossip!(self.logger, "Sending message to all peers except {:?} or the announced node: {:?}", except_node, msg); let encoded_msg = encode_msg!(msg); for (_, peer) in peers.peers.iter_mut() { @@ -1168,7 +1179,7 @@ impl P if peer.pending_outbound_buffer.len() > OUTBOUND_BUFFER_LIMIT_DROP_GOSSIP || peer.msgs_sent_since_pong > BUFFER_DRAIN_MSGS_PER_TICK * FORWARD_INIT_SYNC_BUFFER_LIMIT_RATIO { - log_trace!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id); + log_gossip!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id); continue; } if peer.their_node_id.as_ref() == Some(&msg.contents.node_id) { @@ -1181,7 +1192,7 @@ impl P } }, wire::Message::ChannelUpdate(ref msg) => { - log_trace!(self.logger, "Sending message to all peers except {:?}: {:?}", except_node, msg); + log_gossip!(self.logger, "Sending message to all peers except {:?}: {:?}", except_node, msg); let encoded_msg = encode_msg!(msg); for (_, peer) in peers.peers.iter_mut() { @@ -1192,7 +1203,7 @@ impl P if peer.pending_outbound_buffer.len() > OUTBOUND_BUFFER_LIMIT_DROP_GOSSIP || peer.msgs_sent_since_pong > BUFFER_DRAIN_MSGS_PER_TICK * FORWARD_INIT_SYNC_BUFFER_LIMIT_RATIO { - log_trace!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id); + log_gossip!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id); continue; } if except_node.is_some() && peer.their_node_id.as_ref() == except_node { @@ -1377,7 +1388,7 @@ impl P // room in the send buffer, put the error message there... self.do_attempt_write_data(&mut descriptor, &mut peer); } else { - log_trace!(self.logger, "Handling DisconnectPeer HandleError event in peer_handler for node {} with no message", log_pubkey!(node_id)); + log_gossip!(self.logger, "Handling DisconnectPeer HandleError event in peer_handler for node {} with no message", log_pubkey!(node_id)); } } descriptor.disconnect_socket(); @@ -1405,7 +1416,7 @@ impl P self.enqueue_message(get_peer_for_forwarding!(node_id), msg); } MessageSendEvent::SendReplyChannelRange { ref node_id, ref msg } => { - log_trace!(self.logger, "Handling SendReplyChannelRange event in peer_handler for node {} with num_scids={} first_blocknum={} number_of_blocks={}, sync_complete={}", + log_gossip!(self.logger, "Handling SendReplyChannelRange event in peer_handler for node {} with num_scids={} first_blocknum={} number_of_blocks={}, sync_complete={}", log_pubkey!(node_id), msg.short_channel_ids.len(), msg.first_blocknum, @@ -1588,6 +1599,15 @@ impl P } } +fn is_gossip_msg(type_id: u16) -> bool { + match type_id { + msgs::ChannelAnnouncement::TYPE | + msgs::ChannelUpdate::TYPE | + msgs::NodeAnnouncement::TYPE => true, + _ => false + } +} + #[cfg(test)] mod tests { use ln::peer_handler::{PeerManager, MessageHandler, SocketDescriptor, IgnoringMessageHandler}; diff --git a/lightning/src/routing/network_graph.rs b/lightning/src/routing/network_graph.rs index 851e01b50..4d33bbdee 100644 --- a/lightning/src/routing/network_graph.rs +++ b/lightning/src/routing/network_graph.rs @@ -299,7 +299,7 @@ where C::Target: chain::Access, L::Target: Logger fn handle_channel_announcement(&self, msg: &msgs::ChannelAnnouncement) -> Result { self.network_graph.update_channel_from_announcement(msg, &self.chain_access, &self.secp_ctx)?; - log_trace!(self.logger, "Added channel_announcement for {}{}", msg.contents.short_channel_id, if !msg.contents.excess_data.is_empty() { " with excess uninterpreted data!" } else { "" }); + log_gossip!(self.logger, "Added channel_announcement for {}{}", msg.contents.short_channel_id, if !msg.contents.excess_data.is_empty() { " with excess uninterpreted data!" } else { "" }); Ok(msg.contents.excess_data.len() <= MAX_EXCESS_BYTES_FOR_RELAY) } @@ -848,7 +848,7 @@ impl NetworkGraph { Some(node) => { if let Some(node_info) = node.announcement_info.as_ref() { if node_info.last_update >= msg.timestamp { - return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)}); + return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)}); } } @@ -977,7 +977,7 @@ impl NetworkGraph { Self::remove_channel_in_nodes(&mut nodes, &entry.get(), msg.short_channel_id); *entry.get_mut() = chan_info; } else { - return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)}) + return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)}) } }, BtreeEntry::Vacant(entry) => { @@ -1083,7 +1083,7 @@ impl NetworkGraph { ( $target: expr, $src_node: expr) => { if let Some(existing_chan_info) = $target.as_ref() { if existing_chan_info.last_update >= msg.timestamp { - return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)}); + return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)}); } chan_was_enabled = existing_chan_info.enabled; } else { diff --git a/lightning/src/util/logger.rs b/lightning/src/util/logger.rs index 2717effb2..103f89891 100644 --- a/lightning/src/util/logger.rs +++ b/lightning/src/util/logger.rs @@ -17,11 +17,13 @@ use core::cmp; use core::fmt; -static LOG_LEVEL_NAMES: [&'static str; 5] = ["TRACE", "DEBUG", "INFO", "WARN", "ERROR"]; +static LOG_LEVEL_NAMES: [&'static str; 6] = ["GOSSIP", "TRACE", "DEBUG", "INFO", "WARN", "ERROR"]; /// An enum representing the available verbosity levels of the logger. #[derive(Copy, Clone, PartialEq, Eq, Debug, Hash)] pub enum Level { + /// Designates extremely verbose information, including gossip-induced messages + Gossip, /// Designates very low priority, often extremely verbose, information Trace, /// Designates lower priority information @@ -78,7 +80,7 @@ impl Level { /// Returns the most verbose logging level. #[inline] pub fn max() -> Level { - Level::Trace + Level::Gossip } } @@ -163,13 +165,14 @@ mod tests { log_info!(self.logger, "This is an info"); log_debug!(self.logger, "This is a debug"); log_trace!(self.logger, "This is a trace"); + log_gossip!(self.logger, "This is a gossip"); } } #[test] fn test_logging_macros() { let mut logger = TestLogger::new(); - logger.enable(Level::Trace); + logger.enable(Level::Gossip); let logger : Arc = Arc::new(logger); let wrapper = WrapperLog::new(Arc::clone(&logger)); wrapper.call_macros(); @@ -189,7 +192,10 @@ mod tests { assert!(Level::Debug > Level::Trace); assert!(Level::Debug >= Level::Trace); assert!(Level::Debug >= Level::Debug); + assert!(Level::Trace > Level::Gossip); + assert!(Level::Trace >= Level::Gossip); assert!(Level::Trace >= Level::Trace); + assert!(Level::Gossip >= Level::Gossip); assert!(Level::Error <= Level::Error); assert!(Level::Warn < Level::Error); @@ -204,5 +210,8 @@ mod tests { assert!(Level::Trace < Level::Debug); assert!(Level::Trace <= Level::Debug); assert!(Level::Trace <= Level::Trace); + assert!(Level::Gossip < Level::Trace); + assert!(Level::Gossip <= Level::Trace); + assert!(Level::Gossip <= Level::Gossip); } } diff --git a/lightning/src/util/macro_logger.rs b/lightning/src/util/macro_logger.rs index 747752613..0210229de 100644 --- a/lightning/src/util/macro_logger.rs +++ b/lightning/src/util/macro_logger.rs @@ -174,6 +174,8 @@ macro_rules! log_given_level { $crate::util::logger::Level::Debug => log_internal!($logger, $lvl, $($arg)*), #[cfg(not(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn", feature = "max_level_info", feature = "max_level_debug")))] $crate::util::logger::Level::Trace => log_internal!($logger, $lvl, $($arg)*), + #[cfg(not(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn", feature = "max_level_info", feature = "max_level_debug", feature = "max_level_trace")))] + $crate::util::logger::Level::Gossip => log_internal!($logger, $lvl, $($arg)*), #[cfg(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn", feature = "max_level_info", feature = "max_level_debug"))] _ => { @@ -216,3 +218,10 @@ macro_rules! log_trace { log_given_level!($logger, $crate::util::logger::Level::Trace, $($arg)*) ) } + +/// Log a gossip log. +macro_rules! log_gossip { + ($logger: expr, $($arg:tt)*) => ( + log_given_level!($logger, $crate::util::logger::Level::Gossip, $($arg)*); + ) +} -- 2.39.5