From 94fca17c143af0919cac475e1c7cf621e059568e Mon Sep 17 00:00:00 2001 From: Azrenbeth <7782548+Azrenbeth@users.noreply.github.com> Date: Tue, 14 Sep 2021 14:49:59 +0100 Subject: [PATCH 1/2] All printing replaced by logging This allows other packages that use the compressor to control what and how the libary prints. --- Cargo.lock | 2 + Cargo.toml | 2 + .../auto_compressor_state_saving_tests.rs | 3 +- .../tests/compressor_config_tests.rs | 10 ++++- .../tests/compressor_continue_run_tests.rs | 3 +- src/database.rs | 11 +++-- src/lib.rs | 41 ++++++++++--------- src/main.rs | 19 +++++++++ 8 files changed, 62 insertions(+), 29 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 3cfc6fe..9f409be 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1139,8 +1139,10 @@ name = "synapse_compress_state" version = "0.1.0" dependencies = [ "clap", + "env_logger 0.9.0 (registry+https://github.com/rust-lang/crates.io-index)", "indicatif", "jemallocator", + "log", "openssl", "postgres", "postgres-openssl", diff --git a/Cargo.toml b/Cargo.toml index 295d5f2..15b0a3f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -18,6 +18,8 @@ postgres-openssl = "0.5.0" rand = "0.8.0" rayon = "1.3.0" string_cache = "0.8.0" +env_logger = "0.9.0" +log = "0.4.14" [dependencies.state-map] git = "https://github.com/matrix-org/rust-matrix-state-map" diff --git a/compressor_integration_tests/tests/auto_compressor_state_saving_tests.rs b/compressor_integration_tests/tests/auto_compressor_state_saving_tests.rs index b5ae98c..849fcde 100644 --- a/compressor_integration_tests/tests/auto_compressor_state_saving_tests.rs +++ b/compressor_integration_tests/tests/auto_compressor_state_saving_tests.rs @@ -2,13 +2,14 @@ use auto_compressor::state_saving::{ connect_to_database, create_tables_if_needed, read_room_compressor_state, write_room_compressor_state, }; -use compressor_integration_tests::{clear_compressor_state, DB_URL}; +use compressor_integration_tests::{clear_compressor_state, setup_logger, DB_URL}; use serial_test::serial; use synapse_compress_state::Level; #[test] #[serial(db)] fn write_then_read_state_gives_correct_results() { + setup_logger(); let mut client = connect_to_database(DB_URL).unwrap(); create_tables_if_needed(&mut client).unwrap(); clear_compressor_state(); diff --git a/compressor_integration_tests/tests/compressor_config_tests.rs b/compressor_integration_tests/tests/compressor_config_tests.rs index 6c83b3c..ace03a2 100644 --- a/compressor_integration_tests/tests/compressor_config_tests.rs +++ b/compressor_integration_tests/tests/compressor_config_tests.rs @@ -7,7 +7,7 @@ use compressor_integration_tests::{ compressed_3_3_from_0_to_13_with_state, line_segments_with_state, line_with_state, structure_from_edges_with_state, }, - DB_URL, + setup_logger, DB_URL, }; use serial_test::serial; use synapse_compress_state::{run, Config}; @@ -22,6 +22,7 @@ use synapse_compress_state::{run, Config}; #[test] #[serial(db)] fn run_succeeds_without_crashing() { + setup_logger(); // This starts with the following structure // // 0-1-2-3-4-5-6-7-8-9-10-11-12-13 @@ -67,6 +68,7 @@ fn run_succeeds_without_crashing() { #[test] #[serial(db)] fn changes_commited_if_no_min_saved_rows() { + setup_logger(); // This starts with the following structure // // 0-1-2 3-4-5 6-7-8 9-10-11 12-13 @@ -132,6 +134,7 @@ fn changes_commited_if_no_min_saved_rows() { #[test] #[serial(db)] fn changes_commited_if_min_saved_rows_exceeded() { + setup_logger(); // This starts with the following structure // // 0-1-2 3-4-5 6-7-8 9-10-11 12-13 @@ -197,6 +200,7 @@ fn changes_commited_if_min_saved_rows_exceeded() { #[test] #[serial(db)] fn changes_not_commited_if_fewer_than_min_saved_rows() { + setup_logger(); // This starts with the following structure // // 0-1-2 3-4-5 6-7-8 9-10-11 12-13 @@ -263,6 +267,7 @@ fn changes_not_commited_if_fewer_than_min_saved_rows() { #[test] #[should_panic(expected = "Error connecting to the database:")] fn run_panics_if_invalid_db_url() { + setup_logger(); // set up the config options let db_url = "thisIsAnInvalidURL".to_string(); let room_id = "room1".to_string(); @@ -298,6 +303,7 @@ fn run_panics_if_invalid_db_url() { #[test] #[serial(db)] fn run_only_affects_given_room_id() { + setup_logger(); // build room1 stuff up // This starts with the following structure // @@ -374,6 +380,7 @@ fn run_only_affects_given_room_id() { #[test] #[serial(db)] fn run_respects_groups_to_compress() { + setup_logger(); // This starts with the following structure // // 0-1-2 3-4-5 6-7-8 9-10-11 12-13 @@ -456,6 +463,7 @@ fn run_respects_groups_to_compress() { #[test] #[serial(db)] fn run_is_idempotent_when_run_on_whole_room() { + setup_logger(); // This starts with the following structure // // 0-1-2 3-4-5 6-7-8 9-10-11 12-13 diff --git a/compressor_integration_tests/tests/compressor_continue_run_tests.rs b/compressor_integration_tests/tests/compressor_continue_run_tests.rs index 5f44610..0ae05db 100644 --- a/compressor_integration_tests/tests/compressor_continue_run_tests.rs +++ b/compressor_integration_tests/tests/compressor_continue_run_tests.rs @@ -2,7 +2,7 @@ use compressor_integration_tests::{ add_contents_to_database, database_collapsed_states_match_map, database_structure_matches_map, empty_database, map_builder::{compressed_3_3_from_0_to_13_with_state, line_segments_with_state}, - DB_URL, + setup_logger, DB_URL, }; use serial_test::serial; use synapse_compress_state::{continue_run, Level}; @@ -13,6 +13,7 @@ use synapse_compress_state::{continue_run, Level}; #[test] #[serial(db)] fn continue_run_called_twice_same_as_run() { + setup_logger(); // This starts with the following structure // // 0-1-2 3-4-5 6-7-8 9-10-11 12-13 diff --git a/src/database.rs b/src/database.rs index 1808f56..3982be8 100644 --- a/src/database.rs +++ b/src/database.rs @@ -13,6 +13,7 @@ // limitations under the License. use indicatif::{ProgressBar, ProgressStyle}; +use log::{debug, trace}; use openssl::ssl::{SslConnector, SslMethod, SslVerifyMode}; use postgres::{fallible_iterator::FallibleIterator, types::ToSql, Client}; use postgres_openssl::MakeTlsConnector; @@ -40,7 +41,6 @@ use super::StateGroupEntry; /// * `max_state_group` - If specified, then only fetch the entries for state /// groups lower than or equal to this number. /// * 'groups_to_compress' - The number of groups to get from the database before stopping - pub fn get_data_from_db( db_url: &str, room_id: &str, @@ -59,7 +59,6 @@ pub fn get_data_from_db( // Search for the group id of the groups_to_compress'th group after min_state_group // If this is saved, then the compressor can continue by having min_state_group being // set to this maximum. If no such group can be found then return None. - let max_group_found = find_max_group( &mut client, room_id, @@ -222,7 +221,7 @@ fn load_map_from_db( max_group_found, )); - println!("Got initial state from database. Checking for any missing state groups..."); + debug!("Got initial state from database. Checking for any missing state groups..."); // Due to reasons some of the state groups appear in the edges table, but // not in the state_groups_state table. @@ -251,14 +250,14 @@ fn load_map_from_db( .collect(); if missing_sgs.is_empty() { - // println!("No missing state groups"); + trace!("No missing state groups"); break; } missing_sgs.sort_unstable(); missing_sgs.dedup(); - // println!("Missing {} state groups", missing_sgs.len()); + trace!("Missing {} state groups", missing_sgs.len()); // find state groups not picked up already and add them to the map let map = get_missing_from_db(client, &missing_sgs, min_state_group, max_group_found); @@ -535,7 +534,7 @@ pub fn send_changes_to_db( let mut client = Client::connect(db_url, connector).unwrap(); - println!("Writing changes..."); + debug!("Writing changes..."); // setup the progress bar let pb: ProgressBar; diff --git a/src/lib.rs b/src/lib.rs index 6ffd351..31f284a 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -20,6 +20,7 @@ // of arguments - this hopefully doesn't make the code unclear // #[allow(clippy::too_many_arguments)] is therefore used around some functions +use log::{info, warn}; use pyo3::{exceptions, prelude::*}; use clap::{crate_authors, crate_description, crate_name, crate_version, value_t, App, Arg}; @@ -290,7 +291,7 @@ impl Config { pub fn run(mut config: Config) { // First we need to get the current state groups - println!("Fetching state from DB for room '{}'...", config.room_id); + info!("Fetching state from DB for room '{}'...", config.room_id); let (state_group_map, max_group_found) = database::get_data_from_db( &config.db_url, @@ -301,19 +302,19 @@ pub fn run(mut config: Config) { ) .unwrap_or_else(|| panic!("No state groups found within this range")); - println!("Fetched state groups up to {}", max_group_found); + info!("Fetched state groups up to {}", max_group_found); - println!("Number of state groups: {}", state_group_map.len()); + info!("Number of state groups: {}", state_group_map.len()); let original_summed_size = state_group_map .iter() .fold(0, |acc, (_, v)| acc + v.state_map.len()); - println!("Number of rows in current table: {}", original_summed_size); + info!("Number of rows in current table: {}", original_summed_size); // Now we actually call the compression algorithm. - println!("Compressing state..."); + info!("Compressing state..."); let compressor = Compressor::compress(&state_group_map, &config.level_sizes.0); @@ -327,22 +328,22 @@ pub fn run(mut config: Config) { let ratio = (compressed_summed_size as f64) / (original_summed_size as f64); - println!( + info!( "Number of rows after compression: {} ({:.2}%)", compressed_summed_size, ratio * 100. ); - println!("Compression Statistics:"); - println!( + info!("Compression Statistics:"); + info!( " Number of forced resets due to lacking prev: {}", compressor.stats.resets_no_suitable_prev ); - println!( + info!( " Number of compressed rows caused by the above: {}", compressor.stats.resets_no_suitable_prev_size ); - println!( + info!( " Number of state groups changed: {}", compressor.stats.state_groups_changed ); @@ -352,14 +353,14 @@ pub fn run(mut config: Config) { } if ratio > 1.0 { - println!("This compression would not remove any rows. Exiting."); + warn!("This compression would not remove any rows. Exiting."); return; } if let Some(min) = config.min_saved_rows { let saving = (original_summed_size - compressed_summed_size) as i32; if saving < min { - println!( + warn!( "Only {} rows would be saved by this compression. Skipping output.", saving ); @@ -485,7 +486,7 @@ fn output_sql( return; } - println!("Writing changes..."); + info!("Writing changes..."); let pb: ProgressBar; if cfg!(feature = "no-progress-bars") { @@ -559,7 +560,7 @@ pub fn continue_run( let ratio = (new_num_rows as f64) / (original_num_rows as f64); if ratio > 1.0 { - println!("This compression would not remove any rows. Aborting."); + warn!("This compression would not remove any rows. Aborting."); return Some(ChunkStats { new_level_info: compressor.get_level_info(), last_compressed_group: max_group_found, @@ -600,7 +601,7 @@ fn check_that_maps_match( old_map: &BTreeMap, new_map: &BTreeMap, ) { - println!("Checking that state maps match..."); + info!("Checking that state maps match..."); let pb: ProgressBar; if cfg!(feature = "no-progress-bars") { @@ -625,10 +626,10 @@ fn check_that_maps_match( pb.inc(1); if expected != actual { - println!("State Group: {}", sg); - println!("Expected: {:#?}", expected); - println!("actual: {:#?}", actual); - Err(format!("States for group {} do not match", sg)) + Err(format!( + "States for group {} do not match. Expected {:#?}, found {:#?}", + sg, expected, actual + )) } else { Ok(()) } @@ -637,7 +638,7 @@ fn check_that_maps_match( pb.finish(); - println!("New state map matches old one"); + info!("New state map matches old one"); } /// Gets the full state for a given group from the map (of deltas) diff --git a/src/main.rs b/src/main.rs index 17cfe49..ce83f07 100644 --- a/src/main.rs +++ b/src/main.rs @@ -20,8 +20,27 @@ #[global_allocator] static GLOBAL: jemallocator::Jemalloc = jemallocator::Jemalloc; +use log::LevelFilter; +use std::env; +use std::io::Write; + use synapse_compress_state as comp_state; fn main() { + // setup the logger + // The default can be overwritten with COMPRESSOR_LOG_LEVEL + // see the README for more information <---- TODO + if env::var("COMPRESSOR_LOG_LEVEL").is_err() { + let mut log_builder = env_logger::builder(); + // Only output the log message (and not the prefixed timestamp etc.) + log_builder.format(|buf, record| writeln!(buf, "{}", record.args())); + // By default print all of the debugging messages from this library + log_builder.filter_module("synapse_compress_state", LevelFilter::Debug); + log_builder.init(); + } else { + // If COMPRESSOR_LOG_LEVEL was set then use that + env_logger::Builder::from_env("COMPRESSOR_LOG_LEVEL").init(); + } + comp_state::run(comp_state::Config::parse_arguments()); } From 7e326566ef9d4eb5119ae1b552c98c07fe6d9eb9 Mon Sep 17 00:00:00 2001 From: Azrenbeth <7782548+Azrenbeth@users.noreply.github.com> Date: Mon, 27 Sep 2021 12:19:13 +0100 Subject: [PATCH 2/2] replace COMPRESSOR_LOG_LEVEL with RUST_LOG --- compressor_integration_tests/src/lib.rs | 8 ++++---- src/main.rs | 8 ++++---- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/compressor_integration_tests/src/lib.rs b/compressor_integration_tests/src/lib.rs index 9f72f68..6f4f2a3 100644 --- a/compressor_integration_tests/src/lib.rs +++ b/compressor_integration_tests/src/lib.rs @@ -357,9 +357,9 @@ fn functions_are_self_consistent() { pub fn setup_logger() { // setup the logger for the auto_compressor - // The default can be overwritten with COMPRESSOR_LOG_LEVEL + // The default can be overwritten with RUST_LOG // see the README for more information <--- TODO - if env::var("COMPRESSOR_LOG_LEVEL").is_err() { + if env::var("RUST_LOG").is_err() { let mut log_builder = env_logger::builder(); // set is_test(true) so that the output is hidden by cargo test (unless the test fails) log_builder.is_test(true); @@ -370,8 +370,8 @@ pub fn setup_logger() { // use try_init() incase the logger has been setup by some previous test let _ = log_builder.try_init(); } else { - // If COMPRESSOR_LOG_LEVEL was set then use that - let mut log_builder = env_logger::Builder::from_env("COMPRESSOR_LOG_LEVEL"); + // If RUST_LOG was set then use that + let mut log_builder = env_logger::Builder::from_env("RUST_LOG"); // set is_test(true) so that the output is hidden by cargo test (unless the test fails) log_builder.is_test(true); // use try_init() in case the logger has been setup by some previous test diff --git a/src/main.rs b/src/main.rs index ce83f07..6f72005 100644 --- a/src/main.rs +++ b/src/main.rs @@ -28,9 +28,9 @@ use synapse_compress_state as comp_state; fn main() { // setup the logger - // The default can be overwritten with COMPRESSOR_LOG_LEVEL + // The default can be overwritten with RUST_LOG // see the README for more information <---- TODO - if env::var("COMPRESSOR_LOG_LEVEL").is_err() { + if env::var("RUST_LOG").is_err() { let mut log_builder = env_logger::builder(); // Only output the log message (and not the prefixed timestamp etc.) log_builder.format(|buf, record| writeln!(buf, "{}", record.args())); @@ -38,8 +38,8 @@ fn main() { log_builder.filter_module("synapse_compress_state", LevelFilter::Debug); log_builder.init(); } else { - // If COMPRESSOR_LOG_LEVEL was set then use that - env_logger::Builder::from_env("COMPRESSOR_LOG_LEVEL").init(); + // If RUST_LOG was set then use that + env_logger::Builder::from_env("RUST_LOG").init(); } comp_state::run(comp_state::Config::parse_arguments());