test: add some debug calls (#11762)

Author: DaniPopes

Cargo.lock

@@ -18,6 +18,7 @@ use foundry_evm::{constants::CALLER, opts::EvmOpts};
 use foundry_test_utils::{
     fd_lock, init_tracing,
     rpc::{next_http_archive_rpc_url, next_rpc_endpoint},
+    test_debug,
 };
 use revm::primitives::hardfork::SpecId;
 use std::{
@@ -278,6 +279,7 @@ pub fn get_vyper() -> Vyper {
         };
         let url = format!("https://github.com/vyperlang/vyper/releases/download/v0.4.3/vyper.0.4.3+commit.bff19ea2.{suffix}");
 
+        test_debug!("downloading vyper from {url}");
         let res = reqwest::Client::builder().build().unwrap().get(url).send().await.unwrap();
 
         assert!(res.status().is_success());
@@ -293,6 +295,7 @@ pub fn get_vyper() -> Vyper {
     })
 }
 
+#[tracing::instrument]
 pub fn get_compiled(project: &mut Project) -> ProjectCompileOutput {
     let lock_file_path = project.sources_path().join(".lock");
     // Compile only once per test run.
@@ -307,13 +310,18 @@ pub fn get_compiled(project: &mut Project) -> ProjectCompileOutput {
     if !project.cache_path().exists() || std::fs::read(&lock_file_path).unwrap() != b"1" {
         drop(read);
         write = Some(lock.write().unwrap());
+        test_debug!("cache miss for {}", lock_file_path.display());
+    } else {
+        test_debug!("cache hit for {}", lock_file_path.display());
     }
 
     if project.compiler.vyper.is_none() {
         project.compiler.vyper = Some(get_vyper());
     }
 
+    test_debug!("compiling {}", lock_file_path.display());
     out = project.compile().unwrap();
+    test_debug!("compiled {}", lock_file_path.display());
 
     if out.has_compiler_errors() {
         panic!("Compiled with errors:\n{out}");

crates/forge/tests/it/test_helpers.rs

@@ -11,6 +11,7 @@
 extern crate tracing;
 
 // Macros useful for testing.
+#[macro_use]
 mod macros;
 
 pub mod rpc;
@@ -36,18 +37,32 @@ pub use snapbox::{self, assert_data_eq, file, str};
 
 /// Initializes tracing for tests.
 pub fn init_tracing() {
-    if std::env::var_os("RUST_BACKTRACE").is_none() {
-        unsafe { std::env::set_var("RUST_BACKTRACE", "1") };
-    }
-    let _ = tracing_subscriber::FmtSubscriber::builder().with_env_filter(env_filter()).try_init();
-    let _ = ui_test::color_eyre::install();
+    use std::sync::Once;
+    static ONCE: Once = Once::new();
+    ONCE.call_once(|| {
+        if std::env::var_os("RUST_BACKTRACE").is_none() {
+            unsafe { std::env::set_var("RUST_BACKTRACE", "1") };
+        }
+        let _ = tracing_subscriber::FmtSubscriber::builder()
+            .with_env_filter(env_filter())
+            .with_test_writer()
+            .try_init();
+        let _ = ui_test::color_eyre::install();
+    });
 }
 
 fn env_filter() -> tracing_subscriber::EnvFilter {
     const DEFAULT_DIRECTIVES: &[&str] = &include!("../../cli/src/utils/default_directives.txt");
-    let mut filter = tracing_subscriber::EnvFilter::from_default_env();
+    let mut filter = tracing_subscriber::EnvFilter::builder()
+        .with_default_directive("foundry_test_utils=debug".parse().unwrap())
+        .from_env_lossy();
     for &directive in DEFAULT_DIRECTIVES {
         filter = filter.add_directive(directive.parse().unwrap());
     }
     filter
 }
+
+pub fn test_debug(args: std::fmt::Arguments<'_>) {
+    init_tracing();
+    debug!("{args}");
+}

crates/test-utils/src/lib.rs

@@ -122,3 +122,10 @@ macro_rules! forgesoldeer {
         }
     };
 }
+
+#[macro_export]
+macro_rules! test_debug {
+    ($($args:tt)*) => {
+        $crate::test_debug(format_args!($($args)*))
+    }
+}

crates/test-utils/src/macros.rs

@@ -128,14 +128,14 @@ pub fn next_ws_archive_rpc_url() -> String {
 fn next_archive_url(is_ws: bool) -> String {
     let domain = next(if is_ws { &WS_ARCHIVE_DOMAINS } else { &HTTP_ARCHIVE_DOMAINS });
     let url = if is_ws { format!("wss://{domain}") } else { format!("https://{domain}") };
-    eprintln!("--- next_archive_url(is_ws={is_ws}) = {url} ---");
+    test_debug!("next_archive_url(is_ws={is_ws}) = {url}");
     url
 }
 
 /// Returns the next etherscan api key.
 pub fn next_etherscan_api_key() -> String {
     let key = next(&ETHERSCAN_KEYS).to_string();
-    eprintln!("--- next_etherscan_api_key() = {key} ---");
+    test_debug!("next_etherscan_api_key() = {key}");
     key
 }
 
@@ -175,7 +175,7 @@ fn next_url(is_ws: bool, chain: NamedChain) -> String {
 
     let url = if is_ws { format!("wss://{domain}") } else { format!("https://{domain}") };
 
-    eprintln!("--- next_url(is_ws={is_ws}, chain={chain:?}) = {url} ---");
+    test_debug!("next_url(is_ws={is_ws}, chain={chain:?}) = {url}");
     url
 }