feat(build): special handling for backends tracing output

crates/pixi_build_frontend/src/backend/logs.rs

@@ -0,0 +1,237 @@
+use serde_json::{Map, Value as JsonValue};
+use tracing::Level;
+
+const BACKEND_EVENT_TARGET: &str = "pixi::backend";
+
+#[derive(Debug, Clone)]
+pub struct BackendLogEntry {
+    level: Level,
+    target: String,
+    message: String,
+    extra: Map<String, JsonValue>,
+}
+
+impl BackendLogEntry {
+    pub fn emit(&self) {
+        let formatted_message = if self.extra.is_empty() {
+            self.message.clone()
+        } else {
+            format!("{} {}", self.message, format_fields(&self.extra))
+        };
+
+        match self.level {
+            Level::TRACE => {
+                tracing::event!(target: BACKEND_EVENT_TARGET, Level::TRACE, backend_target = %self.target, "{formatted_message}")
+            }
+            Level::DEBUG => {
+                tracing::event!(target: BACKEND_EVENT_TARGET, Level::DEBUG, backend_target = %self.target, "{formatted_message}")
+            }
+            Level::INFO => {
+                tracing::event!(target: BACKEND_EVENT_TARGET, Level::INFO, backend_target = %self.target, "{formatted_message}")
+            }
+            Level::WARN => {
+                tracing::event!(target: BACKEND_EVENT_TARGET, Level::WARN, backend_target = %self.target, "{formatted_message}")
+            }
+            Level::ERROR => {
+                tracing::event!(target: BACKEND_EVENT_TARGET, Level::ERROR, backend_target = %self.target, "{formatted_message}")
+            }
+        }
+    }
+}
+
+pub fn parse_backend_logs(line: &str) -> Option<Vec<BackendLogEntry>> {
+    match serde_json::from_str::<JsonValue>(line) {
+        Ok(JsonValue::Object(map)) => {
+            BackendLogEntry::from_tracing_fields(map).map(|entry| vec![entry])
+        }
+        Ok(_) => None,
+        Err(err) => {
+            tracing::debug!(target: "pixi::backend_logs", "Failed to parse tracing JSON line: {err}");
+            None
+        }
+    }
+}
+
+fn format_fields(fields: &Map<String, JsonValue>) -> String {
+    fields
+        .iter()
+        .filter_map(|(key, value)| {
+            if key == "message" {
+                return None;
+            }
+            Some(format!("{}={}", key, value_to_string(value)))
+        })
+        .collect::<Vec<_>>()
+        .join(" ")
+}
+
+fn value_to_string(value: &JsonValue) -> String {
+    match value {
+        JsonValue::String(v) => maybe_quote(v),
+        JsonValue::Number(num) => num.to_string(),
+        JsonValue::Bool(b) => b.to_string(),
+        JsonValue::Array(arr) => {
+            let parts: Vec<String> = arr.iter().map(value_to_string).collect();
+            format!("[{}]", parts.join(","))
+        }
+        JsonValue::Object(obj) => {
+            let parts: Vec<String> = obj
+                .iter()
+                .map(|(k, v)| format!("{}={}", k, value_to_string(v)))
+                .collect();
+            format!("{{{}}}", parts.join(","))
+        }
+        JsonValue::Null => "null".to_string(),
+    }
+}
+
+fn maybe_quote(value: &str) -> String {
+    if value.chars().any(|c| c.is_whitespace()) {
+        format!("\"{}\"", value.replace('"', "\\\""))
+    } else {
+        value.to_string()
+    }
+}
+
+impl BackendLogEntry {
+    fn from_tracing_fields(mut map: Map<String, JsonValue>) -> Option<Self> {
+        let level = map
+            .remove("level")
+            .and_then(|value| value.as_str().and_then(parse_level))
+            .unwrap_or(Level::INFO);
+
+        let target = map
+            .remove("target")
+            .and_then(|value| value.as_str().map(|s| s.to_string()))
+            .unwrap_or_else(|| "pixi-build-backend".to_string());
+
+        let mut extra = Map::new();
+        let mut message = take_message_from_fields(map.remove("fields"), &mut extra);
+
+        if message.is_none() {
+            if let Some(value) = map.remove("message") {
+                message = Some(stringify_value(value));
+            }
+        } else {
+            map.remove("message");
+        }
+
+        for (key, value) in map.into_iter() {
+            if is_reserved_top_level_field(&key) {
+                continue;
+            }
+            extra.insert(key, value);
+        }
+
+        Some(Self {
+            level,
+            target,
+            message: message.unwrap_or_default(),
+            extra,
+        })
+    }
+}
+
+fn parse_level(value: &str) -> Option<Level> {
+    match value.to_ascii_uppercase().as_str() {
+        "TRACE" => Some(Level::TRACE),
+        "DEBUG" => Some(Level::DEBUG),
+        "INFO" => Some(Level::INFO),
+        "WARN" | "WARNING" => Some(Level::WARN),
+        "ERROR" => Some(Level::ERROR),
+        _ => None,
+    }
+}
+
+fn take_message_from_fields(
+    fields_value: Option<JsonValue>,
+    extra_fields: &mut Map<String, JsonValue>,
+) -> Option<String> {
+    let mut message = None;
+    if let Some(JsonValue::Object(mut fields)) = fields_value {
+        message = take_message(&mut fields);
+        for (key, value) in fields.into_iter() {
+            extra_fields.insert(key, value);
+        }
+    }
+    message
+}
+
+fn take_message(fields: &mut Map<String, JsonValue>) -> Option<String> {
+    if let Some(value) = fields.remove("message") {
+        return Some(stringify_value(value));
+    }
+    None
+}
+
+fn stringify_value(value: JsonValue) -> String {
+    match value {
+        JsonValue::String(s) => s,
+        JsonValue::Null => "null".to_string(),
+        other => value_to_string(&other),
+    }
+}
+
+fn is_reserved_top_level_field(key: &str) -> bool {
+    matches!(
+        key,
+        "timestamp"
+            | "level"
+            | "target"
+            | "threadName"
+            | "threadId"
+            | "filename"
+            | "line_number"
+            | "span"
+            | "spans"
+    )
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn parses_tracing_json_line() {
+        let sample = include_str!("../../tests/tracing_sample.json");
+        let entries = parse_backend_logs(sample).expect("failed to parse tracing sample");
+        assert_eq!(entries.len(), 1);
+        let entry = &entries[0];
+        assert_eq!(entry.level, Level::INFO);
+        assert_eq!(entry.target, "pixi_build_backend::intermediate_backend");
+        assert_eq!(entry.message, "sample message");
+        assert!(entry.extra.contains_key("path"));
+    }
+
+    #[test]
+    fn parses_flattened_tracing_line() {
+        let sample = include_str!("../../tests/tracing_flattened_sample.json");
+        let entries = parse_backend_logs(sample).expect("failed to parse flattened sample");
+        assert_eq!(entries.len(), 1);
+        let entry = &entries[0];
+        assert_eq!(entry.level, Level::DEBUG);
+        assert_eq!(entry.target, "pixi_build_backend::flattened");
+        assert_eq!(entry.message, "flattened message");
+        assert_eq!(
+            entry.extra.get("answer").and_then(|value| value.as_i64()),
+            Some(42)
+        );
+        assert!(!entry.extra.contains_key("timestamp"));
+        assert!(!entry.extra.contains_key("threadName"));
+    }
+
+    #[test]
+    fn parses_span_metadata_line() {
+        let sample = include_str!("../../tests/tracing_span_sample.json");
+        let entries = parse_backend_logs(sample).expect("failed to parse span sample");
+        assert_eq!(entries.len(), 1);
+        let entry = &entries[0];
+        assert_eq!(entry.level, Level::INFO);
+        assert_eq!(entry.target, "pixi_build_backend::span");
+        assert_eq!(entry.message, "span event");
+        assert_eq!(
+            entry.extra.get("busy_ns").and_then(|value| value.as_i64()),
+            Some(123)
+        );
+    }
+}

crates/pixi_build_frontend/src/backend/mod.rs

@@ -172,6 +172,8 @@ impl Backend {
     }
 }
 
+pub mod logs;
+
 pub trait BackendOutputStream {
     fn on_line(&mut self, line: String);
 }

crates/pixi_build_frontend/src/backend/stderr.rs

@@ -1,6 +1,6 @@
-use std::sync::Arc;
+use std::{fs::OpenOptions, io::Write, sync::Arc};
 
-use crate::BackendOutputStream;
+use crate::{BackendOutputStream, backend::logs::parse_backend_logs};
 use tokio::{
     io::{BufReader, Lines},
     process::ChildStderr,
@@ -14,12 +14,31 @@ pub(crate) async fn stream_stderr<W: BackendOutputStream>(
     cancel: oneshot::Receiver<()>,
     mut on_log: W,
 ) -> Result<String, std::io::Error> {
+    let dump_raw_path = std::env::var_os("PIXI_DUMP_BACKEND_RAW");
+
     // Create a future that continuously read from the buffer and stores the lines
     // until all data is received.
     let mut lines = Vec::new();
     let read_and_buffer = async {
         let mut buffer = buffer.lock().await;
         while let Some(line) = buffer.next_line().await? {
+            if let Some(path) = dump_raw_path.as_ref() {
+                let _ = OpenOptions::new()
+                    .create(true)
+                    .append(true)
+                    .open(path)
+                    .and_then(|mut file| writeln!(file, "{line}"));
+            }
+
+            if let Some(entries) = parse_backend_logs(&line) {
+                for entry in entries {
+                    entry.emit();
+                }
+                on_log.on_line(line.clone());
+                lines.push(line);
+                continue;
+            }
+
             on_log.on_line(line.clone());
             lines.push(line);
         }

crates/pixi_build_frontend/src/lib.rs

@@ -1,7 +1,7 @@
 mod backend_override;
 mod jsonrpc;
 
-mod backend;
+pub mod backend;
 pub mod error;
 pub mod tool;
 

crates/pixi_build_frontend/tests/otlp_sample.json

@@ -0,0 +1 @@
+{"resourceSpans":[{"resource":{"attributes":[{"key":"telemetry.sdk.version","value":{"stringValue":"0.31.0"}},{"key":"telemetry.sdk.language","value":{"stringValue":"rust"}},{"key":"telemetry.sdk.name","value":{"stringValue":"opentelemetry"}},{"key":"service.name","value":{"stringValue":"pixi-build-backend"}}]},"scopeSpans":[{"scope":{"name":"pixi-build-backend"},"spans":[{"traceId":"4c113524259afec826e8687a47ab56ff","spanId":"fb54f5fa931c8780","parentSpanId":"dcfaa5625800da8f","flags":257,"name":"Fetching source code","kind":1,"startTimeUnixNano":"1763547699215925758","endTimeUnixNano":"1763547699215952548","attributes":[{"key":"code.file.path","value":{"stringValue":"/home/remi/.cargo/git/checkouts/rattler-build-5c6d2407a545b614/d4d9a38/src/source/mod.rs"}},{"key":"code.module.name","value":{"stringValue":"rattler_build::source"}},{"key":"code.line.number","value":{"intValue":"364"}},{"key":"thread.id","value":{"intValue":"1"}},{"key":"thread.name","value":{"stringValue":"main"}},{"key":"target","value":{"stringValue":"rattler_build::source"}},{"key":"busy_ns","value":{"intValue":"25538"}},{"key":"idle_ns","value":{"intValue":"1813"}}],"events":[{"name":"No sources to fetch","timeUnixNano":"1763547699215934234","attributes":[{"key":"level","value":{"stringValue":"INFO"}},{"key":"target","value":{"stringValue":"rattler_build::source"}},{"key":"code.file.path","value":{"stringValue":"/home/remi/.cargo/git/checkouts/rattler-build-5c6d2407a545b614/d4d9a38/src/source/mod.rs"}},{"key":"code.module.name","value":{"stringValue":"rattler_build::source"}},{"key":"code.line.number","value":{"intValue":"303"}}]}]}]}]}]}

crates/pixi_build_frontend/tests/tracing_flattened_sample.json

@@ -0,0 +1 @@
+{"timestamp":"fake time","level":"DEBUG","target":"pixi_build_backend::flattened","message":"flattened message","answer":42,"threadName":"main","spans":[{"name":"flattened_span","context":"demo"}]}

crates/pixi_build_frontend/tests/tracing_sample.json

@@ -0,0 +1 @@
+{"level":"INFO","fields":{"message":"sample message","path":"./debug"},"target":"pixi_build_backend::intermediate_backend","spans":[{"name":"solve","package":"sdl_example","platform":"linux-64"}]}

crates/pixi_build_frontend/tests/tracing_span_sample.json

@@ -0,0 +1 @@
+{"level":"INFO","target":"pixi_build_backend::span","fields":{"message":"span event","busy_ns":123},"span":{"name":"solve","context":"pkg=sdl_example"},"spans":[{"name":"solve","pkg":"sdl_example"}]}

crates/pixi_cli/src/lib.rs

@@ -295,6 +295,11 @@ fn setup_logging(args: &Args, use_colors: bool) -> miette::Result<()> {
         LevelFilter::DEBUG => (LevelFilter::INFO, LevelFilter::DEBUG, LevelFilter::TRACE),
         LevelFilter::TRACE => (LevelFilter::TRACE, LevelFilter::TRACE, LevelFilter::TRACE),
     };
+    let backend_level = if level_filter >= LevelFilter::INFO {
+        pixi_level
+    } else {
+        LevelFilter::WARN
+    };
 
     // Check if CLI verbosity flags were explicitly set
     let cli_verbosity_set = args.global_options.verbose > 0 || args.global_options.quiet > 0;
@@ -307,15 +312,15 @@ fn setup_logging(args: &Args, use_colors: bool) -> miette::Result<()> {
         EnvFilter::builder()
             .with_default_directive(level_filter.into())
             .parse(format!(
-                "apple_codesign=off,pixi={pixi_level},pixi_command_dispatcher={pixi_level},pixi_core={pixi_level},uv_resolver={pixi_level},resolvo={low_level_filter}"
+                "apple_codesign=off,pixi={pixi_level},pixi_command_dispatcher={pixi_level},pixi_core={pixi_level},uv_resolver={pixi_level},resolvo={low_level_filter},pixi_build_backend={backend_level},pixi_build_cmake={backend_level},pixi_build_python={backend_level},pixi_build_rattler_build={backend_level},pixi_build_rust={backend_level},pixi_build_mojo={backend_level},pixi_build_ros={backend_level},rattler_build={backend_level}"
             ))
             .into_diagnostic()?
     } else {
         // No CLI flags - use RUST_LOG if set
         // Parse RUST_LOG because we need to set it other our other directives
         let env_directives = env::var("RUST_LOG").unwrap_or_default();
         let original_directives = format!(
-            "apple_codesign=off,pixi={pixi_level},pixi_command_dispatcher={pixi_level},pixi_core={pixi_level},uv_resolver={pixi_level},resolvo={low_level_filter}",
+            "apple_codesign=off,pixi={pixi_level},pixi_command_dispatcher={pixi_level},pixi_core={pixi_level},uv_resolver={pixi_level},resolvo={low_level_filter},pixi_build_backend={backend_level},pixi_build_cmake={backend_level},pixi_build_python={backend_level},pixi_build_rattler_build={backend_level},pixi_build_rust={backend_level},pixi_build_mojo={backend_level},pixi_build_ros={backend_level},rattler_build={backend_level}",
         );
         // Concatenate both directives where the LOG overrides the potential original directives
         let final_directives = if env_directives.is_empty() {

crates/pixi_command_dispatcher/src/backend_source_build/mod.rs

@@ -149,6 +149,16 @@ impl BackendSourceBuildSpec {
         channel_config: ChannelConfig,
         mut log_sink: UnboundedSender<String>,
     ) -> Result<BackendBuiltSource, CommandDispatcherError<BackendSourceBuildError>> {
+        let backend_span = tracing::info_span!(
+            target: "pixi::backend",
+            "backend-build",
+            backend = backend.identifier(),
+            package = %record.name.as_normalized(),
+            version = %record.version,
+            build = %record.build,
+        );
+        let _backend_guard = backend_span.enter();
+
         let built_package = backend
             .conda_build_v1(
                 CondaBuildV1Params {

crates/pixi_command_dispatcher/src/source_build/mod.rs

@@ -503,6 +503,16 @@ impl SourceBuildSpec {
         let host_platform = self.build_environment.host_platform;
         let build_platform = self.build_environment.build_platform;
 
+        let backend_span = tracing::info_span!(
+            target: "pixi::backend",
+            "backend-build",
+            backend = backend.identifier(),
+            package = %self.package.name.as_normalized(),
+            version = %self.package.version,
+            build = %self.package.build,
+        );
+        let _backend_guard = backend_span.enter();
+
         // Request the metadata from the backend.
         // TODO: Can we somehow cache this metadata?
         let outputs = backend

crates/pixi_reporters/Cargo.toml

@@ -25,9 +25,12 @@ indicatif = { workspace = true }
 # Utilities
 human_bytes = { workspace = true }
 regex = { workspace = true }
+serde = { workspace = true, features = ["derive"] }
+serde_json = { workspace = true }
 tracing = { workspace = true }
 
 # Pixi ecosystem
+pixi_build_frontend = { workspace = true }
 pixi_command_dispatcher = { workspace = true }
 pixi_git = { workspace = true }
 pixi_progress = { workspace = true }