Skip to content

Introduce GOSSIP log level to PeerHandler #1145

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
TheBlueMatt merged 1 commit into from
Nov 22, 2021
Merged

Introduce GOSSIP log level to PeerHandler #1145

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions lightning/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 = []
Expand Down
44 changes: 32 additions & 12 deletions lightning/src/ln/peer_handler.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
}

Expand Down Expand Up @@ -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 => {
Expand All @@ -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;
}
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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() {
Expand All @@ -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) ||
Expand All @@ -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() {
Expand All @@ -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) {
Expand All @@ -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() {
Expand All @@ -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 {
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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};
Expand Down
8 changes: 4 additions & 4 deletions lightning/src/routing/network_graph.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}

Expand Down Expand Up @@ -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)});
}
}

Expand Down Expand Up @@ -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) => {
Expand Down Expand Up @@ -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 {
Expand Down
15 changes: 12 additions & 3 deletions lightning/src/util/logger.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -78,7 +80,7 @@ impl Level {
/// Returns the most verbose logging level.
#[inline]
pub fn max() -> Level {
Level::Trace
Level::Gossip
}
}

Expand Down Expand Up @@ -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();
Expand All @@ -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);
Expand All @@ -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);
}
}
9 changes: 9 additions & 0 deletions lightning/src/util/macro_logger.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"))]
_ => {
Expand Down Expand Up @@ -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)*);
)
}