Add some trivial logging during RGS update processing. 2023-04-rgs-log-some
authorMatt Corallo <git@bluematt.me>
Mon, 3 Apr 2023 22:29:41 +0000 (22:29 +0000)
committerMatt Corallo <git@bluematt.me>
Tue, 4 Apr 2023 16:37:35 +0000 (16:37 +0000)
Rather than being totally silent, we need to at least note that we
are processing an RGS update when doing so in the logs, which we do
here.

Fixes #1981.

lightning-rapid-gossip-sync/src/lib.rs
lightning-rapid-gossip-sync/src/processing.rs

index da59b37b10a673c9420b9d2232c81758f0811f59..ce329e241370a5dfc216ef7199fe42ddc94479c2 100644 (file)
@@ -49,7 +49,7 @@
 //! # use lightning::util::logger::{Logger, Record};
 //! # struct FakeLogger {}
 //! # impl Logger for FakeLogger {
-//! #     fn log(&self, record: &Record) { unimplemented!() }
+//! #     fn log(&self, record: &Record) { }
 //! # }
 //! # let logger = FakeLogger {};
 //!
index 8d36dfe38844f75d189e4c27896b3f3a4d3e4891..400fe1ccc5d4f803d395fbfa2adc2d066146957d 100644 (file)
@@ -10,7 +10,7 @@ use lightning::ln::msgs::{
 };
 use lightning::routing::gossip::NetworkGraph;
 use lightning::util::logger::Logger;
-use lightning::{log_warn, log_trace, log_given_level};
+use lightning::{log_debug, log_warn, log_trace, log_given_level, log_gossip};
 use lightning::util::ser::{BigSize, Readable};
 use lightning::io;
 
@@ -58,6 +58,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
                mut read_cursor: &mut R,
                current_time_unix: Option<u64>
        ) -> Result<u32, GraphSyncError> {
+               log_trace!(self.logger, "Processing RGS data...");
                let mut prefix = [0u8; 4];
                read_cursor.read_exact(&mut prefix)?;
 
@@ -110,6 +111,9 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
                        let node_id_1 = node_ids[node_id_1_index.0 as usize];
                        let node_id_2 = node_ids[node_id_2_index.0 as usize];
 
+                       log_gossip!(self.logger, "Adding channel {} from RGS announcement at {}",
+                               short_channel_id, latest_seen_timestamp);
+
                        let announcement_result = network_graph.add_channel_from_partial_announcement(
                                short_channel_id,
                                backdated_timestamp as u64,
@@ -130,6 +134,8 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
                previous_scid = 0; // updates start at a new scid
 
                let update_count: u32 = Readable::read(read_cursor)?;
+               log_debug!(self.logger, "Processing RGS update from {} with {} nodes, {} channel announcements and {} channel updates.",
+                       latest_seen_timestamp, node_id_count, announcement_count, update_count);
                if update_count == 0 {
                        return Ok(latest_seen_timestamp);
                }
@@ -217,6 +223,8 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
                                continue;
                        }
 
+                       log_gossip!(self.logger, "Updating channel {} with flags {} from RGS announcement at {}",
+                               short_channel_id, channel_flags, latest_seen_timestamp);
                        match network_graph.update_channel_unsigned(&synthetic_update) {
                                Ok(_) => {},
                                Err(LightningError { action: ErrorAction::IgnoreDuplicateGossip, .. }) => {},
@@ -230,6 +238,7 @@ impl<NG: Deref<Target=NetworkGraph<L>>, L: Deref> RapidGossipSync<NG, L> where L
 
                self.network_graph.set_last_rapid_gossip_sync_timestamp(latest_seen_timestamp);
                self.is_initial_sync_complete.store(true, Ordering::Release);
+               log_trace!(self.logger, "Done processing RGS data from {}", latest_seen_timestamp);
                Ok(latest_seen_timestamp)
        }
 }