Do not log_debug when we receive duplicate gossip messages

We very often receive duplicate gossip messages, which now causes us
to log at the DEBUG level, which is almost certainly not what a
user wants. Instead, we add a new form of ErrorAction which causes
us to only log at the TRACE level.

Author: TheBlueMatt

lightning/src/ln/msgs.rs

@@ -38,6 +38,7 @@ use core::fmt::Debug;
 use std::io::Read;
 
 use util::events::MessageSendEventsProvider;
+use util::logger;
 use util::ser::{Readable, Writeable, Writer, FixedLengthReader, HighZeroBytesDroppedVarInt};
 
 use ln::{PaymentPreimage, PaymentHash, PaymentSecret};
@@ -688,7 +689,11 @@ pub enum ErrorAction {
 		msg: Option<ErrorMessage>
 	},
 	/// The peer did something harmless that we weren't able to process, just log and ignore
+	// New code should *not* use this. New code must use IgnoreAndLog, below!
 	IgnoreError,
+	/// The peer did something harmless that we weren't able to meaningfully process.
+	/// If the error is logged, log it at the given level.
+	IgnoreAndLog(logger::Level),
 	/// The peer did something incorrect. Tell them.
 	SendErrorMessage {
 		/// The message to send.

lightning/src/ln/peer_handler.rs

@@ -27,7 +27,7 @@ use ln::wire;
 use ln::wire::Encode;
 use util::byte_utils;
 use util::events::{MessageSendEvent, MessageSendEventsProvider};
-use util::logger::Logger;
+use util::logger::{Logger, Level};
 use routing::network_graph::NetGraphMsgHandler;
 
 use prelude::*;
@@ -717,15 +717,19 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref> PeerManager<D
 											match e.action {
 												msgs::ErrorAction::DisconnectPeer { msg: _ } => {
 													//TODO: Try to push msg
-													log_debug!(self.logger, "Got Err handling message, disconnecting peer with: {}", e.err);
+													log_debug!(self.logger, "Error handling message; disconnecting peer with: {}", e.err);
 													return Err(PeerHandleError{ no_connection_possible: false });
 												},
+												msgs::ErrorAction::IgnoreAndLog(level) => {
+													log_given_level!(self.logger, level, "Error handling message; ignoring: {}", e.err);
+													continue
+												},
 												msgs::ErrorAction::IgnoreError => {
-													log_debug!(self.logger, "Got ignored error handling message: {}", e.err);
+													log_debug!(self.logger, "Error handling message; ignoring: {}", e.err);
 													continue;
 												},
 												msgs::ErrorAction::SendErrorMessage { msg } => {
-													log_debug!(self.logger, "Got Err handling message, sending Error message with: {}", e.err);
+													log_debug!(self.logger, "Error handling message; sending error message with: {}", e.err);
 													self.enqueue_message(peer, &msg);
 													continue;
 												},
@@ -1284,7 +1288,12 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref> PeerManager<D
 									self.message_handler.chan_handler.peer_disconnected(&node_id, false);
 								}
 							},
-							msgs::ErrorAction::IgnoreError => {},
+							msgs::ErrorAction::IgnoreAndLog(level) => {
+								log_given_level!(self.logger, level, "Received a HandleError event to be ignored for node {}", log_pubkey!(node_id));
+							},
+							msgs::ErrorAction::IgnoreError => {
+								log_debug!(self.logger, "Received a HandleError event to be ignored for node {}", log_pubkey!(node_id));
+							},
 							msgs::ErrorAction::SendErrorMessage { ref msg } => {
 								log_trace!(self.logger, "Handling SendErrorMessage HandleError event in peer_handler for node {} with message {}",
 										log_pubkey!(node_id),

lightning/src/routing/network_graph.rs

@@ -28,7 +28,7 @@ use ln::msgs::{ChannelAnnouncement, ChannelUpdate, NodeAnnouncement, OptionalFie
 use ln::msgs::{QueryChannelRange, ReplyChannelRange, QueryShortChannelIds, ReplyShortChannelIdsEnd};
 use ln::msgs;
 use util::ser::{Writeable, Readable, Writer};
-use util::logger::Logger;
+use util::logger::{Logger, Level};
 use util::events::{MessageSendEvent, MessageSendEventsProvider};
 use util::scid_utils::{block_from_scid, scid_from_parts, MAX_SCID_BLOCK};
 
@@ -717,7 +717,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::IgnoreError});
+						return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)});
 					}
 				}
 
@@ -838,7 +838,7 @@ impl NetworkGraph {
 					Self::remove_channel_in_nodes(&mut self.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::IgnoreError})
+					return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)})
 				}
 			},
 			BtreeEntry::Vacant(entry) => {
@@ -940,7 +940,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::IgnoreError});
+								return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)});
 							}
 							chan_was_enabled = existing_chan_info.enabled;
 						} else {