Switch timestamp queries to use f64.
[rapid-gossip-sync-server] / src / lookup.rs
index c554f9f57508bb251d7f664a26cd2ec0eee3ae2d..fa66103ec53a3af9f657a37ffbbd7a18266c8fcd 100644 (file)
@@ -1,8 +1,8 @@
 use std::collections::{BTreeMap, HashSet};
 use std::io::Cursor;
-use std::ops::Add;
+use std::ops::Deref;
 use std::sync::Arc;
-use std::time::{Duration, Instant, SystemTime};
+use std::time::{Instant, SystemTime, UNIX_EPOCH};
 
 use lightning::ln::msgs::{ChannelAnnouncement, ChannelUpdate, UnsignedChannelAnnouncement, UnsignedChannelUpdate};
 use lightning::routing::gossip::NetworkGraph;
@@ -11,8 +11,10 @@ use tokio_postgres::{Client, Connection, NoTls, Socket};
 use tokio_postgres::tls::NoTlsStream;
 
 use futures::StreamExt;
+use lightning::log_info;
+use lightning::util::logger::Logger;
 
-use crate::{config, TestLogger};
+use crate::config;
 use crate::serialization::MutatedProperties;
 
 /// The delta set needs to be a BTreeMap so the keys are sorted.
@@ -75,24 +77,28 @@ pub(super) async fn connect_to_db() -> (Client, Connection<Socket, NoTlsStream>)
 /// whether they had been seen before.
 /// Also include all announcements for which the first update was announced
 /// after `last_sync_timestamp`
-pub(super) async fn fetch_channel_announcements(delta_set: &mut DeltaSet, network_graph: Arc<NetworkGraph<TestLogger>>, client: &Client, last_sync_timestamp: u32) {
-       println!("Obtaining channel ids from network graph");
-       let last_sync_timestamp_object = SystemTime::UNIX_EPOCH.add(Duration::from_secs(last_sync_timestamp as u64));
+pub(super) async fn fetch_channel_announcements<L: Deref>(delta_set: &mut DeltaSet, network_graph: Arc<NetworkGraph<L>>, client: &Client, last_sync_timestamp: u32, logger: L) where L::Target: Logger {
+       log_info!(logger, "Obtaining channel ids from network graph");
        let channel_ids = {
                let read_only_graph = network_graph.read_only();
-               println!("Retrieved read-only network graph copy");
+               log_info!(logger, "Retrieved read-only network graph copy");
                let channel_iterator = read_only_graph.channels().unordered_iter();
                channel_iterator
                        .filter(|c| c.1.announcement_message.is_some())
                        .map(|c| c.1.announcement_message.as_ref().unwrap().contents.short_channel_id as i64)
                        .collect::<Vec<_>>()
        };
+       #[cfg(test)]
+       log_info!(logger, "Channel IDs: {:?}", channel_ids);
+       log_info!(logger, "Last sync timestamp: {}", last_sync_timestamp);
+       let last_sync_timestamp_float = last_sync_timestamp as f64;
 
-       println!("Obtaining corresponding database entries");
+       log_info!(logger, "Obtaining corresponding database entries");
        // get all the channel announcements that are currently in the network graph
        let announcement_rows = client.query_raw("SELECT announcement_signed, seen FROM channel_announcements WHERE short_channel_id = any($1) ORDER BY short_channel_id ASC", [&channel_ids]).await.unwrap();
        let mut pinned_rows = Box::pin(announcement_rows);
 
+       let mut announcement_count = 0;
        while let Some(row_res) = pinned_rows.next().await {
                let current_announcement_row = row_res.unwrap();
                let blob: Vec<u8> = current_announcement_row.get("announcement_signed");
@@ -108,12 +114,15 @@ pub(super) async fn fetch_channel_announcements(delta_set: &mut DeltaSet, networ
                        announcement: unsigned_announcement,
                        seen: current_seen_timestamp,
                });
+
+               announcement_count += 1;
        }
+       log_info!(logger, "Fetched {} announcement rows", announcement_count);
 
        {
                // THIS STEP IS USED TO DETERMINE IF A CHANNEL SHOULD BE OMITTED FROM THE DELTA
 
-               println!("Annotating channel announcements whose oldest channel update in a given direction occurred after the last sync");
+               log_info!(logger, "Annotating channel announcements whose oldest channel update in a given direction occurred after the last sync");
                // Steps:
                // — Obtain all updates, distinct by (scid, direction), ordered by seen DESC // to find the oldest update in a given direction
                // — From those updates, select distinct by (scid), ordered by seen DESC (to obtain the newer one per direction)
@@ -122,7 +131,7 @@ pub(super) async fn fetch_channel_announcements(delta_set: &mut DeltaSet, networ
                // here is where the channels whose first update in either direction occurred after
                // `last_seen_timestamp` are added to the selection
                let params: [&(dyn tokio_postgres::types::ToSql + Sync); 2] =
-                       [&channel_ids, &last_sync_timestamp_object];
+                       [&channel_ids, &last_sync_timestamp_float];
                let newer_oldest_directional_updates = client.query_raw("
                        SELECT * FROM (
                                SELECT DISTINCT ON (short_channel_id) *
@@ -134,10 +143,11 @@ pub(super) async fn fetch_channel_announcements(delta_set: &mut DeltaSet, networ
                                ) AS directional_last_seens
                                ORDER BY short_channel_id ASC, seen DESC
                        ) AS distinct_chans
-                       WHERE distinct_chans.seen >= $2
+                       WHERE distinct_chans.seen >= TO_TIMESTAMP($2)
                        ", params).await.unwrap();
                let mut pinned_updates = Box::pin(newer_oldest_directional_updates);
 
+               let mut newer_oldest_directional_update_count = 0;
                while let Some(row_res) = pinned_updates.next().await {
                        let current_row = row_res.unwrap();
 
@@ -149,17 +159,20 @@ pub(super) async fn fetch_channel_announcements(delta_set: &mut DeltaSet, networ
                        let current_channel_delta = delta_set.entry(scid as u64).or_insert(ChannelDelta::default());
                        // first time a channel was seen in both directions
                        (*current_channel_delta).first_bidirectional_updates_seen = Some(current_seen_timestamp);
+
+                       newer_oldest_directional_update_count += 1;
                }
+               log_info!(logger, "Fetched {} update rows of the first update in a new direction", newer_oldest_directional_update_count);
        }
 
        {
                // THIS STEP IS USED TO DETERMINE IF A REMINDER UPDATE SHOULD BE SENT
 
-               println!("Annotating channel announcements whose latest channel update in a given direction occurred more than six days ago");
+               log_info!(logger, "Annotating channel announcements whose latest channel update in a given direction occurred more than six days ago");
                // Steps:
                // — Obtain all updates, distinct by (scid, direction), ordered by seen DESC
                // — From those updates, select distinct by (scid), ordered by seen ASC (to obtain the older one per direction)
-               let reminder_threshold_timestamp = SystemTime::now().checked_sub(config::CHANNEL_REMINDER_AGE).unwrap();
+               let reminder_threshold_timestamp = SystemTime::now().checked_sub(config::CHANNEL_REMINDER_AGE).unwrap().duration_since(UNIX_EPOCH).unwrap().as_secs() as f64;
 
                let params: [&(dyn tokio_postgres::types::ToSql + Sync); 2] =
                        [&channel_ids, &reminder_threshold_timestamp];
@@ -174,10 +187,11 @@ pub(super) async fn fetch_channel_announcements(delta_set: &mut DeltaSet, networ
                                ) AS directional_last_seens
                                ORDER BY short_channel_id ASC, seen ASC
                        ) AS distinct_chans
-                       WHERE distinct_chans.seen <= $2
+                       WHERE distinct_chans.seen <= TO_TIMESTAMP($2)
                        ", params).await.unwrap();
                let mut pinned_updates = Box::pin(older_latest_directional_updates);
 
+               let mut older_latest_directional_update_count = 0;
                while let Some(row_res) = pinned_updates.next().await {
                        let current_row = row_res.unwrap();
                        let scid: i64 = current_row.get("short_channel_id");
@@ -209,13 +223,15 @@ pub(super) async fn fetch_channel_announcements(delta_set: &mut DeltaSet, networ
                                // we don't send reminders if we don't have the channel
                                continue;
                        }
+                       older_latest_directional_update_count += 1;
                }
+               log_info!(logger, "Fetched {} update rows of the latest update in the less recently updated direction", older_latest_directional_update_count);
        }
 }
 
-pub(super) async fn fetch_channel_updates(delta_set: &mut DeltaSet, client: &Client, last_sync_timestamp: u32) {
+pub(super) async fn fetch_channel_updates<L: Deref>(delta_set: &mut DeltaSet, client: &Client, last_sync_timestamp: u32, logger: L) where L::Target: Logger {
        let start = Instant::now();
-       let last_sync_timestamp_object = SystemTime::UNIX_EPOCH.add(Duration::from_secs(last_sync_timestamp as u64));
+       let last_sync_timestamp_float = last_sync_timestamp as f64;
 
        // get the latest channel update in each direction prior to last_sync_timestamp, provided
        // there was an update in either direction that happened after the last sync (to avoid
@@ -225,17 +241,17 @@ pub(super) async fn fetch_channel_updates(delta_set: &mut DeltaSet, client: &Cli
                WHERE id IN (
                        SELECT DISTINCT ON (short_channel_id, direction) id
                        FROM channel_updates
-                       WHERE seen < $1 AND short_channel_id IN (
+                       WHERE seen < TO_TIMESTAMP($1) AND short_channel_id IN (
                                SELECT DISTINCT ON (short_channel_id) short_channel_id
                                FROM channel_updates
-                               WHERE seen >= $1
+                               WHERE seen >= TO_TIMESTAMP($1)
                        )
                        ORDER BY short_channel_id ASC, direction ASC, seen DESC
                )
-               ", [last_sync_timestamp_object]).await.unwrap();
+               ", [last_sync_timestamp_float]).await.unwrap();
        let mut pinned_rows = Box::pin(reference_rows);
 
-       println!("Fetched reference rows in {:?}", start.elapsed());
+       log_info!(logger, "Fetched reference rows in {:?}", start.elapsed());
 
        let mut last_seen_update_ids: Vec<i32> = Vec::new();
        let mut non_intermediate_ids: HashSet<i32> = HashSet::new();
@@ -263,7 +279,7 @@ pub(super) async fn fetch_channel_updates(delta_set: &mut DeltaSet, client: &Cli
                reference_row_count += 1;
        }
 
-       println!("Processed {} reference rows (delta size: {}) in {:?}",
+       log_info!(logger, "Processed {} reference rows (delta size: {}) in {:?}",
                reference_row_count, delta_set.len(), start.elapsed());
 
        // get all the intermediate channel updates
@@ -273,10 +289,10 @@ pub(super) async fn fetch_channel_updates(delta_set: &mut DeltaSet, client: &Cli
        let intermediate_updates = client.query_raw("
                SELECT id, direction, blob_signed, seen
                FROM channel_updates
-               WHERE seen >= $1
-               ", [last_sync_timestamp_object]).await.unwrap();
+               WHERE seen >= TO_TIMESTAMP($1)
+               ", [last_sync_timestamp_float]).await.unwrap();
        let mut pinned_updates = Box::pin(intermediate_updates);
-       println!("Fetched intermediate rows in {:?}", start.elapsed());
+       log_info!(logger, "Fetched intermediate rows in {:?}", start.elapsed());
 
        let mut previous_scid = u64::MAX;
        let mut previously_seen_directions = (false, false);
@@ -351,10 +367,10 @@ pub(super) async fn fetch_channel_updates(delta_set: &mut DeltaSet, client: &Cli
                        }
                }
        }
-       println!("Processed intermediate rows ({}) (delta size: {}): {:?}", intermediate_update_count, delta_set.len(), start.elapsed());
+       log_info!(logger, "Processed intermediate rows ({}) (delta size: {}): {:?}", intermediate_update_count, delta_set.len(), start.elapsed());
 }
 
-pub(super) fn filter_delta_set(delta_set: &mut DeltaSet) {
+pub(super) fn filter_delta_set<L: Deref>(delta_set: &mut DeltaSet, logger: L) where L::Target: Logger {
        let original_length = delta_set.len();
        let keys: Vec<u64> = delta_set.keys().cloned().collect();
        for k in keys {
@@ -386,6 +402,6 @@ pub(super) fn filter_delta_set(delta_set: &mut DeltaSet) {
 
        let new_length = delta_set.len();
        if original_length != new_length {
-               println!("length modified!");
+               log_info!(logger, "length modified!");
        }
 }