diff --git a/Cargo.lock b/Cargo.lock index 123a855199..ad418c4ebc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5321,6 +5321,7 @@ dependencies = [ "indicatif", "itertools 0.14.0", "parking_lot", + "pixi_build_frontend", "pixi_command_dispatcher", "pixi_git", "pixi_progress", @@ -5329,6 +5330,8 @@ dependencies = [ "rattler_conda_types", "rattler_repodata_gateway", "regex", + "serde", + "serde_json", "tokio", "tracing", "url", diff --git a/crates/pixi_build_frontend/src/backend/logs.rs b/crates/pixi_build_frontend/src/backend/logs.rs new file mode 100644 index 0000000000..39657ed397 --- /dev/null +++ b/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, +} + +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> { + match serde_json::from_str::(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 { + fields + .iter() + .filter_map(|(key, value)| { + if key == "message" { + return None; + } + Some(format!("{}={}", key, value_to_string(value))) + }) + .collect::>() + .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 = arr.iter().map(value_to_string).collect(); + format!("[{}]", parts.join(",")) + } + JsonValue::Object(obj) => { + let parts: Vec = 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) -> Option { + 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 { + 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, + extra_fields: &mut Map, +) -> Option { + 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) -> Option { + 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) + ); + } +} diff --git a/crates/pixi_build_frontend/src/backend/mod.rs b/crates/pixi_build_frontend/src/backend/mod.rs index 59e911cc11..57cb6cdb69 100644 --- a/crates/pixi_build_frontend/src/backend/mod.rs +++ b/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); } diff --git a/crates/pixi_build_frontend/src/backend/stderr.rs b/crates/pixi_build_frontend/src/backend/stderr.rs index 050078ebfe..2b46144c6e 100644 --- a/crates/pixi_build_frontend/src/backend/stderr.rs +++ b/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( cancel: oneshot::Receiver<()>, mut on_log: W, ) -> Result { + 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); } diff --git a/crates/pixi_build_frontend/src/lib.rs b/crates/pixi_build_frontend/src/lib.rs index 8db5c88077..6ef79cc5eb 100644 --- a/crates/pixi_build_frontend/src/lib.rs +++ b/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; diff --git a/crates/pixi_build_frontend/tests/otlp_sample.json b/crates/pixi_build_frontend/tests/otlp_sample.json new file mode 100644 index 0000000000..f6ffcb0c38 --- /dev/null +++ b/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"}}]}]}]}]}]} diff --git a/crates/pixi_build_frontend/tests/tracing_flattened_sample.json b/crates/pixi_build_frontend/tests/tracing_flattened_sample.json new file mode 100644 index 0000000000..b60eb27870 --- /dev/null +++ b/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"}]} diff --git a/crates/pixi_build_frontend/tests/tracing_sample.json b/crates/pixi_build_frontend/tests/tracing_sample.json new file mode 100644 index 0000000000..2eef9d94c3 --- /dev/null +++ b/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"}]} diff --git a/crates/pixi_build_frontend/tests/tracing_span_sample.json b/crates/pixi_build_frontend/tests/tracing_span_sample.json new file mode 100644 index 0000000000..4b465a61cc --- /dev/null +++ b/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"}]} diff --git a/crates/pixi_cli/src/lib.rs b/crates/pixi_cli/src/lib.rs index c67fb89e42..a089e55532 100644 --- a/crates/pixi_cli/src/lib.rs +++ b/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,7 +312,7 @@ 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 { @@ -315,7 +320,7 @@ fn setup_logging(args: &Args, use_colors: bool) -> miette::Result<()> { // 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() { diff --git a/crates/pixi_command_dispatcher/src/backend_source_build/mod.rs b/crates/pixi_command_dispatcher/src/backend_source_build/mod.rs index 70aaf4e503..99f89ed303 100644 --- a/crates/pixi_command_dispatcher/src/backend_source_build/mod.rs +++ b/crates/pixi_command_dispatcher/src/backend_source_build/mod.rs @@ -149,6 +149,16 @@ impl BackendSourceBuildSpec { channel_config: ChannelConfig, mut log_sink: UnboundedSender, ) -> Result> { + 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 { diff --git a/crates/pixi_command_dispatcher/src/source_build/mod.rs b/crates/pixi_command_dispatcher/src/source_build/mod.rs index 5fdd10d817..1a94285934 100644 --- a/crates/pixi_command_dispatcher/src/source_build/mod.rs +++ b/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 diff --git a/crates/pixi_reporters/Cargo.toml b/crates/pixi_reporters/Cargo.toml index 5c3bae6a28..12e2e89aff 100644 --- a/crates/pixi_reporters/Cargo.toml +++ b/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 } diff --git a/crates/pixi_reporters/src/sync_reporter.rs b/crates/pixi_reporters/src/sync_reporter.rs index 432f00b962..0c8766e1fb 100644 --- a/crates/pixi_reporters/src/sync_reporter.rs +++ b/crates/pixi_reporters/src/sync_reporter.rs @@ -21,7 +21,6 @@ use crate::{ #[derive(Clone)] pub struct SyncReporter { - multi_progress: MultiProgress, combined_inner: Arc>, } @@ -34,10 +33,7 @@ impl SyncReporter { multi_progress.clone(), progress_bar_placement, ))); - Self { - multi_progress, - combined_inner, - } + Self { combined_inner } } pub fn clear(&mut self) { @@ -95,8 +91,6 @@ impl BackendSourceBuildReporter for SyncReporter { // Enable streaming of the logs from the backend let print_backend_output = tracing::event_enabled!(tracing::Level::WARN); // Stream the progress of the output to the screen. - let progress_bar = self.multi_progress.clone(); - // Create a sender to buffer the output lines so we can output them later if // needed. let (tx, rx) = tokio::sync::mpsc::unbounded_channel::(); @@ -107,15 +101,8 @@ impl BackendSourceBuildReporter for SyncReporter { tokio::spawn(async move { while let Some(line) = backend_output_stream.next().await { - if print_backend_output { - // Suspend the main progress bar while we print the line. - progress_bar.suspend(|| eprintln!("{line}")); - } else { - // Send the line to the receiver - if tx.send(line).is_err() { - // Receiver dropped, exit early - break; - } + if !print_backend_output && tx.send(line).is_err() { + break; } } }); @@ -130,15 +117,9 @@ impl BackendSourceBuildReporter for SyncReporter { }; // If the build failed, we want to print the output from the backend. - let progress_bar = self.multi_progress.clone(); if failed { if let Some(mut build_output_receiver) = build_output_receiver { - tokio::spawn(async move { - while let Some(line) = build_output_receiver.recv().await { - // Suspend the main progress bar while we print the line. - progress_bar.suspend(|| eprintln!("{line}")); - } - }); + tokio::spawn(async move { while build_output_receiver.recv().await.is_some() {} }); } } } @@ -162,7 +143,6 @@ impl SourceBuildReporter for SyncReporter { ) { // Notify the progress bar that the build has started. let print_backend_output = tracing::event_enabled!(tracing::Level::WARN); - let progress_bar = self.multi_progress.clone(); let (tx, rx) = tokio::sync::mpsc::unbounded_channel::(); { @@ -175,9 +155,7 @@ impl SourceBuildReporter for SyncReporter { tokio::spawn(async move { while let Some(line) = backend_output_stream.next().await { - if print_backend_output { - progress_bar.suspend(|| eprintln!("{line}")); - } else if tx.send(line).is_err() { + if !print_backend_output && tx.send(line).is_err() { break; } } @@ -192,13 +170,8 @@ impl SourceBuildReporter for SyncReporter { }; if failed { - let progress_bar = self.multi_progress.clone(); if let Some(mut build_output_receiver) = build_output_receiver { - tokio::spawn(async move { - while let Some(line) = build_output_receiver.recv().await { - progress_bar.suspend(|| eprintln!("{line}")); - } - }); + tokio::spawn(async move { while build_output_receiver.recv().await.is_some() {} }); } } } diff --git a/examples/pixi-build/cpp-sdl/pixi.toml b/examples/pixi-build/cpp-sdl/pixi.toml index 280ba165a9..c4463100c8 100644 --- a/examples/pixi-build/cpp-sdl/pixi.toml +++ b/examples/pixi-build/cpp-sdl/pixi.toml @@ -21,6 +21,9 @@ description = "Showcases how to create a simple C++ executable with Pixi" name = "sdl_example" version = "0.1.0" +[package.build.config] +debug-dir = "./debug" + [package.build.backend] channels = [ "https://prefix.dev/pixi-build-backends",