Add basic tracing (#3739)

cptartur · franciszekjob · web-flow · commit 6730722d9167 · 2025-09-22T10:37:57.000Z
&lt;!-- Reference any GitHub issues resolved by this PR --&gt;

Closes #

## Introduced changes

&lt;!-- A brief description of the changes --&gt;

-

## Checklist

&lt;!-- Make sure all of these are complete --&gt;

- [ ] Linked relevant issue
- [ ] Updated relevant documentation
- [ ] Added relevant tests
- [ ] Performed self-review of the code
- [ ] Added changes to `CHANGELOG.md`

---------

Co-authored-by: Franciszek Job &lt;54181625+franciszekjob@users.noreply.github.com&gt;
diff --git a/Cargo.lock b/Cargo.lock
diff --git a/Cargo.toml b/Cargo.toml
@@ -33,7 +33,7 @@ license = "MIT"
 license-file = "LICENSE"
 
 [workspace.dependencies]
-blockifier = { version = "0.15.0-rc.3", features = ["testing", "tracing"]}
+blockifier = { version = "0.15.0-rc.3", features = ["testing", "tracing"] }
 bigdecimal = "0.4.8"
 starknet_api = "0.15.0-rc.3"
 cairo-lang-casm = { version = "2.12.0", features = ["serde"] }
@@ -68,7 +68,7 @@ rayon = "1.10"
 regex = "1.11.1"
 serde = { version = "1.0.219", features = ["derive"] }
 serde_json = "1.0.140"
-starknet = { git = "https://github.com/xJonathanLEI/starknet-rs", rev = "ea064f0b51655e4c7b3d382315f0d83cfa17393b"}
+starknet = { git = "https://github.com/xJonathanLEI/starknet-rs", rev = "ea064f0b51655e4c7b3d382315f0d83cfa17393b" }
 starknet-crypto = "0.7.4"
 tempfile = "3.20.0"
 thiserror = "2.0.12"
@@ -121,3 +121,7 @@ paste = "1.0.15"
 strum = "0.27"
 strum_macros = "0.27"
 scarb-oracle-hint-service = { git = "https://github.com/software-mansion/scarb", rev = "210da8dfd0b370f0f1970b33a373f1a7afe6ae33" }
+chrono = "0.4.41"
+tracing-subscriber = { version = "0.3.20", features = ["env-filter"] }
+tracing = "0.1.41"
+tracing-chrome = "0.7.2"
diff --git a/crates/forge-runner/Cargo.toml b/crates/forge-runner/Cargo.toml
@@ -48,3 +48,4 @@ foundry-ui = { path = "../foundry-ui" }
 strum = "0.27"
 strum_macros = "0.27"
 scarb-oracle-hint-service.workspace = true
+tracing.workspace = true
diff --git a/crates/forge-runner/src/gas.rs b/crates/forge-runner/src/gas.rs
@@ -18,6 +18,7 @@ use starknet_api::execution_resources::{GasAmount, GasVector};
 use starknet_api::transaction::EventContent;
 use starknet_api::transaction::fields::GasVectorComputationMode;
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn calculate_used_gas(
     transaction_context: &TransactionContext,
     state: &mut CachedState<ExtendedStateReader>,
diff --git a/crates/forge-runner/src/lib.rs b/crates/forge-runner/src/lib.rs
@@ -103,6 +103,7 @@ pub fn maybe_generate_coverage(
 }
 
 #[must_use]
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn run_for_test_case(
     case: Arc<TestCaseWithResolvedConfig>,
     casm_program: Arc<AssembledProgramWithDebugInfo>,
@@ -137,6 +138,7 @@ pub fn run_for_test_case(
     }
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 fn run_with_fuzzing(
     case: Arc<TestCaseWithResolvedConfig>,
     casm_program: Arc<AssembledProgramWithDebugInfo>,
diff --git a/crates/forge-runner/src/running.rs b/crates/forge-runner/src/running.rs
@@ -58,6 +58,7 @@ pub use syscall_handler::has_segment_arena;
 pub use syscall_handler::syscall_handler_offset;
 
 #[must_use]
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn run_test(
     case: Arc<TestCaseWithResolvedConfig>,
     casm_program: Arc<AssembledProgramWithDebugInfo>,
@@ -87,6 +88,7 @@ pub fn run_test(
     })
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub(crate) fn run_fuzz_test(
     case: Arc<TestCaseWithResolvedConfig>,
     casm_program: Arc<AssembledProgramWithDebugInfo>,
@@ -151,6 +153,7 @@ pub enum RunResult {
 }
 
 #[expect(clippy::too_many_lines)]
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn run_test_case(
     case: &TestCaseWithResolvedConfig,
     casm_program: &AssembledProgramWithDebugInfo,
diff --git a/crates/forge-runner/src/running/execution.rs b/crates/forge-runner/src/running/execution.rs
@@ -10,6 +10,7 @@ use blockifier::transaction::objects::ExecutionResourcesTraits;
 use cairo_vm::vm::runners::cairo_runner::{CairoRunner, ExecutionResources};
 
 // Based on the code from blockifer
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn finalize_execution(
     // region: Modified blockifier code
     runner: &mut CairoRunner,
diff --git a/crates/forge-runner/src/running/setup.rs b/crates/forge-runner/src/running/setup.rs
@@ -30,6 +30,7 @@ pub struct VmExecutionContext<'a> {
 
 // Based on code from https://github.com/starkware-libs/sequencer/blob/e417a9e7d50cbd78065d357763df2fbc2ad41f7c/crates/blockifier/src/execution/entry_point_execution.rs#L122
 // Enough of the logic of this had to be changed that probably it won't be possible to upstream it
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn initialize_execution_context<'a>(
     call: ExecutableCallEntryPoint,
     hints: &'a HashMap<String, Hint>,
diff --git a/crates/forge-runner/src/running/with_config.rs b/crates/forge-runner/src/running/with_config.rs
@@ -21,6 +21,7 @@ use rayon::iter::ParallelIterator;
 use std::{collections::HashMap, sync::Arc};
 use universal_sierra_compiler_api::{SierraType, compile_sierra_at_path};
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn test_target_with_config(
     test_target_raw: TestTargetRaw,
     tracked_resource: &ForgeTrackedResource,
diff --git a/crates/forge/Cargo.toml b/crates/forge/Cargo.toml
@@ -52,6 +52,10 @@ url.workspace = true
 indoc.workspace = true
 derive_more.workspace = true
 foundry-ui = { path = "../foundry-ui" }
+chrono.workspace = true
+tracing-subscriber.workspace = true
+tracing.workspace = true
+tracing-chrome.workspace = true
 
 [[bin]]
 name = "snforge"
diff --git a/crates/forge/src/lib.rs b/crates/forge/src/lib.rs
@@ -264,6 +264,7 @@ pub enum ExitStatus {
     Failure,
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn main_execution(ui: Arc<UI>) -> Result<ExitStatus> {
     let cli = Cli::parse();
 
@@ -325,6 +326,7 @@ pub fn main_execution(ui: Arc<UI>) -> Result<ExitStatus> {
     }
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 fn check_requirements(output_on_success: bool, ui: &UI) -> Result<()> {
     let mut requirements_checker = RequirementsChecker::new(output_on_success);
     requirements_checker.add_requirement(Requirement {
diff --git a/crates/forge/src/main.rs b/crates/forge/src/main.rs
@@ -1,9 +1,11 @@
-use std::sync::Arc;
-
 use forge::{ExitStatus, main_execution};
 use foundry_ui::{UI, components::error::ErrorMessage};
+use std::io::IsTerminal;
+use std::sync::Arc;
+use std::{env, io};
 
 fn main() {
+    let _guard = init_logging();
     let ui = Arc::new(UI::default());
     match main_execution(ui.clone()) {
         Ok(ExitStatus::Success) => std::process::exit(0),
@@ -14,3 +16,83 @@ fn main() {
         }
     };
 }
+
+fn init_logging() -> Option<impl Drop> {
+    use chrono::Local;
+    use std::fs;
+
+    use std::path::PathBuf;
+    use tracing_chrome::ChromeLayerBuilder;
+    use tracing_subscriber::filter::{EnvFilter, LevelFilter, Targets};
+    use tracing_subscriber::fmt::Layer;
+    use tracing_subscriber::fmt::time::Uptime;
+    use tracing_subscriber::prelude::*;
+
+    let mut guard = None;
+
+    let fmt_layer = Layer::new()
+        .with_writer(io::stderr)
+        .with_ansi(io::stderr().is_terminal())
+        .with_timer(Uptime::default())
+        .with_filter(
+            EnvFilter::builder()
+                .with_default_directive(LevelFilter::WARN.into())
+                .with_env_var("SNFORGE_LOG")
+                .from_env_lossy(),
+        );
+
+    let tracing_profile = env::var("SNFORGE_TRACING_PROFILE").ok().is_some_and(|var| {
+        let s = var.as_str();
+        s == "true" || s == "1"
+    });
+
+    let profile_layer = if tracing_profile {
+        let mut path = PathBuf::from(format!(
+            "./snforge-profile-{}.json",
+            Local::now().to_rfc3339()
+        ));
+
+        // Create the file now, so that we early panic, and `fs::canonicalize` will work.
+        let profile_file = fs::File::create(&path).expect("failed to create profile file");
+
+        // Try to canonicalize the path so that it is easier to find the file from logs.
+        if let Ok(canonical) = fs::canonicalize(&path) {
+            path = canonical;
+        }
+
+        eprintln!(
+            "`snforge` run will output tracing profile to: {}",
+            path.display()
+        );
+        eprintln!(
+            "Open that file with https://ui.perfetto.dev (or chrome://tracing) to analyze it"
+        );
+
+        let (profile_layer, profile_layer_guard) = ChromeLayerBuilder::new()
+            .writer(profile_file)
+            .include_args(true)
+            .build();
+
+        // Filter out less important logs because they're too verbose,
+        // and with them the profile file quickly grows to several GBs of data.
+        let profile_layer = profile_layer.with_filter(
+            Targets::new()
+                .with_default(LevelFilter::TRACE)
+                .with_target("salsa", LevelFilter::WARN),
+        );
+
+        guard = Some(profile_layer_guard);
+        Some(profile_layer)
+    } else {
+        None
+    };
+
+    tracing::subscriber::set_global_default(
+        tracing_subscriber::registry()
+            .with(fmt_layer)
+            .with(profile_layer),
+    )
+    .expect("could not set up global logger");
+
+    guard
+}
diff --git a/crates/forge/src/run_tests/package.rs b/crates/forge/src/run_tests/package.rs
@@ -69,6 +69,7 @@ pub struct RunForPackageArgs {
 }
 
 impl RunForPackageArgs {
+    #[tracing::instrument(skip_all, level = "debug")]
     pub fn build(
         package: PackageMetadata,
         scarb_metadata: &Metadata,
@@ -130,6 +131,7 @@ impl RunForPackageArgs {
     }
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 async fn test_package_with_config_resolved(
     test_targets: Vec<TestTargetRaw>,
     fork_targets: &[ForkTarget],
@@ -156,6 +158,7 @@ fn sum_test_cases(test_targets: &[TestTargetWithResolvedConfig]) -> usize {
     test_targets.iter().map(|tc| tc.test_cases.len()).sum()
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub async fn run_for_package(
     RunForPackageArgs {
         test_targets,
diff --git a/crates/forge/src/run_tests/resolve_config.rs b/crates/forge/src/run_tests/resolve_config.rs
@@ -14,6 +14,7 @@ use forge_runner::package_tests::{
 };
 use starknet_api::block::BlockNumber;
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub async fn resolve_config(
     test_target: TestTargetWithConfig,
     fork_targets: &[ForkTarget],
diff --git a/crates/forge/src/run_tests/test_target.rs b/crates/forge/src/run_tests/test_target.rs
@@ -20,6 +20,7 @@ pub enum TestTargetRunResult {
     Interrupted(TestTargetSummary),
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub async fn run_for_test_target(
     tests: TestTargetWithResolvedConfig,
     forge_config: Arc<ForgeConfig>,
diff --git a/crates/forge/src/run_tests/workspace.rs b/crates/forge/src/run_tests/workspace.rs
@@ -27,6 +27,7 @@ use shared::consts::SNFORGE_TEST_FILTER;
 use std::env;
 use std::sync::Arc;
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub async fn run_for_workspace(args: TestArgs, ui: Arc<UI>) -> Result<ExitStatus> {
     match args.color {
         // SAFETY: This runs in a single-threaded environment.
@@ -147,6 +148,7 @@ pub async fn run_for_workspace(args: TestArgs, ui: Arc<UI>) -> Result<ExitStatus
     })
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 fn extract_failed_tests(
     tests_summaries: Vec<TestTargetSummary>,
 ) -> impl Iterator<Item = AnyTestCaseSummary> {
diff --git a/crates/forge/src/scarb.rs b/crates/forge/src/scarb.rs
@@ -37,6 +37,7 @@ pub fn should_compile_starknet_contract_target(
     *scarb_version < MINIMAL_SCARB_VERSION_TO_OPTIMIZE_COMPILATION || no_optimization
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn build_artifacts_with_scarb(
     filter: PackagesFilter,
     features: FeaturesSpec,
@@ -82,6 +83,7 @@ fn build_test_artifacts_with_scarb(
     Ok(())
 }
 
+#[tracing::instrument(skip_all, level = "debug")]
 pub fn load_test_artifacts(
     target_dir: &Utf8Path,
     package: &PackageMetadata,

Original file line number	Diff line number	Diff line change
`@@ -103,6 +103,7 @@ pub fn maybe_generate_coverage(`
`103`	`103`	`}`
`104`	`104`
`105`	`105`	`#[must_use]`
	`106`	`+#[tracing::instrument(skip_all, level = "debug")]`
`106`	`107`	`pub fn run_for_test_case(`
`107`	`108`	`case: Arc<TestCaseWithResolvedConfig>,`
`108`	`109`	`casm_program: Arc<AssembledProgramWithDebugInfo>,`
`@@ -137,6 +138,7 @@ pub fn run_for_test_case(`
`137`	`138`	`}`
`138`	`139`	`}`
`139`	`140`
	`141`	`+#[tracing::instrument(skip_all, level = "debug")]`
`140`	`142`	`fn run_with_fuzzing(`
`141`	`143`	`case: Arc<TestCaseWithResolvedConfig>,`
`142`	`144`	`casm_program: Arc<AssembledProgramWithDebugInfo>,`