1use std::collections::{HashMap, VecDeque};2use std::fmt::Arguments;3use std::sync::{LazyLock, Mutex};45use cxx::ExternType;6use tracing::{7 Level, Span, debug, debug_span, error, error_span, info, info_span, trace, trace_span, warn,8 warn_span,9};10#[cfg(feature = "indicatif")]11use tracing_indicatif::span_ext::IndicatifSpanExt as _;12use vte::Parser;1314#[derive(Debug)]15enum ActivityType {16 Unknown = 0,17 CopyPath = 100,18 FileTransfer = 101,19 Realise = 102,20 CopyPaths = 103,21 Builds = 104,22 Build = 105,23 OptimiseStore = 106,24 VerifyPaths = 107,25 Substitute = 108,26 QueryPathInfo = 109,27 PostBuildHook = 110,28 BuildWaiting = 111,29 FetchTree = 112,30}3132fn strip_prefix_suffix<'s, 'p>(a: &'s str, pref: &'p str, suff: &'p str) -> Option<&'s str> {33 a.strip_prefix(pref)?.strip_suffix(suff)34}3536fn parse_path(path: &str) -> &str {37 strip_prefix_suffix(path, "\x1b[35;1m", "\x1b[0m").unwrap_or(path)38}3940fn parse_drv(drv: &str) -> &str {41 let drv = parse_path(drv);42 if let Some(pkg) = drv.strip_prefix("/nix/store/") {43 let mut it = pkg.splitn(2, '-');44 it.next();45 if let Some(pkg) = it.next() {46 return pkg;47 }48 }49 drv50}51fn parse_host(host: &str) -> &str {52 if host.is_empty() || host == "local" {53 return "local";54 }55 56 host.strip_prefix("https://").unwrap_or(host)57}5859impl ActivityType {60 fn name(&self) -> &'static str {61 match self {62 ActivityType::Unknown => "nix",63 ActivityType::CopyPath => "nix::copy-path",64 ActivityType::FileTransfer => "nix::file-transfer",65 ActivityType::Realise => "nix::realise",66 ActivityType::CopyPaths => "nix::copy-paths",67 ActivityType::Builds => "nix::builds",68 ActivityType::Build => "nix::build",69 ActivityType::OptimiseStore => "nix::optimise-store",70 ActivityType::VerifyPaths => "nix::verify-paths",71 ActivityType::Substitute => "nix::substitute",72 ActivityType::QueryPathInfo => "nix::query-path-info",73 ActivityType::PostBuildHook => "nix::post-build-hook",74 ActivityType::BuildWaiting => "nix::build-waiting",75 ActivityType::FetchTree => "nix::fetch-tree",76 }77 }78 fn format(79 &self,80 values: &[FieldValue],81 s: &str,82 into: impl FnOnce(Arguments<'_>) -> Span,83 ) -> Span {84 use FieldValue::*;85 match (self, values) {86 (ActivityType::QueryPathInfo, [Str(drv), Str(host)]) => {87 let drv = parse_drv(drv);88 let host = parse_host(host);89 debug_span!(target: "nix::query-path-info", "querying", drv, host)90 }91 (ActivityType::Substitute, [Str(drv), Str(host)]) => {92 let drv = parse_drv(drv);93 let host = parse_host(host);94 debug_span!(target: "nix::substitute", "substituting", drv, host)95 }96 (ActivityType::CopyPath, [Str(drv), Str(from), Str(to)]) => {97 let drv = parse_drv(drv);98 let from = parse_host(from);99 let to = parse_host(to);100 debug_span!(target: "nix::copy-path", "copying", drv, from, to)101 }102 (ActivityType::Build, [Str(drv), Str(host), Int(_), Int(_)]) => {103 let drv = parse_drv(drv);104 let host = parse_host(host);105 info_span!(target: "nix::build", "building", drv, host)106 }107 (ActivityType::FileTransfer, [Str(file)]) => {108 info_span!(target: "nix::file-transfer", "downloading", file)109 }110 (ActivityType::Realise, []) => {111 debug_span!(target: "nix::realise", "realising")112 }113 (ActivityType::CopyPaths, []) => {114 debug_span!(target: "nix::copy-paths", "copying paths")115 }116 (ActivityType::Unknown, [])117 if s.starts_with("copying \"") && s.ends_with("\" to the store") =>118 {119 let tree = s120 .trim_start_matches("copying \"")121 .trim_end_matches("\" to the store");122 debug_span!(target: "nix::trees", "copying", tree)123 }124 (ActivityType::Unknown, [])125 if s.starts_with("copying '") && s.ends_with("' to the store") =>126 {127 let tree = s128 .trim_start_matches("copying '")129 .trim_end_matches("' to the store");130 debug_span!(target: "nix::trees", "copying", tree)131 }132 (ActivityType::Unknown, []) if s.starts_with("hashing '") && s.ends_with("'") => {133 let tree = s.trim_start_matches("hashing '").trim_end_matches("'");134 debug_span!(target: "nix::trees", "hashing", tree)135 }136 (ActivityType::Unknown, []) if s.starts_with("connecting to '") && s.ends_with("'") => {137 let host = s138 .trim_start_matches("connecting to '")139 .trim_end_matches("'");140 debug_span!(target: "nix::remote", "connecting", host)141 }142 (ActivityType::Unknown, [])143 if s.starts_with("copying outputs from '") && s.ends_with("'") =>144 {145 let host = s146 .trim_start_matches("copying outputs from '")147 .trim_end_matches("'");148 debug_span!(target: "nix::remote", "copying outputs", host)149 }150 (ActivityType::Unknown, [])151 if s.starts_with("copying dependencies to '") && s.ends_with("'") =>152 {153 let host = s154 .trim_start_matches("copying dependencies to '")155 .trim_end_matches("'");156 debug_span!(target: "nix::remote", "copying dependencies", host)157 }158 (ActivityType::Unknown, [])159 if s.starts_with("waiting for the upload lock to '") && s.ends_with("'") =>160 {161 let host = s162 .trim_start_matches("waiting for the upload lock to '")163 .trim_end_matches("'");164 debug_span!(target: "nix::remote", "waiting for upload lock", host)165 }166 (ActivityType::BuildWaiting, [])167 if s.starts_with("waiting for a machine to build '") && s.ends_with("'") =>168 {169 let drv = parse_drv(170 s.trim_start_matches("waiting for a machine to build '")171 .trim_end_matches("'"),172 );173 debug_span!(target: "nix::build-waiting", "waiting for available builder", drv)174 }175 (ActivityType::Unknown, []) if s == "querying info about missing paths" => {176 debug_span!(target: "nix::remote", "querying")177 }178 _ => into(format_args!("{}({values:?})", self.name())),179 }180 }181 fn from_int(v: u32) -> Self {182 match v {183 0 => Self::Unknown,184 100 => Self::CopyPath,185 101 => Self::FileTransfer,186 102 => Self::Realise,187 103 => Self::CopyPaths,188 104 => Self::Builds,189 105 => Self::Build,190 106 => Self::OptimiseStore,191 107 => Self::VerifyPaths,192 108 => Self::Substitute,193 109 => Self::QueryPathInfo,194 110 => Self::PostBuildHook,195 111 => Self::BuildWaiting,196 112 => Self::FetchTree,197 _ => {198 warn!("unknown nix action: {v}");199 Self::Unknown200 }201 }202 }203}204205#[derive(Debug)]206enum ResultType {207 FileLinked = 100,208 BuildLogLine = 101,209 UntrustedPath = 102,210 CorruptedPath = 103,211 SetPhase = 104,212 Progress = 105,213 SetExpected = 106,214 PostBuildLogLine = 107,215 FetchStatus = 108,216217 Unknown = 999,218}219impl ResultType {220 fn from_int(v: u32) -> Self {221 match v {222 100 => Self::FileLinked,223 101 => Self::BuildLogLine,224 102 => Self::UntrustedPath,225 103 => Self::CorruptedPath,226 104 => Self::SetPhase,227 105 => Self::Progress,228 106 => Self::SetExpected,229 107 => Self::PostBuildLogLine,230 108 => Self::FetchStatus,231232 _ => {233 warn!("unknown nix result: {v}");234 Self::Unknown235 }236 }237 }238}239#[derive(Clone, Copy)]240enum Verbosity {241 Error,242 Warn,243 Notice,244 Info,245 Talkative,246 Chatty,247 Debug,248 Vomit,249}250impl From<Verbosity> for tracing::Level {251 fn from(val: Verbosity) -> Self {252 match val {253 Verbosity::Error => Level::ERROR,254 Verbosity::Warn => Level::WARN,255 Verbosity::Notice => Level::WARN,256 Verbosity::Info => Level::INFO,257 Verbosity::Talkative => Level::DEBUG,258 Verbosity::Chatty => Level::DEBUG,259 Verbosity::Debug => Level::DEBUG,260 Verbosity::Vomit => Level::TRACE,261 }262 }263}264impl Verbosity {265 fn from_int(u: u32) -> Self {266 [267 Self::Error,268 Self::Warn,269 Self::Notice,270 Self::Info,271 Self::Talkative,272 Self::Chatty,273 Self::Debug,274 Self::Vomit,275 ]276 .get(u as usize)277 .cloned()278 .unwrap_or_else(|| {279 warn!("unknown log level: {u}");280 Verbosity::Vomit281 })282 }283}284285static NIX_SPAN_MAPPING: LazyLock<Mutex<HashMap<u64, Span>>> =286 LazyLock::new(|| Mutex::new(HashMap::new()));287288struct DrvGraphEntry {289 name: String,290 parent: Option<String>,291 span: Option<Span>,292 refcount: usize,293}294295static DRV_GRAPH: LazyLock<Mutex<HashMap<String, DrvGraphEntry>>> =296 LazyLock::new(|| Mutex::new(HashMap::new()));297298static ACTIVITY_TO_DRV: LazyLock<Mutex<HashMap<u64, String>>> =299 LazyLock::new(|| Mutex::new(HashMap::new()));300301pub struct BuildGraphGuard {302 paths: Vec<String>,303}304305impl Drop for BuildGraphGuard {306 fn drop(&mut self) {307 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");308 for path in &self.paths {309 if let Some(entry) = drv_graph.get_mut(path) {310 entry.refcount -= 1;311 if entry.refcount == 0 {312 drv_graph.remove(path);313 }314 }315 }316 }317}318319pub fn register_build_graph(parent: &Span, graph: &crate::drv::DrvGraph) -> BuildGraphGuard {320 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");321 let mut paths = Vec::new();322323 drv_graph324 .entry(graph.root.clone())325 .and_modify(|e| e.refcount += 1)326 .or_insert_with(|| DrvGraphEntry {327 name: graph.nodes[&graph.root].name.clone(),328 parent: None,329 span: Some(parent.clone()),330 refcount: 1,331 });332 paths.push(graph.root.clone());333334 let mut queue = VecDeque::new();335 queue.push_back(graph.root.clone());336337 let mut visited = std::collections::HashSet::new();338 visited.insert(graph.root.clone());339340 while let Some(path) = queue.pop_front() {341 let Some(node) = graph.nodes.get(&path) else {342 continue;343 };344 for dep_path in node.input_drvs.keys() {345 if !visited.insert(dep_path.clone()) {346 continue;347 }348 let Some(dep_node) = graph.nodes.get(dep_path) else {349 continue;350 };351 if let Some(entry) = drv_graph.get_mut(dep_path) {352 entry.refcount += 1;353 } else {354 drv_graph.insert(355 dep_path.clone(),356 DrvGraphEntry {357 name: dep_node.name.clone(),358 parent: Some(path.clone()),359 span: None,360 refcount: 1,361 },362 );363 }364 paths.push(dep_path.clone());365 queue.push_back(dep_path.clone());366 }367 }368369 BuildGraphGuard { paths }370}371372fn ensure_drv_span(drv_path: &str) -> Option<Span> {373 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");374375 if let Some(span) = drv_graph.get(drv_path).and_then(|e| e.span.clone()) {376 return Some(span);377 }378379 let mut chain = vec![];380 let mut current = drv_path.to_owned();381 loop {382 let Some(entry) = drv_graph.get(¤t) else {383 break;384 };385 if entry.span.is_some() {386 chain.push(current);387 break;388 }389 chain.push(current.clone());390 match &entry.parent {391 Some(p) => current = p.clone(),392 None => break,393 }394 }395396 if chain.is_empty() {397 return None;398 }399400 for i in (0..chain.len()).rev() {401 let path = &chain[i];402 if drv_graph.get(path).unwrap().span.is_some() {403 continue;404 }405 let parent_span = chain406 .get(i + 1)407 .and_then(|p| drv_graph.get(p))408 .and_then(|e| e.span.clone());409 let name = drv_graph.get(path).unwrap().name.clone();410 let span = {411 let _enter = parent_span.as_ref().map(|s| s.enter());412 info_span!(target: "nix::build", "building", drv = %name)413 };414 drv_graph.get_mut(path).unwrap().span = Some(span);415 }416417 drv_graph.get(drv_path).and_then(|e| e.span.clone())418}419420#[derive(Debug)]421enum FieldValue {422 Int(i32),423 Str(String),424}425426struct StartActivityBuilder {427 activity_id: u64,428 verbosity: Verbosity,429 typ: ActivityType,430 fields: Vec<FieldValue>,431}432impl StartActivityBuilder {433 fn add_int_field(&mut self, i: i32) {434 self.fields.push(FieldValue::Int(i));435 }436 fn add_string_field(&mut self, v: &[u8]) {437 let v = String::from_utf8_lossy(v);438 self.fields.push(FieldValue::Str(v.to_string()));439 }440 fn emit(&mut self, parent: u64, s: &str) {441 let graph_span = if matches!(self.typ, ActivityType::Build) {442 self.fields.first().and_then(|f| match f {443 FieldValue::Str(drv_path) => {444 let clean = parse_path(drv_path);445 let span = ensure_drv_span(clean);446 if span.is_some() {447 ACTIVITY_TO_DRV448 .lock()449 .expect("not poisoned")450 .insert(self.activity_id, clean.to_owned());451 }452 span453 }454 _ => None,455 })456 } else {457 None458 };459460 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");461462 let span = if let Some(span) = graph_span {463 #[cfg(feature = "indicatif")]464 span.pb_start();465 span466 } else {467 let parent = mapping.get(&parent);468 let _in_parent = parent.map(|p| p.enter());469 let level: Level = self.verbosity.into();470 if level == Level::ERROR {471 self.typ472 .format(&self.fields, s, |v| error_span!("action", v))473 } else if level == Level::WARN {474 self.typ475 .format(&self.fields, s, |v| warn_span!("action", v))476 } else if level == Level::INFO {477 self.typ478 .format(&self.fields, s, |v| info_span!("action", v))479 } else if level == Level::DEBUG {480 self.typ481 .format(&self.fields, s, |v| debug_span!("action", v))482 } else {483 self.typ484 .format(&self.fields, s, |v| trace_span!("action", v))485 }486 };487 if !s.trim().is_empty() {488 let s = ansi_filter(s);489 #[cfg(feature = "indicatif")]490 {491 span.pb_set_message(&s);492 }493 let _e = span.enter();494 let level: Level = self.verbosity.into();495 if level == Level::ERROR {496 error!(target: "nix", "{}", s)497 } else if level == Level::WARN {498 warn!(target: "nix", "{}", s)499 } else if level == Level::INFO {500 info!(target: "nix", "{}", s)501 } else if level == Level::DEBUG {502 debug!(target: "nix", "{}", s)503 } else {504 trace!(target: "nix", "{}", s)505 }506 } else {507 #[cfg(feature = "indicatif")]508 {509 span.pb_start();510 }511 }512 mapping.insert(self.activity_id, span);513 }514 fn emit_result(&mut self, ty: u32) {515 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");516517 let Some(parent) = mapping.get(&self.activity_id) else {518 panic!("unexpected result for dead parent");519 };520521 let _in_parent = parent.enter();522 let res = ResultType::from_int(ty);523524 use FieldValue::*;525 match (&res, self.fields.as_slice()) {526 527 (ResultType::BuildLogLine, [Str(s)]) => {528 let s = ansi_filter(s);529 info!("{s}");530 }531 532 533 534 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {535 let _act_ty = ActivityType::from_int(*act_ty as u32);536 }537 (ResultType::SetPhase, [Str(phase)]) => {538 539 debug!(target: "nix::phase", phase)540 }541 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {542 #[cfg(feature = "indicatif")]543 {544 parent.pb_set_length(*_expected as u64);545 parent.pb_set_position(*_done as u64);546 }547 }548 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),549 }550 }551}552fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {553 Box::new(StartActivityBuilder {554 activity_id,555 verbosity: Verbosity::from_int(lvl),556 typ: ActivityType::from_int(typ),557 fields: vec![],558 })559}560561fn emit_warn(v: &str) {562 warn!(target: "nix::eval", "{v}")563}564fn emit_stop(v: u64) {565 {566 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");567 mapping.remove(&v);568 }569 if let Some(drv_path) = ACTIVITY_TO_DRV.lock().expect("not poisoned").remove(&v) {570 if let Some(entry) = DRV_GRAPH.lock().expect("not poisoned").get_mut(&drv_path) {571 entry.span = None;572 }573 }574}575fn emit_log(lvl: u32, v: &[u8]) {576 let verbosity = Verbosity::from_int(lvl);577 let level: Level = verbosity.into();578 let v = String::from_utf8_lossy(v);579 if level == Level::ERROR {580 error!(target: "nix", "{v}")581 } else if level == Level::WARN {582 warn!(target: "nix", "{v}")583 } else if level == Level::INFO {584 info!(target: "nix", "{v}")585 } else if level == Level::DEBUG {586 debug!(target: "nix", "{v}")587 } else {588 trace!(target: "nix", "{v}")589 }590}591592struct AnsiFiltered {593 output: String,594}595impl vte::Perform for AnsiFiltered {596 fn print(&mut self, c: char) {597 self.output.push(c);598 }599600 fn execute(&mut self, byte: u8) {601 602 if byte == b'\n' {603 self.output.push('\n');604 } else if byte == b'\t' {605 606 self.output.push('\t');607 }608 }609610 fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}611 fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}612613 fn csi_dispatch(614 &mut self,615 params: &vte::Params,616 _intermediates: &[u8],617 _ignore: bool,618 action: char,619 ) {620 use std::fmt::Write;621 if action != 'm' {622 623 return;624 }625 self.output.push_str("\x1b[");626 for (i, par) in params.iter().enumerate() {627 if i != 0 {628 let _ = write!(self.output, ";");629 }630 for (i, sub) in par.iter().enumerate() {631 if i != 0 {632 let _ = write!(self.output, ":");633 }634 let _ = write!(self.output, "{sub}");635 }636 }637 self.output.push(action);638 }639}640fn ansi_filter(i: &str) -> String {641 let mut out = AnsiFiltered {642 output: String::new(),643 };644 let mut parser = Parser::new();645646 647 for chunk in i.as_bytes().chunks(50) {648 parser.advance(&mut out, chunk);649 }650651 out.output652}653654#[derive(Debug)]655pub struct StackFrame {656 pub msg: String,657 pub pos: String,658}659660#[derive(Debug)]661pub struct ErrorInfoBuilder {662 level: Level,663 msg: String,664 pub stack_frames: Vec<StackFrame>,665}666fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder> {667 let verbosity = Verbosity::from_int(lvl);668 let level: Level = verbosity.into();669 let v = String::from_utf8_lossy(v);670 Box::new(ErrorInfoBuilder {671 level,672 msg: v.to_string(),673 stack_frames: Vec::new(),674 })675}676impl ErrorInfoBuilder {677 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]) {678 let v = String::from_utf8_lossy(v);679 let pos = String::from_utf8_lossy(pos);680 self.stack_frames.push(StackFrame {681 msg: v.to_string(),682 pos: pos.to_string(),683 });684 }685 fn emit_error_info(&mut self) {686 error!("{}", self.msg);687 for frame in &self.stack_frames {688 error!(" {} at {}", frame.msg, frame.pos)689 }690 }691}692693#[cxx::bridge]694pub mod nix_logging_cxx {695 extern "Rust" {696 type StartActivityBuilder;697 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;698 fn add_int_field(&mut self, i: i32);699 fn add_string_field(&mut self, v: &[u8]);700 fn emit(&mut self, parent: u64, s: &str);701 fn emit_result(&mut self, ty: u32);702 }703 extern "Rust" {704 type ErrorInfoBuilder;705 fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder>;706 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]);707 fn emit_error_info(&mut self);708 }709 extern "Rust" {710 fn emit_warn(v: &str);711 fn emit_stop(id: u64);712 fn emit_log(lvl: u32, v: &[u8]);713 }714 unsafe extern "C++" {715 include!("nix-eval/src/logging.hh");716717 type nix_c_context = crate::nix_raw::c_context;718719 fn apply_tracing_logger();720 unsafe fn extract_error_info(ctx: *const nix_c_context) -> Box<ErrorInfoBuilder>;721 }722}723724unsafe impl ExternType for crate::nix_raw::c_context {725 type Id = cxx::type_id!("nix_c_context");726727 type Kind = cxx::kind::Opaque;728}