mirrors/rust-lightning
1
0
Fork 0
mirror of https://github.com/lightningdevkit/rust-lightning.git synced 2025-02-24 23:08:36 +01:00
Code Issues Projects Releases Packages Wiki Activity

Add a new log-level for gossip messages.

Browse source
This commit is contained in:
Elias Rohrer 2021-11-22 18:19:08 +01:00
parent 1f170dba02
commit 3b4b74bc66
5 changed files with 58 additions and 19 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
lightning/Cargo.toml
View file

@ -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 = []

44
lightning/src/ln/peer_handler.rs
View file

@ -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};

8
lightning/src/routing/network_graph.rs
View file

@ -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 {

15
lightning/src/util/logger.rs
View file

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

9
lightning/src/util/macro_logger.rs
View file

@ -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)*);
)
}