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(dep_path.clone(), DrvGraphEntry {355 name: dep_node.name.clone(),356 parent: Some(path.clone()),357 span: None,358 refcount: 1,359 });360 }361 paths.push(dep_path.clone());362 queue.push_back(dep_path.clone());363 }364 }365366 BuildGraphGuard { paths }367}368369fn ensure_drv_span(drv_path: &str) -> Option<Span> {370 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");371372 if let Some(span) = drv_graph.get(drv_path).and_then(|e| e.span.clone()) {373 return Some(span);374 }375376 let mut chain = vec![];377 let mut current = drv_path.to_owned();378 loop {379 let Some(entry) = drv_graph.get(¤t) else {380 break;381 };382 if entry.span.is_some() {383 chain.push(current);384 break;385 }386 chain.push(current.clone());387 match &entry.parent {388 Some(p) => current = p.clone(),389 None => break,390 }391 }392393 if chain.is_empty() {394 return None;395 }396397 for i in (0..chain.len()).rev() {398 let path = &chain[i];399 if drv_graph.get(path).unwrap().span.is_some() {400 continue;401 }402 let parent_span = chain403 .get(i + 1)404 .and_then(|p| drv_graph.get(p))405 .and_then(|e| e.span.clone());406 let name = drv_graph.get(path).unwrap().name.clone();407 let span = {408 let _enter = parent_span.as_ref().map(|s| s.enter());409 info_span!(target: "nix::build", "building", drv = %name)410 };411 drv_graph.get_mut(path).unwrap().span = Some(span);412 }413414 drv_graph.get(drv_path).and_then(|e| e.span.clone())415}416417#[derive(Debug)]418enum FieldValue {419 Int(i32),420 Str(String),421}422423struct StartActivityBuilder {424 activity_id: u64,425 verbosity: Verbosity,426 typ: ActivityType,427 fields: Vec<FieldValue>,428}429impl StartActivityBuilder {430 fn add_int_field(&mut self, i: i32) {431 self.fields.push(FieldValue::Int(i));432 }433 fn add_string_field(&mut self, v: &[u8]) {434 let v = String::from_utf8_lossy(v);435 self.fields.push(FieldValue::Str(v.to_string()));436 }437 fn emit(&mut self, parent: u64, s: &str) {438 let graph_span = if matches!(self.typ, ActivityType::Build) {439 self.fields.first().and_then(|f| match f {440 FieldValue::Str(drv_path) => {441 let clean = parse_path(drv_path);442 let span = ensure_drv_span(clean);443 if span.is_some() {444 ACTIVITY_TO_DRV445 .lock()446 .expect("not poisoned")447 .insert(self.activity_id, clean.to_owned());448 }449 span450 }451 _ => None,452 })453 } else {454 None455 };456457 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");458459 let span = if let Some(span) = graph_span {460 #[cfg(feature = "indicatif")]461 span.pb_start();462 span463 } else {464 let parent = mapping.get(&parent);465 let _in_parent = parent.map(|p| p.enter());466 let level: Level = self.verbosity.into();467 if level == Level::ERROR {468 self.typ469 .format(&self.fields, s, |v| error_span!("action", v))470 } else if level == Level::WARN {471 self.typ472 .format(&self.fields, s, |v| warn_span!("action", v))473 } else if level == Level::INFO {474 self.typ475 .format(&self.fields, s, |v| info_span!("action", v))476 } else if level == Level::DEBUG {477 self.typ478 .format(&self.fields, s, |v| debug_span!("action", v))479 } else {480 self.typ481 .format(&self.fields, s, |v| trace_span!("action", v))482 }483 };484 if !s.trim().is_empty() {485 let s = ansi_filter(s);486 #[cfg(feature = "indicatif")]487 {488 span.pb_set_message(&s);489 }490 let _e = span.enter();491 let level: Level = self.verbosity.into();492 if level == Level::ERROR {493 error!(target: "nix", "{}", s)494 } else if level == Level::WARN {495 warn!(target: "nix", "{}", s)496 } else if level == Level::INFO {497 info!(target: "nix", "{}", s)498 } else if level == Level::DEBUG {499 debug!(target: "nix", "{}", s)500 } else {501 trace!(target: "nix", "{}", s)502 }503 } else {504 #[cfg(feature = "indicatif")]505 {506 span.pb_start();507 }508 }509 mapping.insert(self.activity_id, span);510 }511 fn emit_result(&mut self, ty: u32) {512 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");513514 let Some(parent) = mapping.get(&self.activity_id) else {515 panic!("unexpected result for dead parent");516 };517518 let _in_parent = parent.enter();519 let res = ResultType::from_int(ty);520521 use FieldValue::*;522 match (&res, self.fields.as_slice()) {523 524 (ResultType::BuildLogLine, [Str(s)]) => {525 let s = ansi_filter(s);526 info!("{s}");527 }528 529 530 531 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {532 let _act_ty = ActivityType::from_int(*act_ty as u32);533 }534 (ResultType::SetPhase, [Str(phase)]) => {535 536 debug!(target: "nix::phase", phase)537 }538 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {539 #[cfg(feature = "indicatif")]540 {541 parent.pb_set_length(*_expected as u64);542 parent.pb_set_position(*_done as u64);543 }544 }545 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),546 }547 }548}549fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {550 Box::new(StartActivityBuilder {551 activity_id,552 verbosity: Verbosity::from_int(lvl),553 typ: ActivityType::from_int(typ),554 fields: vec![],555 })556}557558fn emit_warn(v: &str) {559 warn!(target: "nix::eval", "{v}")560}561fn emit_stop(v: u64) {562 {563 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");564 mapping.remove(&v);565 }566 if let Some(drv_path) = ACTIVITY_TO_DRV.lock().expect("not poisoned").remove(&v) {567 if let Some(entry) = DRV_GRAPH.lock().expect("not poisoned").get_mut(&drv_path) {568 entry.span = None;569 }570 }571}572fn emit_log(lvl: u32, v: &[u8]) {573 let verbosity = Verbosity::from_int(lvl);574 let level: Level = verbosity.into();575 let v = String::from_utf8_lossy(v);576 if level == Level::ERROR {577 error!(target: "nix", "{v}")578 } else if level == Level::WARN {579 warn!(target: "nix", "{v}")580 } else if level == Level::INFO {581 info!(target: "nix", "{v}")582 } else if level == Level::DEBUG {583 debug!(target: "nix", "{v}")584 } else {585 trace!(target: "nix", "{v}")586 }587}588589struct AnsiFiltered {590 output: String,591}592impl vte::Perform for AnsiFiltered {593 fn print(&mut self, c: char) {594 self.output.push(c);595 }596597 fn execute(&mut self, byte: u8) {598 599 if byte == b'\n' {600 self.output.push('\n');601 } else if byte == b'\t' {602 603 self.output.push('\t');604 }605 }606607 fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}608 fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}609610 fn csi_dispatch(611 &mut self,612 params: &vte::Params,613 _intermediates: &[u8],614 _ignore: bool,615 action: char,616 ) {617 use std::fmt::Write;618 if action != 'm' {619 620 return;621 }622 self.output.push_str("\x1b[");623 for (i, par) in params.iter().enumerate() {624 if i != 0 {625 let _ = write!(self.output, ";");626 }627 for (i, sub) in par.iter().enumerate() {628 if i != 0 {629 let _ = write!(self.output, ":");630 }631 let _ = write!(self.output, "{sub}");632 }633 }634 self.output.push(action);635 }636}637fn ansi_filter(i: &str) -> String {638 let mut out = AnsiFiltered {639 output: String::new(),640 };641 let mut parser = Parser::new();642643 644 for chunk in i.as_bytes().chunks(50) {645 parser.advance(&mut out, chunk);646 }647648 out.output649}650651#[derive(Debug)]652pub struct StackFrame {653 pub msg: String,654 pub pos: String,655}656657#[derive(Debug)]658pub struct ErrorInfoBuilder {659 level: Level,660 msg: String,661 pub stack_frames: Vec<StackFrame>,662}663fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder> {664 let verbosity = Verbosity::from_int(lvl);665 let level: Level = verbosity.into();666 let v = String::from_utf8_lossy(v);667 Box::new(ErrorInfoBuilder {668 level,669 msg: v.to_string(),670 stack_frames: Vec::new(),671 })672}673impl ErrorInfoBuilder {674 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]) {675 let v = String::from_utf8_lossy(v);676 let pos = String::from_utf8_lossy(pos);677 self.stack_frames.push(StackFrame {678 msg: v.to_string(),679 pos: pos.to_string(),680 });681 }682 fn emit_error_info(&mut self) {683 error!("{}", self.msg);684 for frame in &self.stack_frames {685 error!(" {} at {}", frame.msg, frame.pos)686 }687 }688}689690#[cxx::bridge]691pub mod nix_logging_cxx {692 extern "Rust" {693 type StartActivityBuilder;694 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;695 fn add_int_field(&mut self, i: i32);696 fn add_string_field(&mut self, v: &[u8]);697 fn emit(&mut self, parent: u64, s: &str);698 fn emit_result(&mut self, ty: u32);699 }700 extern "Rust" {701 type ErrorInfoBuilder;702 fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder>;703 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]);704 fn emit_error_info(&mut self);705 }706 extern "Rust" {707 fn emit_warn(v: &str);708 fn emit_stop(id: u64);709 fn emit_log(lvl: u32, v: &[u8]);710 }711 unsafe extern "C++" {712 include!("nix-eval/src/logging.hh");713714 type nix_c_context = crate::nix_raw::c_context;715716 fn apply_tracing_logger();717 unsafe fn extract_error_info(ctx: *const nix_c_context) -> Box<ErrorInfoBuilder>;718 }719}720721unsafe impl ExternType for crate::nix_raw::c_context {722 type Id = cxx::type_id!("nix_c_context");723724 type Kind = cxx::kind::Opaque;725}