Add a new log-level for gossip messages.

Author: Elias Rohrer

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

lightning/src/chain/channelmonitor.rs

@@ -2355,7 +2355,8 @@ impl<Signer: Sign> ChannelMonitorImpl<Signer> {
 				let prevout = &tx.input[0].previous_output;
 				if prevout.txid == self.funding_info.0.txid && prevout.vout == self.funding_info.0.index as u32 {
 					let mut balance_spendable_csv = None;
-					log_info!(logger, "Channel closed by funding output spend in txid {}.", log_bytes!(tx.txid()));
+					log_info!(logger, "Channel {} closed by funding output spend in txid {}.",
+						log_bytes!(self.funding_info.0.to_channel_id()), tx.txid());
 					if (tx.input[0].sequence >> 8*3) as u8 == 0x80 && (tx.lock_time >> 8*3) as u8 == 0x20 {
 						let (mut new_outpoints, new_outputs) = self.check_spend_counterparty_transaction(&tx, height, &logger);
 						if !new_outputs.1.is_empty() {

lightning/src/chain/onchaintx.rs

@@ -388,7 +388,8 @@ impl<ChannelSigner: Sign> OnchainTxHandler<ChannelSigner> {
 		let new_timer = Some(cached_request.get_height_timer(cur_height));
 		if cached_request.is_malleable() {
 			let predicted_weight = cached_request.package_weight(&self.destination_script);
-			if let Some((output_value, new_feerate)) = cached_request.compute_package_output(predicted_weight, fee_estimator, logger) {
+			if let Some((output_value, new_feerate)) =
+					cached_request.compute_package_output(predicted_weight, self.destination_script.dust_value().as_sat(), fee_estimator, logger) {
 				assert!(new_feerate != 0);
 
 				let transaction = cached_request.finalize_package(self, output_value, self.destination_script.clone(), logger).unwrap();

lightning/src/chain/package.rs

@@ -636,26 +636,25 @@ impl PackageTemplate {
 		}
 		current_height + LOW_FREQUENCY_BUMP_INTERVAL
 	}
-	/// Returns value in satoshis to be included as package outgoing output amount and feerate with which package finalization should be done.
-	pub(crate) fn compute_package_output<F: Deref, L: Deref>(&self, predicted_weight: usize, fee_estimator: &F, logger: &L) -> Option<(u64, u64)>
+
+	/// Returns value in satoshis to be included as package outgoing output amount and feerate
+	/// which was used to generate the value. Will not return less than `dust_limit_sats` for the
+	/// value.
+	pub(crate) fn compute_package_output<F: Deref, L: Deref>(&self, predicted_weight: usize, dust_limit_sats: u64, fee_estimator: &F, logger: &L) -> Option<(u64, u64)>
 		where F::Target: FeeEstimator,
 		      L::Target: Logger,
 	{
 		debug_assert!(self.malleability == PackageMalleability::Malleable, "The package output is fixed for non-malleable packages");
 		let input_amounts = self.package_amount();
+		assert!(dust_limit_sats as i64 > 0, "Output script must be broadcastable/have a 'real' dust limit.");
 		// If old feerate is 0, first iteration of this claim, use normal fee calculation
 		if self.feerate_previous != 0 {
 			if let Some((new_fee, feerate)) = feerate_bump(predicted_weight, input_amounts, self.feerate_previous, fee_estimator, logger) {
-				// If new computed fee is superior at the whole claimable amount burn all in fees
-				if new_fee > input_amounts {
-					return Some((0, feerate));
-				} else {
-					return Some((input_amounts - new_fee, feerate));
-				}
+				return Some((cmp::max(input_amounts as i64 - new_fee as i64, dust_limit_sats as i64) as u64, feerate));
 			}
 		} else {
 			if let Some((new_fee, feerate)) = compute_fee_from_spent_amounts(input_amounts, predicted_weight, fee_estimator, logger) {
-				return Some((input_amounts - new_fee, feerate));
+				return Some((cmp::max(input_amounts as i64 - new_fee as i64, dust_limit_sats as i64) as u64, feerate));
 			}
 		}
 		None

lightning/src/ln/channelmanager.rs

@@ -5874,6 +5874,7 @@ impl<'a, Signer: Sign, M: Deref, T: Deref, K: Deref, F: Deref, L: Deref>
 						reason: ClosureReason::OutdatedChannelManager
 					});
 				} else {
+					log_info!(args.logger, "Successfully loaded channel {}", log_bytes!(channel.channel_id()));
 					if let Some(short_channel_id) = channel.get_short_channel_id() {
 						short_to_id.insert(short_channel_id, channel.channel_id());
 					}
@@ -5891,6 +5892,7 @@ impl<'a, Signer: Sign, M: Deref, T: Deref, K: Deref, F: Deref, L: Deref>
 
 		for (ref funding_txo, ref mut monitor) in args.channel_monitors.iter_mut() {
 			if !funding_txo_set.contains(funding_txo) {
+				log_info!(args.logger, "Broadcasting latest holder commitment transaction for closed channel {}", log_bytes!(funding_txo.to_channel_id()));
 				monitor.broadcast_latest_holder_commitment_txn(&args.tx_broadcaster, &args.logger);
 			}
 		}

lightning/src/ln/functional_test_utils.rs

@@ -707,6 +707,14 @@ pub fn update_nodes_with_chan_announce<'a, 'b, 'c, 'd>(nodes: &'a Vec<Node<'b, '
 macro_rules! check_spends {
 	($tx: expr, $($spends_txn: expr),*) => {
 		{
+			$(
+			for outp in $spends_txn.output.iter() {
+				assert!(outp.value >= outp.script_pubkey.dust_value().as_sat(), "Input tx output didn't meet dust limit");
+			}
+			)*
+			for outp in $tx.output.iter() {
+				assert!(outp.value >= outp.script_pubkey.dust_value().as_sat(), "Spending tx output didn't meet dust limit");
+			}
 			let get_output = |out_point: &bitcoin::blockdata::transaction::OutPoint| {
 				$(
 					if out_point.txid == $spends_txn.txid() {

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 |
+			_ => false
+		}
+}
+
 #[cfg(test)]
 mod tests {
 	use ln::peer_handler::{PeerManager, MessageHandler, SocketDescriptor, IgnoringMessageHandler};

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 {

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

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