diff --git a/CHANGELOG.md b/CHANGELOG.md index 34926a6..e49967d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 annoying to repeatedly enter your password for key deployment. - Ipv6 addresses are now displayed in a nicer format in "Authenticate for ..." prompts. +- Build logs from `-L` are now properly traced and logged alongside the build + job name. ### Fixed diff --git a/crates/cli/src/tracing_setup.rs b/crates/cli/src/tracing_setup.rs index c057a8c..b8bcd2a 100644 --- a/crates/cli/src/tracing_setup.rs +++ b/crates/cli/src/tracing_setup.rs @@ -13,7 +13,7 @@ use tracing_subscriber::{ field::{RecordFields, VisitFmt}, fmt::{ FormatEvent, FormatFields, FormattedFields, - format::{self, DefaultFields, DefaultVisitor, Format, Full}, + format::{self, DefaultVisitor, Format, Full}, }, layer::{Context, SubscriberExt}, registry::LookupSpan, @@ -48,30 +48,30 @@ impl Write for NonClobberingWriter { /// passed. struct WireEventFormat(Format); /// Formats the node's name with `WireFieldVisitor` -struct WireFieldFormat; -struct WireFieldVisitor<'a>(DefaultVisitor<'a>); +struct WireSpanFieldFormat; +struct WireSpanFieldVisitor<'a>(DefaultVisitor<'a>); /// `WireLayer` injects `WireFieldFormat` as an extension on the event struct WireLayer; -impl<'a> WireFieldVisitor<'a> { +impl<'a> WireSpanFieldVisitor<'a> { fn new(writer: format::Writer<'a>, is_empty: bool) -> Self { Self(DefaultVisitor::new(writer, is_empty)) } } -impl<'writer> FormatFields<'writer> for WireFieldFormat { +impl<'writer> FormatFields<'writer> for WireSpanFieldFormat { fn format_fields( &self, writer: format::Writer<'writer>, fields: R, ) -> std::fmt::Result { - let mut v = WireFieldVisitor::new(writer, true); + let mut v = WireSpanFieldVisitor::new(writer, true); fields.record(&mut v); Ok(()) } } -impl tracing::field::Visit for WireFieldVisitor<'_> { +impl tracing::field::Visit for WireSpanFieldVisitor<'_> { fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { if field.name() == "node" { let _ = write!( @@ -118,6 +118,33 @@ where mut writer: tracing_subscriber::fmt::format::Writer<'_>, event: &tracing::Event<'_>, ) -> std::fmt::Result { + struct OrderedFieldsVisitor { + msg: String, + build: String, + other: String, + has_fields: bool, + } + + // deliberately place the build job field before other fields including the + // message + impl tracing::field::Visit for OrderedFieldsVisitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + use std::fmt::Write; + + self.has_fields = true; + if field.name() == "message" || field.name() == "msg" { + self.msg = format!("{value:?}"); + } else if field.name() == "build" { + self.build = format!("{value:?}"); + } else { + if !self.other.is_empty() { + self.other.push_str(", "); + } + let _ = write!(self.other, "{}={value:?}", field.name()); + } + } + } + let metadata = event.metadata(); // skip events without an "event_scope" @@ -140,6 +167,19 @@ where return self.0.format_event(ctx, writer, event); } + let mut visitor = OrderedFieldsVisitor { + msg: String::new(), + build: String::new(), + other: String::new(), + has_fields: false, + }; + event.record(&mut visitor); + + // Skip logging if there's no fields at all + if !visitor.has_fields { + return Ok(()); + } + let style = get_style(*metadata.level()); // write the log level with colour @@ -152,7 +192,7 @@ where // extract the formatted node name into a string let parent_ext = parent.extensions(); let node_name = &parent_ext - .get::>() + .get::>() .unwrap(); write!(writer, "{node_name}")?; @@ -162,14 +202,24 @@ where write!(writer, " {}", step.name().italic())?; } - write!(writer, " | ")?; + if !visitor.build.is_empty() { + write!( + writer, + " {}", + visitor + .build + .if_supports_color(Stream::Stderr, |text| text.dimmed()) + )?; + } - // write the default fields, including the actual message and other data - let mut fields = FormattedFields::::new(String::new()); + if !visitor.msg.is_empty() { + write!(writer, " | {}", visitor.msg)?; + } - ctx.format_fields(fields.as_writer(), event)?; + if !visitor.other.is_empty() { + write!(writer, " | {}", visitor.other)?; + } - write!(writer, "{fields}")?; writeln!(writer)?; Ok(()) @@ -188,12 +238,12 @@ where ) { let span = ctx.span(id).unwrap(); - if span.extensions().get::().is_some() { + if span.extensions().get::().is_some() { return; } - let mut fields = FormattedFields::::new(String::new()); - if WireFieldFormat + let mut fields = FormattedFields::::new(String::new()); + if WireSpanFieldFormat .format_fields(fields.as_writer(), attrs) .is_ok() { diff --git a/crates/core/src/commands/mod.rs b/crates/core/src/commands/mod.rs index 00d9ebe..b23e664 100644 --- a/crates/core/src/commands/mod.rs +++ b/crates/core/src/commands/mod.rs @@ -3,16 +3,19 @@ use crate::{ commands::pty::{InteractiveChildChip, interactive_command_with_env}, - hive::node::SharedTarget, + hive::node::{BuildNameMap, SharedTarget}, }; +use core::str; use std::{ + borrow::Cow, collections::HashMap, - sync::{Arc, LazyLock}, + path::Path, + sync::{Arc, LazyLock, nonpoison::Mutex}, }; use aho_corasick::AhoCorasick; use itertools::Itertools; -use nix_compat::log::{AT_NIX_PREFIX, LogMessage, VerbosityLevel}; +use nix_compat::log::{AT_NIX_PREFIX, Field, LogMessage, ResultType, VerbosityLevel}; use tracing::{debug, error, info, trace, warn}; use crate::{ @@ -48,6 +51,7 @@ pub(crate) struct CommandArguments> { keep_stdin_open: bool, privilege_escalation_command: Option, log_stdout: bool, + build_name_map: BuildNameMap, } static AHO_CORASICK: LazyLock = LazyLock::new(|| { @@ -59,7 +63,7 @@ static AHO_CORASICK: LazyLock = LazyLock::new(|| { }); impl> CommandArguments { - pub(crate) const fn new(command_string: S, modifiers: SubCommandModifiers) -> Self { + pub(crate) fn new(command_string: S, modifiers: SubCommandModifiers) -> Self { Self { command_string, keep_stdin_open: false, @@ -68,6 +72,7 @@ impl> CommandArguments { target: None, output_mode: ChildOutputMode::Generic, modifiers, + build_name_map: Arc::new(Mutex::new(HashMap::new())), } } @@ -156,7 +161,7 @@ impl WireCommandChip for Either { impl ChildOutputMode { /// this function is by far the biggest hotspot in the whole tree /// Returns a string if this log is notable to be stored as an error message - fn trace_slice(self, line: &mut [u8]) -> Option { + fn trace_slice(self, line: &mut [u8], build_name_map: &BuildNameMap) -> Option { let slice = match self { Self::Generic | Self::Interactive => { let string = String::from_utf8_lossy(line); @@ -183,9 +188,58 @@ impl ChildOutputMode { return None; }; - let (msg, level) = match log_message { - LogMessage::Start { text, level, .. } => (text, level), - LogMessage::Msg { msg, level, .. } => (msg, level), + let (msg, level, build_name) = match log_message { + LogMessage::Start { + text, + r#type, + level, + id, + fields, + .. + } => { + if let Some(fields) = fields + && matches!(r#type, nix_compat::log::ActivityType::Build) + // first field of start log contains the build name. + && let Some(Field::String(name)) = fields.first() + { + build_name_map + .lock() + .insert(id, drv_path_to_build_name(name)); + } + + (text, level, None) + } + LogMessage::Stop { id, .. } => { + build_name_map.lock().remove(&id); + + return None; + } + LogMessage::Msg { msg, level, .. } => (msg, level, None), + LogMessage::Result { + r#type: ResultType::BuildLogLine, + fields, + id, + .. + } => { + let Some(Field::String(msg)) = fields.into_iter().next() else { + return None; + }; + + // Attempt to reuse owned bytes into a utf8 string, or falls + // back lossy if it fails. + let msg = match msg { + std::borrow::Cow::Borrowed(bytes) => String::from_utf8_lossy(bytes), + std::borrow::Cow::Owned(vec) => match String::from_utf8(vec) { + Ok(s) => Cow::Owned(s), + Err(e) => Cow::Owned(String::from_utf8_lossy(e.as_bytes()).into_owned()), + }, + }; + + let lock = build_name_map.lock(); + let build_name = lock.get(&id).cloned(); + + (msg, VerbosityLevel::Info, build_name) + } _ => return None, }; @@ -195,23 +249,81 @@ impl ChildOutputMode { let msg = strip_ansi_escapes::strip_str(msg); - match level { - VerbosityLevel::Info => info!("{msg}"), - VerbosityLevel::Warn | VerbosityLevel::Notice => warn!("{msg}"), - VerbosityLevel::Error => error!("{msg}"), - VerbosityLevel::Debug => debug!("{msg}"), - VerbosityLevel::Vomit | VerbosityLevel::Talkative | VerbosityLevel::Chatty => { - trace!("{msg}"); - } - } + let level = log_print(&level, build_name.as_ref(), &msg); - if matches!( - level, - VerbosityLevel::Error | VerbosityLevel::Warn | VerbosityLevel::Notice - ) { + if matches!(level, tracing::Level::ERROR | tracing::Level::WARN) { return Some(msg); } None } } + +fn log_print( + level: &VerbosityLevel, + build_name: Option<&Arc>, + msg: &String, +) -> tracing::Level { + let level: tracing::Level = match level { + VerbosityLevel::Info => tracing::Level::INFO, + VerbosityLevel::Warn | VerbosityLevel::Notice => tracing::Level::WARN, + VerbosityLevel::Error => tracing::Level::ERROR, + VerbosityLevel::Debug => tracing::Level::DEBUG, + VerbosityLevel::Vomit | VerbosityLevel::Talkative | VerbosityLevel::Chatty => { + tracing::Level::TRACE + } + }; + + if let Some(build_name) = build_name { + match level { + tracing::Level::ERROR => error!(build = %build_name, "{msg}"), + tracing::Level::WARN => warn!(build = %build_name, "{msg}"), + tracing::Level::INFO => info!(build = %build_name, "{msg}"), + tracing::Level::DEBUG => debug!(build = %build_name, "{msg}"), + tracing::Level::TRACE => trace!(build = %build_name, "{msg}"), + } + } else { + match level { + tracing::Level::ERROR => error!("{msg}"), + tracing::Level::WARN => warn!("{msg}"), + tracing::Level::INFO => info!("{msg}"), + tracing::Level::DEBUG => debug!("{msg}"), + tracing::Level::TRACE => trace!("{msg}"), + } + } + + level +} + +fn drv_path_to_build_name(drv_path: &[u8]) -> Arc { + let string = match String::from_utf8(drv_path.to_vec()) { + Err(err) => { + error!(err = %err, "failed to parse build job name"); + + return Arc::new(String::from_utf8_lossy(drv_path).to_string()); + } + Ok(str) => str, + }; + + let Some(file_stem) = Path::new(&string).file_stem() else { + error!("drv path build job's file_stem was None"); + + return Arc::new(String::from_utf8_lossy(drv_path).to_string()); + }; + + let Some(file_stem) = file_stem.to_str() else { + error!("drv path build job's file_stem was not valid unicode"); + + return Arc::new(String::from_utf8_lossy(drv_path).to_string()); + }; + + let build_name = file_stem.split_once('-').map_or_else( + || { + error!("unexpected drv build job file stem format"); + file_stem + }, + |(_, name)| name, + ); + + Arc::new(build_name.to_string()) +} diff --git a/crates/core/src/commands/noninteractive.rs b/crates/core/src/commands/noninteractive.rs index fe9e302..0486c79 100644 --- a/crates/core/src/commands/noninteractive.rs +++ b/crates/core/src/commands/noninteractive.rs @@ -11,7 +11,7 @@ use crate::{ SubCommandModifiers, commands::{ChildOutputMode, CommandArguments, WireCommandChip}, errors::{CommandError, HiveLibError}, - hive::node::SharedTarget, + hive::node::{BuildNameMap, SharedTarget}, }; use itertools::Itertools; use tokio::{ @@ -97,6 +97,7 @@ pub(crate) async fn non_interactive_command_with_env>( error_collection.clone(), true, true, + arguments.build_name_map.clone(), ) .in_current_span(), ); @@ -107,6 +108,7 @@ pub(crate) async fn non_interactive_command_with_env>( stdout_collection.clone(), false, arguments.log_stdout, + arguments.build_name_map.clone(), ) .in_current_span(), ); @@ -161,6 +163,7 @@ pub async fn handle_io( collection: Arc>>, is_error: bool, should_log: bool, + build_name_map: BuildNameMap, ) where R: tokio::io::AsyncRead + Unpin, { @@ -170,7 +173,7 @@ pub async fn handle_io( let mut line = line.into_bytes(); let log = if should_log { - Some(output_mode.trace_slice(&mut line)) + Some(output_mode.trace_slice(&mut line, &build_name_map)) } else { None }; diff --git a/crates/core/src/commands/pty/mod.rs b/crates/core/src/commands/pty/mod.rs index d6fbfdb..e960c3b 100644 --- a/crates/core/src/commands/pty/mod.rs +++ b/crates/core/src/commands/pty/mod.rs @@ -190,6 +190,7 @@ pub(crate) async fn interactive_command_with_env>( span: Span::current(), log_stdout: arguments.log_stdout, status_sender, + build_name_map: arguments.build_name_map.clone(), }; tokio::task::spawn_blocking(move || handle_pty_stdout(arguments)) diff --git a/crates/core/src/commands/pty/output.rs b/crates/core/src/commands/pty/output.rs index 3aa0d27..bcc8db5 100644 --- a/crates/core/src/commands/pty/output.rs +++ b/crates/core/src/commands/pty/output.rs @@ -10,6 +10,7 @@ use crate::{ }, }, errors::CommandError, + hive::node::BuildNameMap, }; use aho_corasick::AhoCorasick; use std::{ @@ -30,6 +31,7 @@ pub(super) struct WatchStdoutArguments { pub status_sender: watch::Sender, pub span: Span, pub log_stdout: bool, + pub build_name_map: BuildNameMap, } /// Handles data from the PTY, and logs or prompts the user depending on the state @@ -49,6 +51,7 @@ pub(super) fn handle_pty_stdout(arguments: WatchStdoutArguments) -> Result<(), C stderr_collection, status_sender, log_stdout, + build_name_map, .. } = arguments; @@ -131,6 +134,7 @@ pub(super) fn handle_pty_stdout(arguments: WatchStdoutArguments) -> Result<(), C &mut line, log_stdout, output_mode, + &build_name_map, ); } } @@ -190,12 +194,13 @@ fn handle_normal_data( line: &mut [u8], log_stdout: bool, output_mode: ChildOutputMode, + build_name_map: &BuildNameMap, ) { if line.starts_with(b"#") { let stripped = &mut line[1..]; if log_stdout { - output_mode.trace_slice(stripped); + output_mode.trace_slice(stripped, build_name_map); } let mut queue = stdout_collection.lock().unwrap(); @@ -203,7 +208,7 @@ fn handle_normal_data( return; } - let log = output_mode.trace_slice(line); + let log = output_mode.trace_slice(line, build_name_map); if let Some(error_msg) = log { let mut queue = stderr_collection.lock().unwrap(); diff --git a/crates/core/src/hive/node.rs b/crates/core/src/hive/node.rs index 65e21fe..8ac1c9a 100644 --- a/crates/core/src/hive/node.rs +++ b/crates/core/src/hive/node.rs @@ -5,9 +5,11 @@ use enum_dispatch::enum_dispatch; use gethostname::gethostname; use serde::{Deserialize, Serialize}; +use std::collections::HashMap; use std::fmt::Display; use std::sync::Arc; use std::sync::atomic::AtomicBool; +use std::sync::nonpoison::Mutex; use tokio::sync::{RwLock, oneshot}; use tracing::instrument; @@ -286,12 +288,16 @@ pub struct StepState { pub key_agent_directory: Option, } +pub type BuildNameMap = Arc>>>; + pub struct Context { pub hive_location: Arc, pub modifiers: SubCommandModifiers, pub state: StepState, pub should_quit: Arc, pub name: Name, + + pub build_id_names: BuildNameMap, } #[enum_dispatch(ExecuteStep)] diff --git a/crates/core/src/hive/plan.rs b/crates/core/src/hive/plan.rs index 4811e94..dd279c9 100644 --- a/crates/core/src/hive/plan.rs +++ b/crates/core/src/hive/plan.rs @@ -1,4 +1,7 @@ -use std::sync::{Arc, atomic::AtomicBool}; +use std::{ + collections::HashMap, + sync::{Arc, atomic::AtomicBool, nonpoison::Mutex}, +}; use tokio::sync::RwLock; @@ -206,6 +209,7 @@ fn apply_plan( hive_location, modifiers, should_quit, + build_id_names: Arc::new(Mutex::new(HashMap::new())), }, steps, greedy_evaluate: !matches!(&goal, ApplyGoal::Keys), @@ -230,6 +234,7 @@ pub fn plan_for_node( hive_location, should_quit, name, + build_id_names: Arc::new(Mutex::new(HashMap::new())), }, steps: vec![ Step::Evaluate(Evaluate),