Replace `tracing_forest` with custom span formatting

3 files changed, 338 insertions, 44 deletions

diff --git a/src/bootstrap/Cargo.lock b/src/bootstrap/Cargo.lock
index e091c94eb53..f5d04c39d3f 100644
--- a/src/bootstrap/Cargo.lock
+++ b/src/bootstrap/Cargo.lock
@@ -12,12 +12,18 @@ dependencies = [
 ]
 
 [[package]]
-name = "ansi_term"
-version = "0.12.1"
+name = "android-tzdata"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e999941b234f3131b00bc13c22d06e8c5ff726d1b6318ac7eb276997bbb4fef0"
+
+[[package]]
+name = "android_system_properties"
+version = "0.1.5"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2"
+checksum = "819e7219dbd41043ac279b19830f2efc897156490d7fd6ea916720117ee66311"
 dependencies = [
- "winapi",
+ "libc",
 ]
 
 [[package]]
@@ -27,6 +33,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "55cc3b69f167a1ef2e161439aa98aed94e6028e5f9a59be9a6ffb47aef1651f9"
 
 [[package]]
+name = "autocfg"
+version = "1.5.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c08606f8c3cbf4ce6ec8e28fb0014a2c086708fe954eaa885384a6165172e7e8"
+
+[[package]]
 name = "bitflags"
 version = "2.6.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -47,6 +59,7 @@ version = "0.0.0"
 dependencies = [
  "build_helper",
  "cc",
+ "chrono",
  "clap",
  "clap_complete",
  "cmake",
@@ -71,7 +84,6 @@ dependencies = [
  "toml",
  "tracing",
  "tracing-chrome",
- "tracing-forest",
  "tracing-subscriber",
  "walkdir",
  "windows",
@@ -98,6 +110,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "bumpalo"
+version = "3.19.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "46c5e41b57b8bba42a04676d81cb89e9ee8e859a1a66f80a5a72e1cb76b34d43"
+
+[[package]]
 name = "cc"
 version = "1.2.23"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -113,6 +131,20 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
 
 [[package]]
+name = "chrono"
+version = "0.4.41"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c469d952047f47f91b68d1cba3f10d63c11d73e4636f24f08daf0278abf01c4d"
+dependencies = [
+ "android-tzdata",
+ "iana-time-zone",
+ "js-sys",
+ "num-traits",
+ "wasm-bindgen",
+ "windows-link",
+]
+
+[[package]]
 name = "clap"
 version = "4.5.20"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -181,6 +213,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "core-foundation-sys"
+version = "0.8.7"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "773648b94d0e5d620f64f280777445740e61fe701025087ec8b57f45c791888b"
+
+[[package]]
 name = "cpufeatures"
 version = "0.2.15"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -336,6 +374,30 @@ dependencies = [
 ]
 
 [[package]]
+name = "iana-time-zone"
+version = "0.1.63"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b0c919e5debc312ad217002b8048a17b7d83f80703865bbfcfebb0458b0b27d8"
+dependencies = [
+ "android_system_properties",
+ "core-foundation-sys",
+ "iana-time-zone-haiku",
+ "js-sys",
+ "log",
+ "wasm-bindgen",
+ "windows-core",
+]
+
+[[package]]
+name = "iana-time-zone-haiku"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f31827a206f56af32e590ba56d5d2d085f558508192593743f16b2306495269f"
+dependencies = [
+ "cc",
+]
+
+[[package]]
 name = "ignore"
 version = "0.4.23"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -369,6 +431,16 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "49f1f14873335454500d59611f1cf4a4b0f786f9ac11f4312a78e4cf2566695b"
 
 [[package]]
+name = "js-sys"
+version = "0.3.77"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1cfaf33c695fc6e08064efbc1f72ec937429614f25eef83af942d0e227c3a28f"
+dependencies = [
+ "once_cell",
+ "wasm-bindgen",
+]
+
+[[package]]
 name = "junction"
 version = "1.2.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -459,6 +531,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "num-traits"
+version = "0.2.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "071dfc062690e90b734c0b2273ce72ad0ffa95f0c74596bc250dcfd960262841"
+dependencies = [
+ "autocfg",
+]
+
+[[package]]
 name = "objc2-core-foundation"
 version = "0.3.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -621,6 +702,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "rustversion"
+version = "1.0.22"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b39cdef0fa800fc44525c84ccb54a029961a8215f9619753635a9c0d2538d46d"
+
+[[package]]
 name = "ryu"
 version = "1.0.18"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -776,26 +863,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "thiserror"
-version = "1.0.69"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "b6aaf5339b578ea85b50e080feb250a3e8ae8cfcdff9a461c9ec2904bc923f52"
-dependencies = [
- "thiserror-impl",
-]
-
-[[package]]
-name = "thiserror-impl"
-version = "1.0.69"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "4fee6c4efc90059e10f81e6d42c60a18f76588c3d74cb83a0b242a2b6c7504c1"
-dependencies = [
- "proc-macro2",
- "quote",
- "syn",
-]
-
-[[package]]
 name = "thread_local"
 version = "1.1.8"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -858,19 +925,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "tracing-forest"
-version = "0.1.6"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "ee40835db14ddd1e3ba414292272eddde9dad04d3d4b65509656414d1c42592f"
-dependencies = [
- "ansi_term",
- "smallvec",
- "thiserror",
- "tracing",
- "tracing-subscriber",
-]
-
-[[package]]
 name = "tracing-log"
 version = "0.2.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -943,6 +997,64 @@ dependencies = [
 ]
 
 [[package]]
+name = "wasm-bindgen"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1edc8929d7499fc4e8f0be2262a241556cfc54a0bea223790e71446f2aab1ef5"
+dependencies = [
+ "cfg-if",
+ "once_cell",
+ "rustversion",
+ "wasm-bindgen-macro",
+]
+
+[[package]]
+name = "wasm-bindgen-backend"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "2f0a0651a5c2bc21487bde11ee802ccaf4c51935d0d3d42a6101f98161700bc6"
+dependencies = [
+ "bumpalo",
+ "log",
+ "proc-macro2",
+ "quote",
+ "syn",
+ "wasm-bindgen-shared",
+]
+
+[[package]]
+name = "wasm-bindgen-macro"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "7fe63fc6d09ed3792bd0897b314f53de8e16568c2b3f7982f468c0bf9bd0b407"
+dependencies = [
+ "quote",
+ "wasm-bindgen-macro-support",
+]
+
+[[package]]
+name = "wasm-bindgen-macro-support"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8ae87ea40c9f689fc23f209965b6fb8a99ad69aeeb0231408be24920604395de"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+ "wasm-bindgen-backend",
+ "wasm-bindgen-shared",
+]
+
+[[package]]
+name = "wasm-bindgen-shared"
+version = "0.2.100"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1a05d73b933a847d6cccdda8f838a22ff101ad9bf93e33684f39c1f5f0eece3d"
+dependencies = [
+ "unicode-ident",
+]
+
+[[package]]
 name = "winapi"
 version = "0.3.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/src/bootstrap/Cargo.toml b/src/bootstrap/Cargo.toml
index ecb332eb7e3..ae5a5d798e5 100644
--- a/src/bootstrap/Cargo.toml
+++ b/src/bootstrap/Cargo.toml
@@ -7,7 +7,7 @@ default-run = "bootstrap"
 
 [features]
 build-metrics = ["sysinfo"]
-tracing = ["dep:tracing", "dep:tracing-chrome", "dep:tracing-subscriber", "dep:tracing-forest", "dep:tempfile"]
+tracing = ["dep:tracing", "dep:tracing-chrome", "dep:tracing-subscriber", "dep:chrono", "dep:tempfile"]
 
 [lib]
 path = "src/lib.rs"
@@ -61,10 +61,10 @@ xz2 = "0.1"
 sysinfo = { version = "0.36.0", default-features = false, optional = true, features = ["system"] }
 
 # Dependencies needed by the `tracing` feature
+chrono = { version = "0.4", optional = true }
 tracing = { version = "0.1", optional = true, features = ["attributes"] }
 tracing-chrome = { version = "0.7", optional = true }
 tracing-subscriber = { version = "0.3", optional = true, features = ["env-filter", "fmt", "registry", "std"] }
-tracing-forest = { version = "0.1.6", optional = true, default-features =  false, features = ["smallvec", "ansi", "env-filter"] }
 tempfile = { version = "3.15.0", optional = true }
 
 [target.'cfg(windows)'.dependencies.junction]
diff --git a/src/bootstrap/src/bin/main.rs b/src/bootstrap/src/bin/main.rs
index a078a519b85..a98fc447e89 100644
--- a/src/bootstrap/src/bin/main.rs
+++ b/src/bootstrap/src/bin/main.rs
@@ -263,16 +263,198 @@ fn check_version(config: &Config) -> Option<String> {
 //   "tracing", instrument(..))]`.
 #[cfg(feature = "tracing")]
 fn setup_tracing(profiling_enabled: bool) -> Option<TracingGuard> {
+    use std::fmt::Debug;
     use std::fs::File;
     use std::io::BufWriter;
+    use std::sync::atomic::{AtomicU32, Ordering};
 
-    use tracing_forest::ForestLayer;
-    use tracing_subscriber::EnvFilter;
-    use tracing_subscriber::layer::SubscriberExt;
+    use chrono::{DateTime, Utc};
+    use tracing::field::{Field, Visit};
+    use tracing::{Event, Id, Level, Subscriber};
+    use tracing_subscriber::layer::{Context, SubscriberExt};
+    use tracing_subscriber::registry::{LookupSpan, SpanRef};
+    use tracing_subscriber::{EnvFilter, Layer};
 
     let filter = EnvFilter::from_env("BOOTSTRAP_TRACING");
 
-    let registry = tracing_subscriber::registry().with(filter).with(ForestLayer::default());
+    #[derive(Default)]
+    struct FieldValues {
+        message: Option<String>,
+        fields: Vec<(&'static str, String)>,
+    }
+
+    impl Visit for FieldValues {
+        fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
+            if field.name() == "message" {
+                self.message = Some(format!("{value:?}"));
+            } else {
+                self.fields.push((field.name(), format!("{value:?}")));
+            }
+        }
+    }
+
+    #[derive(Copy, Clone)]
+    enum SpanAction {
+        Enter,
+    }
+
+    #[derive(Default)]
+    struct TracingPrinter {
+        indent: AtomicU32,
+        span_values: std::sync::Mutex<std::collections::HashMap<tracing::Id, FieldValues>>,
+    }
+
+    impl TracingPrinter {
+        fn format_header<W: Write>(
+            &self,
+            writer: &mut W,
+            time: DateTime<Utc>,
+            level: &Level,
+        ) -> std::io::Result<()> {
+            // Use a fixed-width timestamp without date, that shouldn't be very important
+            let timestamp = time.format("%H:%M:%S.%3f");
+            write!(writer, "{timestamp} ")?;
+            // Make sure that levels are aligned to the same number of characters, in order not to
+            // break the layout
+            write!(writer, "{level:>5} ")?;
+            write!(writer, "{}", " ".repeat(self.indent.load(Ordering::Relaxed) as usize))
+        }
+
+        fn write_event<W: Write>(&self, writer: &mut W, event: &Event<'_>) -> std::io::Result<()> {
+            let now = Utc::now();
+
+            self.format_header(writer, now, event.metadata().level())?;
+
+            let mut field_values = FieldValues::default();
+            event.record(&mut field_values);
+
+            if let Some(msg) = &field_values.message {
+                write!(writer, "{msg}")?;
+            }
+
+            if !field_values.fields.is_empty() {
+                if field_values.message.is_some() {
+                    write!(writer, " ")?;
+                }
+                write!(writer, "[")?;
+                for (index, (name, value)) in field_values.fields.iter().enumerate() {
+                    write!(writer, "{name} = {value}")?;
+                    if index < field_values.fields.len() - 1 {
+                        write!(writer, ", ")?;
+                    }
+                }
+                write!(writer, "]")?;
+            }
+            write_location(writer, event.metadata())?;
+            writeln!(writer)?;
+            Ok(())
+        }
+
+        fn write_span<W: Write, S>(
+            &self,
+            writer: &mut W,
+            span: SpanRef<'_, S>,
+            field_values: Option<&FieldValues>,
+            action: SpanAction,
+        ) -> std::io::Result<()>
+        where
+            S: for<'lookup> LookupSpan<'lookup>,
+        {
+            let now = Utc::now();
+
+            self.format_header(writer, now, span.metadata().level())?;
+            match action {
+                SpanAction::Enter => {
+                    write!(writer, "> ")?;
+                }
+            }
+
+            write!(writer, "{}", span.name())?;
+            if let Some(values) = field_values.filter(|v| !v.fields.is_empty()) {
+                write!(writer, " [")?;
+                for (index, (name, value)) in values.fields.iter().enumerate() {
+                    write!(writer, "{name} = {value}")?;
+                    if index < values.fields.len() - 1 {
+                        write!(writer, ", ")?;
+                    }
+                }
+                write!(writer, "]")?;
+            }
+
+            write_location(writer, span.metadata())?;
+            writeln!(writer)?;
+            Ok(())
+        }
+    }
+
+    fn write_location<W: Write>(
+        writer: &mut W,
+        metadata: &'static tracing::Metadata<'static>,
+    ) -> std::io::Result<()> {
+        use std::path::{Path, PathBuf};
+
+        if let Some(filename) = metadata.file() {
+            // Keep only the module name and file name to make it shorter
+            let filename: PathBuf = Path::new(filename)
+                .components()
+                // Take last two path components
+                .rev()
+                .take(2)
+                .collect::<Vec<_>>()
+                .into_iter()
+                .rev()
+                .collect();
+
+            write!(writer, " ({}", filename.display())?;
+            if let Some(line) = metadata.line() {
+                write!(writer, ":{line}")?;
+            }
+            write!(writer, ")")?;
+        }
+        Ok(())
+    }
+
+    impl<S> Layer<S> for TracingPrinter
+    where
+        S: Subscriber,
+        S: for<'lookup> LookupSpan<'lookup>,
+    {
+        fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
+            let mut writer = std::io::stderr().lock();
+            self.write_event(&mut writer, event).unwrap();
+        }
+
+        fn on_new_span(
+            &self,
+            attrs: &tracing::span::Attributes<'_>,
+            id: &Id,
+            _ctx: Context<'_, S>,
+        ) {
+            // Record value of span fields
+            // Note that we do not implement changing values of span fields after they are created.
+            // For that we would also need to implement the `on_record` method
+
+            let mut field_values = FieldValues::default();
+            attrs.record(&mut field_values);
+            self.span_values.lock().unwrap().insert(id.clone(), field_values);
+        }
+
+        fn on_enter(&self, id: &Id, ctx: Context<'_, S>) {
+            if let Some(span) = ctx.span(id) {
+                let mut writer = std::io::stderr().lock();
+                let values = self.span_values.lock().unwrap();
+                let values = values.get(id);
+                self.write_span(&mut writer, span, values, SpanAction::Enter).unwrap();
+            }
+            self.indent.fetch_add(1, Ordering::Relaxed);
+        }
+
+        fn on_exit(&self, _id: &Id, _ctx: Context<'_, S>) {
+            self.indent.fetch_sub(1, Ordering::Relaxed);
+        }
+    }
+
+    let registry = tracing_subscriber::registry().with(filter).with(TracingPrinter::default());
 
     let guard = if profiling_enabled {
         // When we're creating this layer, we do not yet know the location of the tracing output