Fix logging

Author: romac

code/crates/test/app/src/app.rs

@@ -88,8 +88,7 @@ pub async fn run(
                 // then we would need to respect the timeout and stop at a certain point.
 
                 info!(%height, %round, "Consensus is requesting a value to propose");
-
-                dbg!(state.ctx.middleware());
+                tracing::debug!(%height, %round, "Middleware: {:?}", state.ctx.middleware());
 
                 // Here it is important that, if we have previously built a value for this height and round,
                 // we send back the very same value.

code/crates/test/framework/src/logging.rs

@@ -2,16 +2,29 @@ pub fn init_logging() {
     use tracing_subscriber::util::SubscriberInitExt;
     use tracing_subscriber::{EnvFilter, FmtSubscriber};
 
-    let crate_name = env!("CARGO_CRATE_NAME");
     let debug_vars = &[("ACTIONS_RUNNER_DEBUG", "true"), ("MALACHITE_DEBUG", "1")];
     let enable_debug = debug_vars
         .iter()
         .any(|(k, v)| std::env::var(k).as_deref() == Ok(v));
 
-    let trace_level = if enable_debug { "trace" } else { "info" };
-    let directive = format!(
-        "{crate_name}=debug,informalsystems_malachitebft={trace_level},informalsystems_malachitebft_discovery=error,libp2p=warn,ractor=warn"
-    );
+    let trace_level = if enable_debug { "debug" } else { "info" };
+
+    let directives = &[
+        ("informalsystems_malachitebft", trace_level),
+        (env!("CARGO_CRATE_NAME"), "debug"),
+        ("it", "debug"), // Name of the integration test crate
+        ("informalsystems_malachitebft_test", "debug"),
+        ("informalsystems_malachitebft_test_app", "debug"),
+        ("informalsystems_malachitebft_discovery", "error"),
+        ("libp2p", "warn"),
+        ("ractor", "warn"),
+    ];
+
+    let directive = directives
+        .iter()
+        .map(|(target, level)| format!("{target}={level}"))
+        .collect::<Vec<_>>()
+        .join(",");
 
     let filter = EnvFilter::builder().parse(directive).unwrap();
 

code/crates/test/tests/it/wal.rs

@@ -462,14 +462,19 @@ impl Middleware for ByzantineProposer {
         proposal: &mut LocallyProposedValue<TestContext>,
         reproposal: bool,
     ) {
+        use informalsystems_malachitebft_test::Value;
+        use rand::Rng;
+
         if !reproposal {
+            tracing::warn!(
+                "ByzantineProposer: First time proposing value {:}",
+                proposal.value.id()
+            );
+
             // Do not change the value if it is the first time we propose it
             return;
         }
 
-        use informalsystems_malachitebft_test::Value;
-        use rand::Rng;
-
         // Make up a new value that is different from the one we are supposed to propose
         let new_value = loop {
             let new_value = Value::new(rand::thread_rng().gen_range(100..=100000));
@@ -478,8 +483,8 @@ impl Middleware for ByzantineProposer {
             }
         };
 
-        tracing::error!(
-            "XXX Not re-using previously built value {:} but a new one {:}",
+        tracing::warn!(
+            "ByzantineProposer: Not re-using previously built value {:} but a new one {:}",
             proposal.value.id(),
             new_value.id()
         );