Add a new log-level for gossip messages.

diff --git a/lightning/Cargo.toml b/lightning/Cargo.toml
index 8202219bf23c9f8a2bb45b467b0f3b5ea4b73f9b..61ac0125fd29e1d7903d1a1dd687593ec6aa859e 100644 (file)
--- 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 f5d106333ba1da96c553f3018bd2f7e994cec7b8..89f3e9ff5ffa48233086af330cb0fdb6ccf58f15 100644 (file)
--- 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
        fn enqueue_message<M: wire::Type>(&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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
                peer: &mut Peer,
                message: wire::Message<<<CMH as core::ops::Deref>::Target as wire::CustomMessageReader>::CustomMessage>
        ) -> Result<Option<wire::Message<<<CMH as core::ops::Deref>::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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
        fn forward_broadcast_msg(&self, peers: &mut PeerHolder<Descriptor>, msg: &wire::Message<<<CMH as core::ops::Deref>::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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> 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 851e01b5088e6988eae597982c91fa4c865b3172..4d33bbdee9278717525c9991805245280bc22137 100644 (file)
--- 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<bool, LightningError> {
                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 2717effb209d94750b1965a28c64a856647f3d80..103f89891cf30115c238f0a9494379c8e6719169 100644 (file)
--- 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<Logger> = 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 7477526133e7b99394e699e7193dda3c7a21bbba..0210229de3a6db5fb33e9f96ffa845b4c6aa3a40 100644 (file)
--- 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)*);
+       )
+}