Merge pull request #1169 from TheBlueMatt/2021-11-fix-update-announcements

Fix announcements of our own gossip

Author: TheBlueMatt

lightning-background-processor/src/lib.rs

@@ -493,9 +493,10 @@ mod tests {
 
 		macro_rules! check_persisted_data {
 			($node: expr, $filepath: expr, $expected_bytes: expr) => {
-				match $node.write(&mut $expected_bytes) {
-					Ok(()) => {
-						loop {
+				loop {
+					$expected_bytes.clear();
+					match $node.write(&mut $expected_bytes) {
+						Ok(()) => {
 							match std::fs::read($filepath) {
 								Ok(bytes) => {
 									if bytes == $expected_bytes {
@@ -506,9 +507,9 @@ mod tests {
 								},
 								Err(_) => continue
 							}
-						}
-					},
-					Err(e) => panic!("Unexpected error: {}", e)
+						},
+						Err(e) => panic!("Unexpected error: {}", e)
+					}
 				}
 			}
 		}

lightning/src/ln/channel.rs

@@ -481,9 +481,14 @@ pub(super) struct Channel<Signer: Sign> {
 	holding_cell_update_fee: Option<u32>,
 	next_holder_htlc_id: u64,
 	next_counterparty_htlc_id: u64,
-	update_time_counter: u32,
 	feerate_per_kw: u32,
 
+	/// The timestamp set on our latest `channel_update` message for this channel. It is updated
+	/// when the channel is updated in ways which may impact the `channel_update` message or when a
+	/// new block is received, ensuring it's always at least moderately close to the current real
+	/// time.
+	update_time_counter: u32,
+
 	#[cfg(debug_assertions)]
 	/// Max to_local and to_remote outputs in a locally-generated commitment transaction
 	holder_max_commitment_tx_output: Mutex<(u64, u64)>,
@@ -4192,6 +4197,7 @@ impl<Signer: Sign> Channel<Signer> {
 	}
 
 	pub fn set_channel_update_status(&mut self, status: ChannelUpdateStatus) {
+		self.update_time_counter += 1;
 		self.channel_update_status = status;
 	}
 

lightning/src/ln/functional_tests.rs

@@ -7369,9 +7369,9 @@ fn test_announce_disable_channels() {
 	let node_chanmgrs = create_node_chanmgrs(2, &node_cfgs, &[None, None]);
 	let nodes = create_network(2, &node_cfgs, &node_chanmgrs);
 
-	let short_id_1 = create_announced_chan_between_nodes(&nodes, 0, 1, InitFeatures::known(), InitFeatures::known()).0.contents.short_channel_id;
-	let short_id_2 = create_announced_chan_between_nodes(&nodes, 1, 0, InitFeatures::known(), InitFeatures::known()).0.contents.short_channel_id;
-	let short_id_3 = create_announced_chan_between_nodes(&nodes, 0, 1, InitFeatures::known(), InitFeatures::known()).0.contents.short_channel_id;
+	create_announced_chan_between_nodes(&nodes, 0, 1, InitFeatures::known(), InitFeatures::known());
+	create_announced_chan_between_nodes(&nodes, 1, 0, InitFeatures::known(), InitFeatures::known());
+	create_announced_chan_between_nodes(&nodes, 0, 1, InitFeatures::known(), InitFeatures::known());
 
 	// Disconnect peers
 	nodes[0].node.peer_disconnected(&nodes[1].node.get_our_node_id(), false);
@@ -7381,13 +7381,13 @@ fn test_announce_disable_channels() {
 	nodes[0].node.timer_tick_occurred(); // DisabledStaged -> Disabled
 	let msg_events = nodes[0].node.get_and_clear_pending_msg_events();
 	assert_eq!(msg_events.len(), 3);
-	let mut chans_disabled: HashSet<u64> = [short_id_1, short_id_2, short_id_3].iter().map(|a| *a).collect();
+	let mut chans_disabled = HashMap::new();
 	for e in msg_events {
 		match e {
 			MessageSendEvent::BroadcastChannelUpdate { ref msg } => {
 				assert_eq!(msg.contents.flags & (1<<1), 1<<1); // The "channel disabled" bit should be set
 				// Check that each channel gets updated exactly once
-				if !chans_disabled.remove(&msg.contents.short_channel_id) {
+				if chans_disabled.insert(msg.contents.short_channel_id, msg.contents.timestamp).is_some() {
 					panic!("Generated ChannelUpdate for wrong chan!");
 				}
 			},
@@ -7423,19 +7423,22 @@ fn test_announce_disable_channels() {
 	nodes[0].node.timer_tick_occurred();
 	let msg_events = nodes[0].node.get_and_clear_pending_msg_events();
 	assert_eq!(msg_events.len(), 3);
-	chans_disabled = [short_id_1, short_id_2, short_id_3].iter().map(|a| *a).collect();
 	for e in msg_events {
 		match e {
 			MessageSendEvent::BroadcastChannelUpdate { ref msg } => {
 				assert_eq!(msg.contents.flags & (1<<1), 0); // The "channel disabled" bit should be off
-				// Check that each channel gets updated exactly once
-				if !chans_disabled.remove(&msg.contents.short_channel_id) {
-					panic!("Generated ChannelUpdate for wrong chan!");
+				match chans_disabled.remove(&msg.contents.short_channel_id) {
+					// Each update should have a higher timestamp than the previous one, replacing
+					// the old one.
+					Some(prev_timestamp) => assert!(msg.contents.timestamp > prev_timestamp),
+					None => panic!("Generated ChannelUpdate for wrong chan!"),
 				}
 			},
 			_ => panic!("Unexpected event"),
 		}
 	}
+	// Check that each channel gets updated exactly once
+	assert!(chans_disabled.is_empty());
 }
 
 #[test]

lightning/src/ln/msgs.rs

@@ -707,6 +707,10 @@ pub enum ErrorAction {
 	/// 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 provided us with a gossip message which we'd already seen. In most cases this
+	/// should be ignored, but it may result in the message being forwarded if it is a duplicate of
+	/// our own channel announcements.
+	IgnoreDuplicateGossip,
 	/// The peer did something incorrect. Tell them.
 	SendErrorMessage {
 		/// The message to send.

lightning/src/ln/peer_handler.rs

@@ -811,6 +811,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
 													log_given_level!(self.logger, level, "Error handling message{}; ignoring: {}", OptionalFromDebugger(&peer.their_node_id), e.err);
 													continue
 												},
+												msgs::ErrorAction::IgnoreDuplicateGossip => continue, // Don't even bother logging these
 												msgs::ErrorAction::IgnoreError => {
 													log_debug!(self.logger, "Error handling message{}; ignoring: {}", OptionalFromDebugger(&peer.their_node_id), e.err);
 													continue;
@@ -1351,21 +1352,31 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
 					},
 					MessageSendEvent::BroadcastChannelAnnouncement { msg, update_msg } => {
 						log_debug!(self.logger, "Handling BroadcastChannelAnnouncement event in peer_handler for short channel id {}", msg.contents.short_channel_id);
-						if self.message_handler.route_handler.handle_channel_announcement(&msg).is_ok() && self.message_handler.route_handler.handle_channel_update(&update_msg).is_ok() {
-							self.forward_broadcast_msg(peers, &wire::Message::ChannelAnnouncement(msg), None);
-							self.forward_broadcast_msg(peers, &wire::Message::ChannelUpdate(update_msg), None);
+						match self.message_handler.route_handler.handle_channel_announcement(&msg) {
+							Ok(_) | Err(LightningError { action: msgs::ErrorAction::IgnoreDuplicateGossip, .. }) =>
+								self.forward_broadcast_msg(peers, &wire::Message::ChannelAnnouncement(msg), None),
+							_ => {},
+						}
+						match self.message_handler.route_handler.handle_channel_update(&update_msg) {
+							Ok(_) | Err(LightningError { action: msgs::ErrorAction::IgnoreDuplicateGossip, .. }) =>
+								self.forward_broadcast_msg(peers, &wire::Message::ChannelUpdate(update_msg), None),
+							_ => {},
 						}
 					},
 					MessageSendEvent::BroadcastNodeAnnouncement { msg } => {
 						log_debug!(self.logger, "Handling BroadcastNodeAnnouncement event in peer_handler");
-						if self.message_handler.route_handler.handle_node_announcement(&msg).is_ok() {
-							self.forward_broadcast_msg(peers, &wire::Message::NodeAnnouncement(msg), None);
+						match self.message_handler.route_handler.handle_node_announcement(&msg) {
+							Ok(_) | Err(LightningError { action: msgs::ErrorAction::IgnoreDuplicateGossip, .. }) =>
+								self.forward_broadcast_msg(peers, &wire::Message::NodeAnnouncement(msg), None),
+							_ => {},
 						}
 					},
 					MessageSendEvent::BroadcastChannelUpdate { msg } => {
 						log_debug!(self.logger, "Handling BroadcastChannelUpdate event in peer_handler for short channel id {}", msg.contents.short_channel_id);
-						if self.message_handler.route_handler.handle_channel_update(&msg).is_ok() {
-							self.forward_broadcast_msg(peers, &wire::Message::ChannelUpdate(msg), None);
+						match self.message_handler.route_handler.handle_channel_update(&msg) {
+							Ok(_) | Err(LightningError { action: msgs::ErrorAction::IgnoreDuplicateGossip, .. }) =>
+								self.forward_broadcast_msg(peers, &wire::Message::ChannelUpdate(msg), None),
+							_ => {},
 						}
 					},
 					MessageSendEvent::SendChannelUpdate { ref node_id, ref msg } => {
@@ -1398,6 +1409,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, L: Deref, CMH: Deref> P
 							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::IgnoreDuplicateGossip => {},
 							msgs::ErrorAction::IgnoreError => {
 								log_debug!(self.logger, "Received a HandleError event to be ignored for node {}", log_pubkey!(node_id));
 							},

lightning/src/routing/network_graph.rs

@@ -847,8 +847,13 @@ impl NetworkGraph {
 			None => Err(LightningError{err: "No existing channels for node_announcement".to_owned(), action: ErrorAction::IgnoreError}),
 			Some(node) => {
 				if let Some(node_info) = node.announcement_info.as_ref() {
-					if node_info.last_update  >= msg.timestamp {
+					// The timestamp field is somewhat of a misnomer - the BOLTs use it to order
+					// updates to ensure you always have the latest one, only vaguely suggesting
+					// that it be at least the current time.
+					if node_info.last_update  > msg.timestamp {
 						return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)});
+					} else if node_info.last_update  == msg.timestamp {
+						return Err(LightningError{err: "Update had the same timestamp as last processed update".to_owned(), action: ErrorAction::IgnoreDuplicateGossip});
 					}
 				}
 
@@ -977,7 +982,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::Gossip)})
+					return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreDuplicateGossip});
 				}
 			},
 			BtreeEntry::Vacant(entry) => {
@@ -1082,8 +1087,16 @@ impl NetworkGraph {
 				macro_rules! maybe_update_channel_info {
 					( $target: expr, $src_node: expr) => {
 						if let Some(existing_chan_info) = $target.as_ref() {
-							if existing_chan_info.last_update >= msg.timestamp {
+							// The timestamp field is somewhat of a misnomer - the BOLTs use it to
+							// order updates to ensure you always have the latest one, only
+							// suggesting  that it be at least the current time. For
+							// channel_updates specifically, the BOLTs discuss the possibility of
+							// pruning based on the timestamp field being more than two weeks old,
+							// but only in the non-normative section.
+							if existing_chan_info.last_update > msg.timestamp {
 								return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Gossip)});
+							} else if existing_chan_info.last_update == msg.timestamp {
+								return Err(LightningError{err: "Update had same timestamp as last processed update".to_owned(), action: ErrorAction::IgnoreDuplicateGossip});
 							}
 							chan_was_enabled = existing_chan_info.enabled;
 						} else {
@@ -1720,7 +1733,7 @@ mod tests {
 
 		match net_graph_msg_handler.handle_channel_update(&valid_channel_update) {
 			Ok(_) => panic!(),
-			Err(e) => assert_eq!(e.err, "Update older than last processed update")
+			Err(e) => assert_eq!(e.err, "Update had same timestamp as last processed update")
 		};
 		unsigned_channel_update.timestamp += 500;