1use std::collections::{HashMap, VecDeque};2use std::fmt::Arguments;3use std::sync::{LazyLock, Mutex};45use camino::{Utf8Path, Utf8PathBuf};6use cxx::ExternType;7use tracing::{8 Level, Span, debug, debug_span, error, error_span, info, info_span, trace, trace_span, warn,9 warn_span,10};11#[cfg(feature = "indicatif")]12use tracing_indicatif::span_ext::IndicatifSpanExt as _;13use vte::Parser;1415use crate::drv::extract_drv_name;1617#[derive(Debug)]18enum ActivityType {19 Unknown = 0,20 CopyPath = 100,21 FileTransfer = 101,22 Realise = 102,23 CopyPaths = 103,24 Builds = 104,25 Build = 105,26 OptimiseStore = 106,27 VerifyPaths = 107,28 Substitute = 108,29 QueryPathInfo = 109,30 PostBuildHook = 110,31 BuildWaiting = 111,32 FetchTree = 112,33}3435fn strip_prefix_suffix<'s, 'p>(a: &'s str, pref: &'p str, suff: &'p str) -> Option<&'s str> {36 a.strip_prefix(pref)?.strip_suffix(suff)37}3839fn parse_path(path: &str) -> Utf8PathBuf {40 Utf8PathBuf::from(strip_prefix_suffix(path, "\x1b[35;1m", "\x1b[0m").unwrap_or(path))41}4243fn parse_drv(drv: &str) -> String {44 let drv = parse_path(drv);45 extract_drv_name(&drv)46}47fn parse_host(host: &str) -> &str {48 if host.is_empty() || host == "local" {49 return "local";50 }51 52 host.strip_prefix("https://").unwrap_or(host)53}5455impl ActivityType {56 fn name(&self) -> &'static str {57 match self {58 ActivityType::Unknown => "nix",59 ActivityType::CopyPath => "nix::copy-path",60 ActivityType::FileTransfer => "nix::file-transfer",61 ActivityType::Realise => "nix::realise",62 ActivityType::CopyPaths => "nix::copy-paths",63 ActivityType::Builds => "nix::builds",64 ActivityType::Build => "nix::build",65 ActivityType::OptimiseStore => "nix::optimise-store",66 ActivityType::VerifyPaths => "nix::verify-paths",67 ActivityType::Substitute => "nix::substitute",68 ActivityType::QueryPathInfo => "nix::query-path-info",69 ActivityType::PostBuildHook => "nix::post-build-hook",70 ActivityType::BuildWaiting => "nix::build-waiting",71 ActivityType::FetchTree => "nix::fetch-tree",72 }73 }74 fn format(75 &self,76 values: &[FieldValue],77 s: &str,78 into: impl FnOnce(Arguments<'_>) -> Span,79 ) -> Span {80 use FieldValue::*;81 match (self, values) {82 (ActivityType::QueryPathInfo, [Str(drv), Str(host)]) => {83 let drv = parse_drv(drv);84 let host = parse_host(host);85 debug_span!(target: "nix::query-path-info", "querying", drv, host)86 }87 (ActivityType::Substitute, [Str(drv), Str(host)]) => {88 let drv = parse_drv(drv);89 let host = parse_host(host);90 debug_span!(target: "nix::substitute", "substituting", drv, host)91 }92 (ActivityType::CopyPath, [Str(drv), Str(from), Str(to)]) => {93 let drv = parse_drv(drv);94 let from = parse_host(from);95 let to = parse_host(to);96 debug_span!(target: "nix::copy-path", "copying", drv, from, to)97 }98 (ActivityType::Build, [Str(drv), Str(host), Int(_), Int(_)]) => {99 let drv = parse_drv(drv);100 let host = parse_host(host);101 info_span!(target: "nix::build", "building", drv, host)102 }103 (ActivityType::FileTransfer, [Str(file)]) => {104 info_span!(target: "nix::file-transfer", "downloading", file)105 }106 (ActivityType::Realise, []) => {107 debug_span!(target: "nix::realise", "realising")108 }109 (ActivityType::CopyPaths, []) => {110 debug_span!(target: "nix::copy-paths", "copying paths")111 }112 (ActivityType::Unknown, [])113 if s.starts_with("copying \"") && s.ends_with("\" to the store") =>114 {115 let tree = s116 .trim_start_matches("copying \"")117 .trim_end_matches("\" to the store");118 debug_span!(target: "nix::trees", "copying", tree)119 }120 (ActivityType::Unknown, [])121 if s.starts_with("copying '") && s.ends_with("' to the store") =>122 {123 let tree = s124 .trim_start_matches("copying '")125 .trim_end_matches("' to the store");126 debug_span!(target: "nix::trees", "copying", tree)127 }128 (ActivityType::Unknown, []) if s.starts_with("hashing '") && s.ends_with("'") => {129 let tree = s.trim_start_matches("hashing '").trim_end_matches("'");130 debug_span!(target: "nix::trees", "hashing", tree)131 }132 (ActivityType::Unknown, []) if s.starts_with("connecting to '") && s.ends_with("'") => {133 let host = s134 .trim_start_matches("connecting to '")135 .trim_end_matches("'");136 debug_span!(target: "nix::remote", "connecting", host)137 }138 (ActivityType::Unknown, [])139 if s.starts_with("copying outputs from '") && s.ends_with("'") =>140 {141 let host = s142 .trim_start_matches("copying outputs from '")143 .trim_end_matches("'");144 debug_span!(target: "nix::remote", "copying outputs", host)145 }146 (ActivityType::Unknown, [])147 if s.starts_with("copying dependencies to '") && s.ends_with("'") =>148 {149 let host = s150 .trim_start_matches("copying dependencies to '")151 .trim_end_matches("'");152 debug_span!(target: "nix::remote", "copying dependencies", host)153 }154 (ActivityType::Unknown, [])155 if s.starts_with("waiting for the upload lock to '") && s.ends_with("'") =>156 {157 let host = s158 .trim_start_matches("waiting for the upload lock to '")159 .trim_end_matches("'");160 debug_span!(target: "nix::remote", "waiting for upload lock", host)161 }162 (ActivityType::BuildWaiting, [])163 if s.starts_with("waiting for a machine to build '") && s.ends_with("'") =>164 {165 let drv = parse_drv(166 s.trim_start_matches("waiting for a machine to build '")167 .trim_end_matches("'"),168 );169 debug_span!(target: "nix::build-waiting", "waiting for available builder", drv)170 }171 (ActivityType::Unknown, []) if s == "querying info about missing paths" => {172 debug_span!(target: "nix::remote", "querying")173 }174 _ => into(format_args!("{}({values:?})", self.name())),175 }176 }177 fn from_int(v: u32) -> Self {178 match v {179 0 => Self::Unknown,180 100 => Self::CopyPath,181 101 => Self::FileTransfer,182 102 => Self::Realise,183 103 => Self::CopyPaths,184 104 => Self::Builds,185 105 => Self::Build,186 106 => Self::OptimiseStore,187 107 => Self::VerifyPaths,188 108 => Self::Substitute,189 109 => Self::QueryPathInfo,190 110 => Self::PostBuildHook,191 111 => Self::BuildWaiting,192 112 => Self::FetchTree,193 _ => {194 warn!("unknown nix action: {v}");195 Self::Unknown196 }197 }198 }199}200201#[derive(Debug)]202enum ResultType {203 FileLinked = 100,204 BuildLogLine = 101,205 UntrustedPath = 102,206 CorruptedPath = 103,207 SetPhase = 104,208 Progress = 105,209 SetExpected = 106,210 PostBuildLogLine = 107,211 FetchStatus = 108,212213 Unknown = 999,214}215impl ResultType {216 fn from_int(v: u32) -> Self {217 match v {218 100 => Self::FileLinked,219 101 => Self::BuildLogLine,220 102 => Self::UntrustedPath,221 103 => Self::CorruptedPath,222 104 => Self::SetPhase,223 105 => Self::Progress,224 106 => Self::SetExpected,225 107 => Self::PostBuildLogLine,226 108 => Self::FetchStatus,227228 _ => {229 warn!("unknown nix result: {v}");230 Self::Unknown231 }232 }233 }234}235#[derive(Clone, Copy)]236enum Verbosity {237 Error,238 Warn,239 Notice,240 Info,241 Talkative,242 Chatty,243 Debug,244 Vomit,245}246impl From<Verbosity> for tracing::Level {247 fn from(val: Verbosity) -> Self {248 match val {249 Verbosity::Error => Level::ERROR,250 Verbosity::Warn => Level::WARN,251 Verbosity::Notice => Level::WARN,252 Verbosity::Info => Level::INFO,253 Verbosity::Talkative => Level::DEBUG,254 Verbosity::Chatty => Level::DEBUG,255 Verbosity::Debug => Level::DEBUG,256 Verbosity::Vomit => Level::TRACE,257 }258 }259}260impl Verbosity {261 fn from_int(u: u32) -> Self {262 [263 Self::Error,264 Self::Warn,265 Self::Notice,266 Self::Info,267 Self::Talkative,268 Self::Chatty,269 Self::Debug,270 Self::Vomit,271 ]272 .get(u as usize)273 .cloned()274 .unwrap_or_else(|| {275 warn!("unknown log level: {u}");276 Verbosity::Vomit277 })278 }279}280281static NIX_SPAN_MAPPING: LazyLock<Mutex<HashMap<u64, Span>>> =282 LazyLock::new(|| Mutex::new(HashMap::new()));283284struct DrvGraphEntry {285 name: String,286 parent: Option<Utf8PathBuf>,287 span: Option<Span>,288 refcount: usize,289}290291static DRV_GRAPH: LazyLock<Mutex<HashMap<Utf8PathBuf, DrvGraphEntry>>> =292 LazyLock::new(|| Mutex::new(HashMap::new()));293294static ACTIVITY_TO_DRV: LazyLock<Mutex<HashMap<u64, Utf8PathBuf>>> =295 LazyLock::new(|| Mutex::new(HashMap::new()));296297pub struct BuildGraphGuard {298 paths: Vec<Utf8PathBuf>,299}300301impl Drop for BuildGraphGuard {302 fn drop(&mut self) {303 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");304 for path in &self.paths {305 if let Some(entry) = drv_graph.get_mut(path) {306 entry.refcount -= 1;307 if entry.refcount == 0 {308 drv_graph.remove(path);309 }310 }311 }312 }313}314315pub fn register_build_graph(parent: &Span, graph: &crate::drv::DrvGraph) -> BuildGraphGuard {316 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");317 let mut paths = Vec::new();318319 drv_graph320 .entry(graph.root.clone())321 .and_modify(|e| e.refcount += 1)322 .or_insert_with(|| DrvGraphEntry {323 name: graph.nodes[&graph.root].name.clone(),324 parent: None,325 span: Some(parent.clone()),326 refcount: 1,327 });328 paths.push(graph.root.clone());329330 let mut queue = VecDeque::new();331 queue.push_back(graph.root.clone());332333 let mut visited = std::collections::HashSet::new();334 visited.insert(graph.root.clone());335336 while let Some(path) = queue.pop_front() {337 let Some(node) = graph.nodes.get(&path) else {338 continue;339 };340 for dep_path in node.input_drvs.keys() {341 if !visited.insert(dep_path.clone()) {342 continue;343 }344 let Some(dep_node) = graph.nodes.get(dep_path) else {345 continue;346 };347 if let Some(entry) = drv_graph.get_mut(dep_path) {348 entry.refcount += 1;349 } else {350 drv_graph.insert(351 dep_path.clone(),352 DrvGraphEntry {353 name: dep_node.name.clone(),354 parent: Some(path.clone()),355 span: None,356 refcount: 1,357 },358 );359 }360 paths.push(dep_path.clone());361 queue.push_back(dep_path.clone());362 }363 }364365 BuildGraphGuard { paths }366}367368fn ensure_drv_span(drv_path: &Utf8Path) -> Option<Span> {369 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");370371 if let Some(span) = drv_graph.get(drv_path).and_then(|e| e.span.clone()) {372 return Some(span);373 }374375 let mut chain = vec![];376 let mut current = drv_path.to_owned();377 loop {378 let Some(entry) = drv_graph.get(¤t) else {379 break;380 };381 if entry.span.is_some() {382 chain.push(current);383 break;384 }385 chain.push(current.clone());386 match &entry.parent {387 Some(p) => current = p.clone(),388 None => break,389 }390 }391392 if chain.is_empty() {393 return None;394 }395396 for i in (0..chain.len()).rev() {397 let path = &chain[i];398 if drv_graph.get(path).unwrap().span.is_some() {399 continue;400 }401 let parent_span = chain402 .get(i + 1)403 .and_then(|p| drv_graph.get(p))404 .and_then(|e| e.span.clone());405 let name = drv_graph.get(path).unwrap().name.clone();406 let span = {407 let _enter = parent_span.as_ref().map(|s| s.enter());408 info_span!(target: "nix::build", "building", drv = %name)409 };410 drv_graph.get_mut(path).unwrap().span = Some(span);411 }412413 drv_graph.get(drv_path).and_then(|e| e.span.clone())414}415416#[derive(Debug)]417enum FieldValue {418 Int(i32),419 Str(String),420}421422struct StartActivityBuilder {423 activity_id: u64,424 verbosity: Verbosity,425 typ: ActivityType,426 fields: Vec<FieldValue>,427}428impl StartActivityBuilder {429 fn add_int_field(&mut self, i: i32) {430 self.fields.push(FieldValue::Int(i));431 }432 fn add_string_field(&mut self, v: &[u8]) {433 let v = String::from_utf8_lossy(v);434 self.fields.push(FieldValue::Str(v.to_string()));435 }436 fn emit(&mut self, parent: u64, s: &str) {437 let graph_span = if matches!(self.typ, ActivityType::Build) {438 self.fields.first().and_then(|f| match f {439 FieldValue::Str(drv_path) => {440 let clean = parse_path(drv_path);441 let span = ensure_drv_span(&clean);442 if span.is_some() {443 ACTIVITY_TO_DRV444 .lock()445 .expect("not poisoned")446 .insert(self.activity_id, clean.to_owned());447 }448 span449 }450 _ => None,451 })452 } else {453 None454 };455456 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");457458 let span = if let Some(span) = graph_span {459 #[cfg(feature = "indicatif")]460 span.pb_start();461 span462 } else {463 let parent = mapping.get(&parent);464 let _in_parent = parent.map(|p| p.enter());465 let level: Level = self.verbosity.into();466 if level == Level::ERROR {467 self.typ468 .format(&self.fields, s, |v| error_span!("action", v))469 } else if level == Level::WARN {470 self.typ471 .format(&self.fields, s, |v| warn_span!("action", v))472 } else if level == Level::INFO {473 self.typ474 .format(&self.fields, s, |v| info_span!("action", v))475 } else if level == Level::DEBUG {476 self.typ477 .format(&self.fields, s, |v| debug_span!("action", v))478 } else {479 self.typ480 .format(&self.fields, s, |v| trace_span!("action", v))481 }482 };483 if !s.trim().is_empty() {484 let s = ansi_filter(s);485 #[cfg(feature = "indicatif")]486 {487 span.pb_set_message(&s);488 }489 let _e = span.enter();490 let level: Level = self.verbosity.into();491 if level == Level::ERROR {492 error!(target: "nix", "{}", s)493 } else if level == Level::WARN {494 warn!(target: "nix", "{}", s)495 } else if level == Level::INFO {496 info!(target: "nix", "{}", s)497 } else if level == Level::DEBUG {498 if s != "querying info about missing paths" {499 debug!(target: "nix", "{}", s)500 }501 } else {502 trace!(target: "nix", "{}", s)503 }504 } else {505 #[cfg(feature = "indicatif")]506 {507 span.pb_start();508 }509 }510 mapping.insert(self.activity_id, span);511 }512 fn emit_result(&mut self, ty: u32) {513 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");514515 let Some(parent) = mapping.get(&self.activity_id) else {516 panic!("unexpected result for dead parent");517 };518519 let _in_parent = parent.enter();520 let res = ResultType::from_int(ty);521522 use FieldValue::*;523 match (&res, self.fields.as_slice()) {524 525 (ResultType::BuildLogLine, [Str(s)]) => {526 let s = ansi_filter(s);527 info!("{s}");528 }529 530 531 532 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {533 let _act_ty = ActivityType::from_int(*act_ty as u32);534 }535 (ResultType::SetPhase, [Str(phase)]) => {536 537 debug!(target: "nix::phase", phase)538 }539 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {540 #[cfg(feature = "indicatif")]541 {542 parent.pb_set_length(*_expected as u64);543 parent.pb_set_position(*_done as u64);544 }545 }546 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),547 }548 }549}550fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {551 Box::new(StartActivityBuilder {552 activity_id,553 verbosity: Verbosity::from_int(lvl),554 typ: ActivityType::from_int(typ),555 fields: vec![],556 })557}558559fn emit_warn(v: &str) {560 warn!(target: "nix::eval", "{v}")561}562fn emit_stop(v: u64) {563 {564 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");565 mapping.remove(&v);566 }567 if let Some(drv_path) = ACTIVITY_TO_DRV.lock().expect("not poisoned").remove(&v) {568 if let Some(entry) = DRV_GRAPH.lock().expect("not poisoned").get_mut(&drv_path) {569 entry.span = None;570 }571 }572}573fn emit_log(lvl: u32, v: &[u8]) {574 let verbosity = Verbosity::from_int(lvl);575 let level: Level = verbosity.into();576 let v = String::from_utf8_lossy(v);577 if level == Level::ERROR {578 error!(target: "nix", "{v}")579 } else if level == Level::WARN {580 warn!(target: "nix", "{v}")581 } else if level == Level::INFO {582 info!(target: "nix", "{v}")583 } else if level == Level::DEBUG {584 if v != "querying info about missing paths" {585 debug!(target: "nix", "{v}")586 }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}