fix: agent log verbosity

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();

rust/utils/run-locally/src/invariants.rs

@@ -62,12 +62,17 @@ pub fn termination_invariants_met(
     .sum::<u32>();
 
     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",

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<Vec<String>> {
+pub fn get_matching_lines(file: &File, search_strings: &[&str]) -> HashMap<String, u32> {
     let reader = io::BufReader::new(file);
-
-    // Read lines and collect those that contain the search string
-    let matching_lines: Vec<String> = 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
 }