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 if s != "querying info about missing paths" {503 debug!(target: "nix", "{}", s)504 }505 } else {506 trace!(target: "nix", "{}", s)507 }508 } else {509 #[cfg(feature = "indicatif")]510 {511 span.pb_start();512 }513 }514 mapping.insert(self.activity_id, span);515 }516 fn emit_result(&mut self, ty: u32) {517 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");518519 let Some(parent) = mapping.get(&self.activity_id) else {520 panic!("unexpected result for dead parent");521 };522523 let _in_parent = parent.enter();524 let res = ResultType::from_int(ty);525526 use FieldValue::*;527 match (&res, self.fields.as_slice()) {528 529 (ResultType::BuildLogLine, [Str(s)]) => {530 let s = ansi_filter(s);531 info!("{s}");532 }533 534 535 536 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {537 let _act_ty = ActivityType::from_int(*act_ty as u32);538 }539 (ResultType::SetPhase, [Str(phase)]) => {540 541 debug!(target: "nix::phase", phase)542 }543 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {544 #[cfg(feature = "indicatif")]545 {546 parent.pb_set_length(*_expected as u64);547 parent.pb_set_position(*_done as u64);548 }549 }550 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),551 }552 }553}554fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {555 Box::new(StartActivityBuilder {556 activity_id,557 verbosity: Verbosity::from_int(lvl),558 typ: ActivityType::from_int(typ),559 fields: vec![],560 })561}562563fn emit_warn(v: &str) {564 warn!(target: "nix::eval", "{v}")565}566fn emit_stop(v: u64) {567 {568 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");569 mapping.remove(&v);570 }571 if let Some(drv_path) = ACTIVITY_TO_DRV.lock().expect("not poisoned").remove(&v) {572 if let Some(entry) = DRV_GRAPH.lock().expect("not poisoned").get_mut(&drv_path) {573 entry.span = None;574 }575 }576}577fn emit_log(lvl: u32, v: &[u8]) {578 let verbosity = Verbosity::from_int(lvl);579 let level: Level = verbosity.into();580 let v = String::from_utf8_lossy(v);581 if level == Level::ERROR {582 error!(target: "nix", "{v}")583 } else if level == Level::WARN {584 warn!(target: "nix", "{v}")585 } else if level == Level::INFO {586 info!(target: "nix", "{v}")587 } else if level == Level::DEBUG {588 if v != "querying info about missing paths" {589 debug!(target: "nix", "{v}")590 }591 } else {592 trace!(target: "nix", "{v}")593 }594}595596struct AnsiFiltered {597 output: String,598}599impl vte::Perform for AnsiFiltered {600 fn print(&mut self, c: char) {601 self.output.push(c);602 }603604 fn execute(&mut self, byte: u8) {605 606 if byte == b'\n' {607 self.output.push('\n');608 } else if byte == b'\t' {609 610 self.output.push('\t');611 }612 }613614 fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}615 fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}616617 fn csi_dispatch(618 &mut self,619 params: &vte::Params,620 _intermediates: &[u8],621 _ignore: bool,622 action: char,623 ) {624 use std::fmt::Write;625 if action != 'm' {626 627 return;628 }629 self.output.push_str("\x1b[");630 for (i, par) in params.iter().enumerate() {631 if i != 0 {632 let _ = write!(self.output, ";");633 }634 for (i, sub) in par.iter().enumerate() {635 if i != 0 {636 let _ = write!(self.output, ":");637 }638 let _ = write!(self.output, "{sub}");639 }640 }641 self.output.push(action);642 }643}644fn ansi_filter(i: &str) -> String {645 let mut out = AnsiFiltered {646 output: String::new(),647 };648 let mut parser = Parser::new();649650 651 for chunk in i.as_bytes().chunks(50) {652 parser.advance(&mut out, chunk);653 }654655 out.output656}657658#[derive(Debug)]659pub struct StackFrame {660 pub msg: String,661 pub pos: String,662}663664#[derive(Debug)]665pub struct ErrorInfoBuilder {666 level: Level,667 msg: String,668 pub stack_frames: Vec<StackFrame>,669}670fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder> {671 let verbosity = Verbosity::from_int(lvl);672 let level: Level = verbosity.into();673 let v = String::from_utf8_lossy(v);674 Box::new(ErrorInfoBuilder {675 level,676 msg: v.to_string(),677 stack_frames: Vec::new(),678 })679}680impl ErrorInfoBuilder {681 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]) {682 let v = String::from_utf8_lossy(v);683 let pos = String::from_utf8_lossy(pos);684 self.stack_frames.push(StackFrame {685 msg: v.to_string(),686 pos: pos.to_string(),687 });688 }689 fn emit_error_info(&mut self) {690 error!("{}", self.msg);691 for frame in &self.stack_frames {692 error!(" {} at {}", frame.msg, frame.pos)693 }694 }695}696697#[cxx::bridge]698pub mod nix_logging_cxx {699 extern "Rust" {700 type StartActivityBuilder;701 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;702 fn add_int_field(&mut self, i: i32);703 fn add_string_field(&mut self, v: &[u8]);704 fn emit(&mut self, parent: u64, s: &str);705 fn emit_result(&mut self, ty: u32);706 }707 extern "Rust" {708 type ErrorInfoBuilder;709 fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder>;710 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]);711 fn emit_error_info(&mut self);712 }713 extern "Rust" {714 fn emit_warn(v: &str);715 fn emit_stop(id: u64);716 fn emit_log(lvl: u32, v: &[u8]);717 }718 unsafe extern "C++" {719 include!("nix-eval/src/logging.hh");720721 type nix_c_context = crate::nix_raw::c_context;722723 fn apply_tracing_logger();724 unsafe fn extract_error_info(ctx: *const nix_c_context) -> Box<ErrorInfoBuilder>;725 }726}727728unsafe impl ExternType for crate::nix_raw::c_context {729 type Id = cxx::type_id!("nix_c_context");730731 type Kind = cxx::kind::Opaque;732}