diff --git a/rust/hyperlane-base/src/settings/trace/mod.rs b/rust/hyperlane-base/src/settings/trace/mod.rs index 00d9cb4c50..21999d159d 100644 --- a/rust/hyperlane-base/src/settings/trace/mod.rs +++ b/rust/hyperlane-base/src/settings/trace/mod.rs @@ -66,12 +66,12 @@ impl TracingConfig { if self.level < Level::DependencyTrace { // Reduce log noise from trusted libraries that we can reasonably assume are working correctly target_layer = target_layer - .with_target("hyper", Level::Info) + .with_target("hyper::", Level::Info) .with_target("rusoto_core", Level::Info) .with_target("rustls", Level::Info) .with_target("reqwest", Level::Info) .with_target("runtime", Level::Debug) - .with_target("h2", Level::Info) + .with_target("h2::", Level::Info) .with_target("tower", Level::Info) .with_target("tendermint", Level::Info) .with_target("tokio", Level::Debug) @@ -81,7 +81,9 @@ impl TracingConfig { if self.level < Level::Trace { // only show sqlx query logs at trace level - target_layer = target_layer.with_target("sqlx::query", Level::Warn); + target_layer = target_layer + .with_target("sqlx::query", Level::Warn) + .with_target("hyper::", Level::Warn); } let fmt_layer: LogOutputLayer<_> = self.fmt.into(); let err_layer = tracing_error::ErrorLayer::default(); diff --git a/rust/utils/run-locally/src/invariants.rs b/rust/utils/run-locally/src/invariants.rs index 18bc026c22..91866415b2 100644 --- a/rust/utils/run-locally/src/invariants.rs +++ b/rust/utils/run-locally/src/invariants.rs @@ -62,12 +62,17 @@ pub fn termination_invariants_met( .sum::(); let log_file_path = AGENT_LOGGING_DIR.join("RLY-output.log"); + const STORING_NEW_MESSAGE_LOG_MESSAGE: &str = "Storing new message in db"; + const LOOKING_FOR_EVENTS_LOG_MESSAGE: &str = "Looking for events in index range"; + const HYPER_INCOMING_BODY_LOG_MESSAGE: &str = "incoming body completed"; let relayer_logfile = File::open(log_file_path)?; - let gas_expenditure_log_count = - get_matching_lines(&relayer_logfile, GAS_EXPENDITURE_LOG_MESSAGE) - .unwrap() - .len(); - + let invariant_logs = &[ + STORING_NEW_MESSAGE_LOG_MESSAGE, + LOOKING_FOR_EVENTS_LOG_MESSAGE, + GAS_EXPENDITURE_LOG_MESSAGE, + HYPER_INCOMING_BODY_LOG_MESSAGE, + ]; + let log_counts = get_matching_lines(&relayer_logfile, invariant_logs); // Zero insertion messages don't reach `submit` stage where gas is spent, so we only expect these logs for the other messages. // TODO: Sometimes we find more logs than expected. This may either mean that gas is deducted twice for the same message due to a bug, // or that submitting the message transaction fails for some messages. Figure out which is the case and convert this check to @@ -76,9 +81,22 @@ pub fn termination_invariants_met( // (`Transaction attempting to process message either reverted or was reorged`) // in which case more gas expenditure logs than messages are expected. assert!( - gas_expenditure_log_count as u32 >= total_messages_expected, + log_counts.get(GAS_EXPENDITURE_LOG_MESSAGE).unwrap() >= &total_messages_expected, "Didn't record gas payment for all delivered messages" ); + // These tests check that we fixed https://github.com/hyperlane-xyz/hyperlane-monorepo/issues/3915, where some logs would not show up + assert!( + log_counts.get(STORING_NEW_MESSAGE_LOG_MESSAGE).unwrap() > &0, + "Didn't find any logs about storing messages in db" + ); + assert!( + log_counts.get(LOOKING_FOR_EVENTS_LOG_MESSAGE).unwrap() > &0, + "Didn't find any logs about looking for events in index range" + ); + assert!( + log_counts.get(HYPER_INCOMING_BODY_LOG_MESSAGE).is_none(), + "Verbose logs not expected at the log level set in e2e" + ); let gas_payment_sealevel_events_count = fetch_metric( "9092", diff --git a/rust/utils/run-locally/src/utils.rs b/rust/utils/run-locally/src/utils.rs index 5319701742..5e5dd6a126 100644 --- a/rust/utils/run-locally/src/utils.rs +++ b/rust/utils/run-locally/src/utils.rs @@ -1,3 +1,4 @@ +use std::collections::HashMap; use std::fs::File; use std::io::{self, BufRead}; use std::path::{Path, PathBuf}; @@ -118,15 +119,18 @@ pub fn stop_child(child: &mut Child) { }; } -pub fn get_matching_lines(file: &File, search_string: &str) -> io::Result> { +pub fn get_matching_lines(file: &File, search_strings: &[&str]) -> HashMap { let reader = io::BufReader::new(file); - - // Read lines and collect those that contain the search string - let matching_lines: Vec = reader - .lines() - .map_while(Result::ok) - .filter(|line| line.contains(search_string)) - .collect(); - - Ok(matching_lines) + let mut matches = HashMap::new(); + + let mut lines = reader.lines(); + while let Some(Ok(line)) = lines.next() { + search_strings.iter().for_each(|search_string| { + if line.contains(search_string) { + let count = matches.entry(search_string.to_string()).or_insert(0); + *count += 1; + } + }); + } + matches }