Skip to content

Commit 3cb3d18

Browse files
TheBlueMattTheBlueMatt
authored
Merge pull request #1145 from tnull/add_gossip_log_level
Introduce GOSSIP log level to PeerHandler
2 parents 58539b8 + 3b4b74b commit 3cb3d18

File tree

5 files changed

+58
-19
lines changed

5 files changed

+58
-19
lines changed

‎lightning/Cargo.toml‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@ max_level_error = []
2121
max_level_warn = []
2222
max_level_info = []
2323
max_level_debug = []
24+
max_level_trace = []
2425
# Allow signing of local transactions that may have been revoked or will be revoked, for functional testing (e.g. justice tx handling).
2526
# This is unsafe to use in production because it may result in the counterparty publishing taking our funds.
2627
unsafe_revoked_tx_signing = []

‎lightning/src/ln/peer_handler.rs‎

Lines changed: 32 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ use ln::channelmanager::{SimpleArcChannelManager, SimpleRefChannelManager};
2424
use util::ser::{VecWriter, Writeable, Writer};
2525
use ln::peer_channel_encryptor::{PeerChannelEncryptor,NextNoiseStep};
2626
use ln::wire;
27+
use ln::wire::Encode;
2728
use util::atomic_counter::AtomicCounter;
2829
use util::events::{MessageSendEvent, MessageSendEventsProvider};
2930
use util::logger::Logger;
@@ -757,7 +758,12 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
757758
fn enqueue_message<M: wire::Type>(&self, peer: &mut Peer, message: &M) {
758759
let mut buffer = VecWriter(Vec::with_capacity(2048));
759760
wire::write(message, &mut buffer).unwrap(); // crash if the write failed
760-
log_trace!(self.logger, "Enqueueing message {:?} to {}", message, log_pubkey!(peer.their_node_id.unwrap()));
761+
762+
if is_gossip_msg(message.type_id()) {
763+
log_gossip!(self.logger, "Enqueueing message {:?} to {}", message, log_pubkey!(peer.their_node_id.unwrap()));
764+
} else {
765+
log_trace!(self.logger, "Enqueueing message {:?} to {}", message, log_pubkey!(peer.their_node_id.unwrap()))
766+
}
761767
self.enqueue_encoded_message(peer, &buffer.0);
762768
}
763769

@@ -892,7 +898,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
892898
match e {
893899
msgs::DecodeError::UnknownVersion => return Err(PeerHandleError { no_connection_possible: false }),
894900
msgs::DecodeError::UnknownRequiredFeature => {
895-
log_trace!(self.logger, "Got a channel/node announcement with an known required feature flag, you may want to update!");
901+
log_gossip!(self.logger, "Got a channel/node announcement with an unknown required feature flag, you may want to update!");
896902
continue;
897903
}
898904
msgs::DecodeError::InvalidValue => {
@@ -906,7 +912,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
906912
msgs::DecodeError::BadLengthDescriptor => return Err(PeerHandleError { no_connection_possible: false }),
907913
msgs::DecodeError::Io(_) => return Err(PeerHandleError { no_connection_possible: false }),
908914
msgs::DecodeError::UnsupportedCompression => {
909-
log_trace!(self.logger, "We don't support zlib-compressed message fields, ignoring message");
915+
log_gossip!(self.logger, "We don't support zlib-compressed message fields, ignoring message");
910916
continue;
911917
}
912918
}
@@ -953,7 +959,12 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
953959
peer: &mut Peer,
954960
message: wire::Message<<<CMH as core::ops::Deref>::Target as wire::CustomMessageReader>::CustomMessage>
955961
) -> Result<Option<wire::Message<<<CMH as core::ops::Deref>::Target as wire::CustomMessageReader>::CustomMessage>>, MessageHandlingError> {
956-
log_trace!(self.logger, "Received message {:?} from {}", message, log_pubkey!(peer.their_node_id.unwrap()));
962+
if is_gossip_msg(message.type_id()) {
963+
log_gossip!(self.logger, "Received message {:?} from {}", message, log_pubkey!(peer.their_node_id.unwrap()));
964+
} else {
965+
log_trace!(self.logger, "Received message {:?} from {}", message, log_pubkey!(peer.their_node_id.unwrap()));
966+
}
967+
957968
peer.received_message_since_timer_tick = true;
958969

959970
// Need an Init as first message
@@ -1132,7 +1143,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
11321143
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>) {
11331144
match msg {
11341145
wire::Message::ChannelAnnouncement(ref msg) => {
1135-
log_trace!(self.logger, "Sending message to all peers except {:?} or the announced channel's counterparties: {:?}", except_node, msg);
1146+
log_gossip!(self.logger, "Sending message to all peers except {:?} or the announced channel's counterparties: {:?}", except_node, msg);
11361147
let encoded_msg = encode_msg!(msg);
11371148

11381149
for (_, peer) in peers.peers.iter_mut() {
@@ -1143,7 +1154,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
11431154
if peer.pending_outbound_buffer.len() > OUTBOUND_BUFFER_LIMIT_DROP_GOSSIP
11441155
|| peer.msgs_sent_since_pong > BUFFER_DRAIN_MSGS_PER_TICK * FORWARD_INIT_SYNC_BUFFER_LIMIT_RATIO
11451156
{
1146-
log_trace!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
1157+
log_gossip!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
11471158
continue;
11481159
}
11491160
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
11571168
}
11581169
},
11591170
wire::Message::NodeAnnouncement(ref msg) => {
1160-
log_trace!(self.logger, "Sending message to all peers except {:?} or the announced node: {:?}", except_node, msg);
1171+
log_gossip!(self.logger, "Sending message to all peers except {:?} or the announced node: {:?}", except_node, msg);
11611172
let encoded_msg = encode_msg!(msg);
11621173

11631174
for (_, peer) in peers.peers.iter_mut() {
@@ -1168,7 +1179,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
11681179
if peer.pending_outbound_buffer.len() > OUTBOUND_BUFFER_LIMIT_DROP_GOSSIP
11691180
|| peer.msgs_sent_since_pong > BUFFER_DRAIN_MSGS_PER_TICK * FORWARD_INIT_SYNC_BUFFER_LIMIT_RATIO
11701181
{
1171-
log_trace!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
1182+
log_gossip!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
11721183
continue;
11731184
}
11741185
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
11811192
}
11821193
},
11831194
wire::Message::ChannelUpdate(ref msg) => {
1184-
log_trace!(self.logger, "Sending message to all peers except {:?}: {:?}", except_node, msg);
1195+
log_gossip!(self.logger, "Sending message to all peers except {:?}: {:?}", except_node, msg);
11851196
let encoded_msg = encode_msg!(msg);
11861197

11871198
for (_, peer) in peers.peers.iter_mut() {
@@ -1192,7 +1203,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
11921203
if peer.pending_outbound_buffer.len() > OUTBOUND_BUFFER_LIMIT_DROP_GOSSIP
11931204
|| peer.msgs_sent_since_pong > BUFFER_DRAIN_MSGS_PER_TICK * FORWARD_INIT_SYNC_BUFFER_LIMIT_RATIO
11941205
{
1195-
log_trace!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
1206+
log_gossip!(self.logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
11961207
continue;
11971208
}
11981209
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
13771388
// room in the send buffer, put the error message there...
13781389
self.do_attempt_write_data(&mut descriptor, &mut peer);
13791390
} else {
1380-
log_trace!(self.logger, "Handling DisconnectPeer HandleError event in peer_handler for node {} with no message", log_pubkey!(node_id));
1391+
log_gossip!(self.logger, "Handling DisconnectPeer HandleError event in peer_handler for node {} with no message", log_pubkey!(node_id));
13811392
}
13821393
}
13831394
descriptor.disconnect_socket();
@@ -1405,7 +1416,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
14051416
self.enqueue_message(get_peer_for_forwarding!(node_id), msg);
14061417
}
14071418
MessageSendEvent::SendReplyChannelRange { ref node_id, ref msg } => {
1408-
log_trace!(self.logger, "Handling SendReplyChannelRange event in peer_handler for node {} with num_scids={} first_blocknum={} number_of_blocks={}, sync_complete={}",
1419+
log_gossip!(self.logger, "Handling SendReplyChannelRange event in peer_handler for node {} with num_scids={} first_blocknum={} number_of_blocks={}, sync_complete={}",
14091420
log_pubkey!(node_id),
14101421
msg.short_channel_ids.len(),
14111422
msg.first_blocknum,
@@ -1588,6 +1599,15 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
15881599
}
15891600
}
15901601

1602+
fn is_gossip_msg(type_id: u16) -> bool {
1603+
match type_id {
1604+
msgs::ChannelAnnouncement::TYPE |
1605+
msgs::ChannelUpdate::TYPE |
1606+
msgs::NodeAnnouncement::TYPE => true,
1607+
_ => false
1608+
}
1609+
}
1610+
15911611
#[cfg(test)]
15921612
mod tests {
15931613
use ln::peer_handler::{PeerManager, MessageHandler, SocketDescriptor, IgnoringMessageHandler};

‎lightning/src/routing/network_graph.rs‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -299,7 +299,7 @@ where C::Target: chain::Access, L::Target: Logger
299299

300300
fn handle_channel_announcement(&self, msg: &msgs::ChannelAnnouncement) -> Result<bool, LightningError> {
301301
self.network_graph.update_channel_from_announcement(msg, &self.chain_access, &self.secp_ctx)?;
302-
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 { "" });
302+
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 { "" });
303303
Ok(msg.contents.excess_data.len() <= MAX_EXCESS_BYTES_FOR_RELAY)
304304
}
305305

@@ -848,7 +848,7 @@ impl NetworkGraph {
848848
Some(node) => {
849849
if let Some(node_info) = node.announcement_info.as_ref() {
850850
if node_info.last_update >= msg.timestamp {
851-
return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)});
851+
return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)});
852852
}
853853
}
854854

@@ -977,7 +977,7 @@ impl NetworkGraph {
977977
Self::remove_channel_in_nodes(&mut nodes, &entry.get(), msg.short_channel_id);
978978
*entry.get_mut() = chan_info;
979979
} else {
980-
return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)})
980+
return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)})
981981
}
982982
},
983983
BtreeEntry::Vacant(entry) => {
@@ -1083,7 +1083,7 @@ impl NetworkGraph {
10831083
( $target: expr, $src_node: expr) => {
10841084
if let Some(existing_chan_info) = $target.as_ref() {
10851085
if existing_chan_info.last_update >= msg.timestamp {
1086-
return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)});
1086+
return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)});
10871087
}
10881088
chan_was_enabled = existing_chan_info.enabled;
10891089
} else {

‎lightning/src/util/logger.rs‎

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -17,11 +17,13 @@
1717
use core::cmp;
1818
use core::fmt;
1919

20-
static LOG_LEVEL_NAMES: [&'static str; 5] = ["TRACE", "DEBUG", "INFO", "WARN", "ERROR"];
20+
static LOG_LEVEL_NAMES: [&'static str; 6] = ["GOSSIP", "TRACE", "DEBUG", "INFO", "WARN", "ERROR"];
2121

2222
/// An enum representing the available verbosity levels of the logger.
2323
#[derive(Copy, Clone, PartialEq, Eq, Debug, Hash)]
2424
pub enum Level {
25+
/// Designates extremely verbose information, including gossip-induced messages
26+
Gossip,
2527
/// Designates very low priority, often extremely verbose, information
2628
Trace,
2729
/// Designates lower priority information
@@ -78,7 +80,7 @@ impl Level {
7880
/// Returns the most verbose logging level.
7981
#[inline]
8082
pub fn max() -> Level {
81-
Level::Trace
83+
Level::Gossip
8284
}
8385
}
8486

@@ -163,13 +165,14 @@ mod tests {
163165
log_info!(self.logger, "This is an info");
164166
log_debug!(self.logger, "This is a debug");
165167
log_trace!(self.logger, "This is a trace");
168+
log_gossip!(self.logger, "This is a gossip");
166169
}
167170
}
168171

169172
#[test]
170173
fn test_logging_macros() {
171174
let mut logger = TestLogger::new();
172-
logger.enable(Level::Trace);
175+
logger.enable(Level::Gossip);
173176
let logger : Arc<Logger> = Arc::new(logger);
174177
let wrapper = WrapperLog::new(Arc::clone(&logger));
175178
wrapper.call_macros();
@@ -189,7 +192,10 @@ mod tests {
189192
assert!(Level::Debug > Level::Trace);
190193
assert!(Level::Debug >= Level::Trace);
191194
assert!(Level::Debug >= Level::Debug);
195+
assert!(Level::Trace > Level::Gossip);
196+
assert!(Level::Trace >= Level::Gossip);
192197
assert!(Level::Trace >= Level::Trace);
198+
assert!(Level::Gossip >= Level::Gossip);
193199

194200
assert!(Level::Error <= Level::Error);
195201
assert!(Level::Warn < Level::Error);
@@ -204,5 +210,8 @@ mod tests {
204210
assert!(Level::Trace < Level::Debug);
205211
assert!(Level::Trace <= Level::Debug);
206212
assert!(Level::Trace <= Level::Trace);
213+
assert!(Level::Gossip < Level::Trace);
214+
assert!(Level::Gossip <= Level::Trace);
215+
assert!(Level::Gossip <= Level::Gossip);
207216
}
208217
}

‎lightning/src/util/macro_logger.rs‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -174,6 +174,8 @@ macro_rules! log_given_level {
174174
$crate::util::logger::Level::Debug => log_internal!($logger, $lvl, $($arg)*),
175175
#[cfg(not(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn", feature = "max_level_info", feature = "max_level_debug")))]
176176
$crate::util::logger::Level::Trace => log_internal!($logger, $lvl, $($arg)*),
177+
#[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")))]
178+
$crate::util::logger::Level::Gossip => log_internal!($logger, $lvl, $($arg)*),
177179

178180
#[cfg(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn", feature = "max_level_info", feature = "max_level_debug"))]
179181
_ => {
@@ -216,3 +218,10 @@ macro_rules! log_trace {
216218
log_given_level!($logger, $crate::util::logger::Level::Trace, $($arg)*)
217219
)
218220
}
221+
222+
/// Log a gossip log.
223+
macro_rules! log_gossip {
224+
($logger: expr, $($arg:tt)*) => (
225+
log_given_level!($logger, $crate::util::logger::Level::Gossip, $($arg)*);
226+
)
227+
}

0 commit comments

Comments
 (0)