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 113 114 115 (ActivityType::Builds, []) => {116 debug_span!(target: "nix::builds", "building")117 }118 (ActivityType::Unknown, [])119 if s.starts_with("copying \"") && s.ends_with("\" to the store") =>120 {121 let tree = s122 .trim_start_matches("copying \"")123 .trim_end_matches("\" to the store");124 debug_span!(target: "nix::trees", "copying", tree)125 }126 (ActivityType::Unknown, [])127 if s.starts_with("copying '") && s.ends_with("' to the store") =>128 {129 let tree = s130 .trim_start_matches("copying '")131 .trim_end_matches("' to the store");132 debug_span!(target: "nix::trees", "copying", tree)133 }134 (ActivityType::Unknown, []) if s.starts_with("hashing '") && s.ends_with("'") => {135 let tree = s.trim_start_matches("hashing '").trim_end_matches("'");136 debug_span!(target: "nix::trees", "hashing", tree)137 }138 (ActivityType::Unknown, []) if s.starts_with("connecting to '") && s.ends_with("'") => {139 let host = s140 .trim_start_matches("connecting to '")141 .trim_end_matches("'");142 debug_span!(target: "nix::remote", "connecting", host)143 }144 (ActivityType::Unknown, [])145 if s.starts_with("copying outputs from '") && s.ends_with("'") =>146 {147 let host = s148 .trim_start_matches("copying outputs from '")149 .trim_end_matches("'");150 debug_span!(target: "nix::remote", "copying outputs", host)151 }152 (ActivityType::Unknown, [])153 if s.starts_with("copying dependencies to '") && s.ends_with("'") =>154 {155 let host = s156 .trim_start_matches("copying dependencies to '")157 .trim_end_matches("'");158 debug_span!(target: "nix::remote", "copying dependencies", host)159 }160 (ActivityType::Unknown, [])161 if s.starts_with("waiting for the upload lock to '") && s.ends_with("'") =>162 {163 let host = s164 .trim_start_matches("waiting for the upload lock to '")165 .trim_end_matches("'");166 debug_span!(target: "nix::remote", "waiting for upload lock", host)167 }168 (ActivityType::BuildWaiting, [])169 if s.starts_with("waiting for a machine to build '") && s.ends_with("'") =>170 {171 let drv = parse_drv(172 s.trim_start_matches("waiting for a machine to build '")173 .trim_end_matches("'"),174 );175 debug_span!(target: "nix::build-waiting", "waiting for available builder", drv)176 }177 (ActivityType::Unknown, []) if s == "querying info about missing paths" => {178 debug_span!(target: "nix::remote", "querying")179 }180 _ => into(format_args!("{}({values:?})", self.name())),181 }182 }183 fn from_int(v: u32) -> Self {184 match v {185 0 => Self::Unknown,186 100 => Self::CopyPath,187 101 => Self::FileTransfer,188 102 => Self::Realise,189 103 => Self::CopyPaths,190 104 => Self::Builds,191 105 => Self::Build,192 106 => Self::OptimiseStore,193 107 => Self::VerifyPaths,194 108 => Self::Substitute,195 109 => Self::QueryPathInfo,196 110 => Self::PostBuildHook,197 111 => Self::BuildWaiting,198 112 => Self::FetchTree,199 _ => {200 warn!("unknown nix action: {v}");201 Self::Unknown202 }203 }204 }205}206207#[derive(Debug)]208enum ResultType {209 FileLinked = 100,210 BuildLogLine = 101,211 UntrustedPath = 102,212 CorruptedPath = 103,213 SetPhase = 104,214 Progress = 105,215 SetExpected = 106,216 PostBuildLogLine = 107,217 FetchStatus = 108,218219 Unknown = 999,220}221impl ResultType {222 fn from_int(v: u32) -> Self {223 match v {224 100 => Self::FileLinked,225 101 => Self::BuildLogLine,226 102 => Self::UntrustedPath,227 103 => Self::CorruptedPath,228 104 => Self::SetPhase,229 105 => Self::Progress,230 106 => Self::SetExpected,231 107 => Self::PostBuildLogLine,232 108 => Self::FetchStatus,233234 _ => {235 warn!("unknown nix result: {v}");236 Self::Unknown237 }238 }239 }240}241#[derive(Clone, Copy)]242enum Verbosity {243 Error,244 Warn,245 Notice,246 Info,247 Talkative,248 Chatty,249 Debug,250 Vomit,251}252impl From<Verbosity> for tracing::Level {253 fn from(val: Verbosity) -> Self {254 match val {255 Verbosity::Error => Level::ERROR,256 Verbosity::Warn => Level::WARN,257 Verbosity::Notice => Level::WARN,258 Verbosity::Info => Level::INFO,259 Verbosity::Talkative => Level::DEBUG,260 Verbosity::Chatty => Level::DEBUG,261 Verbosity::Debug => Level::DEBUG,262 Verbosity::Vomit => Level::TRACE,263 }264 }265}266impl Verbosity {267 fn from_int(u: u32) -> Self {268 [269 Self::Error,270 Self::Warn,271 Self::Notice,272 Self::Info,273 Self::Talkative,274 Self::Chatty,275 Self::Debug,276 Self::Vomit,277 ]278 .get(u as usize)279 .cloned()280 .unwrap_or_else(|| {281 warn!("unknown log level: {u}");282 Verbosity::Vomit283 })284 }285}286287static NIX_SPAN_MAPPING: LazyLock<Mutex<HashMap<u64, Span>>> =288 LazyLock::new(|| Mutex::new(HashMap::new()));289290struct DrvGraphEntry {291 name: String,292 parent: Option<Utf8PathBuf>,293 span: Option<Span>,294 refcount: usize,295}296297static DRV_GRAPH: LazyLock<Mutex<HashMap<Utf8PathBuf, DrvGraphEntry>>> =298 LazyLock::new(|| Mutex::new(HashMap::new()));299300static ACTIVITY_TO_DRV: LazyLock<Mutex<HashMap<u64, Utf8PathBuf>>> =301 LazyLock::new(|| Mutex::new(HashMap::new()));302303pub struct BuildGraphGuard {304 paths: Vec<Utf8PathBuf>,305}306307impl Drop for BuildGraphGuard {308 fn drop(&mut self) {309 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");310 for path in &self.paths {311 if let Some(entry) = drv_graph.get_mut(path) {312 entry.refcount -= 1;313 if entry.refcount == 0 {314 drv_graph.remove(path);315 }316 }317 }318 }319}320321pub fn register_build_graph(parent: &Span, graph: &crate::drv::DrvGraph) -> BuildGraphGuard {322 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");323 let mut paths = Vec::new();324325 drv_graph326 .entry(graph.root.clone())327 .and_modify(|e| e.refcount += 1)328 .or_insert_with(|| DrvGraphEntry {329 name: graph.nodes[&graph.root].name.clone(),330 parent: None,331 span: Some(parent.clone()),332 refcount: 1,333 });334 paths.push(graph.root.clone());335336 let mut queue = VecDeque::new();337 queue.push_back(graph.root.clone());338339 let mut visited = std::collections::HashSet::new();340 visited.insert(graph.root.clone());341342 while let Some(path) = queue.pop_front() {343 let Some(node) = graph.nodes.get(&path) else {344 continue;345 };346 for dep_path in node.input_drvs.keys() {347 if !visited.insert(dep_path.clone()) {348 continue;349 }350 let Some(dep_node) = graph.nodes.get(dep_path) else {351 continue;352 };353 if let Some(entry) = drv_graph.get_mut(dep_path) {354 entry.refcount += 1;355 } else {356 drv_graph.insert(357 dep_path.clone(),358 DrvGraphEntry {359 name: dep_node.name.clone(),360 parent: Some(path.clone()),361 span: None,362 refcount: 1,363 },364 );365 }366 paths.push(dep_path.clone());367 queue.push_back(dep_path.clone());368 }369 }370371 BuildGraphGuard { paths }372}373374375376377378pub fn remove_drv_span(drv_path: &Utf8Path) {379 if let Some(entry) = DRV_GRAPH.lock().expect("not poisoned").get_mut(drv_path) {380 entry.span = None;381 }382}383384fn ensure_drv_span(drv_path: &Utf8Path) -> Option<Span> {385 let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");386387 if let Some(span) = drv_graph.get(drv_path).and_then(|e| e.span.clone()) {388 return Some(span);389 }390391 let mut chain = vec![];392 let mut current = drv_path.to_owned();393 loop {394 let Some(entry) = drv_graph.get(¤t) else {395 break;396 };397 if entry.span.is_some() {398 chain.push(current);399 break;400 }401 chain.push(current.clone());402 match &entry.parent {403 Some(p) => current = p.clone(),404 None => break,405 }406 }407408 if chain.is_empty() {409 return None;410 }411412 for i in (0..chain.len()).rev() {413 let path = &chain[i];414 if drv_graph.get(path).unwrap().span.is_some() {415 continue;416 }417 let parent_span = chain418 .get(i + 1)419 .and_then(|p| drv_graph.get(p))420 .and_then(|e| e.span.clone());421 let name = drv_graph.get(path).unwrap().name.clone();422 let span = {423 let _enter = parent_span.as_ref().map(|s| s.enter());424 info_span!(target: "nix::build", "building", drv = %name)425 };426 drv_graph.get_mut(path).unwrap().span = Some(span);427 }428429 drv_graph.get(drv_path).and_then(|e| e.span.clone())430}431432#[derive(Debug)]433enum FieldValue {434 Int(i32),435 Str(String),436}437438struct StartActivityBuilder {439 activity_id: u64,440 verbosity: Verbosity,441 typ: ActivityType,442 fields: Vec<FieldValue>,443}444impl StartActivityBuilder {445 fn add_int_field(&mut self, i: i32) {446 self.fields.push(FieldValue::Int(i));447 }448 fn add_string_field(&mut self, v: &[u8]) {449 let v = String::from_utf8_lossy(v);450 self.fields.push(FieldValue::Str(v.to_string()));451 }452 fn emit(&mut self, parent: u64, s: &str) {453 let graph_span = if matches!(self.typ, ActivityType::Build) {454 self.fields.first().and_then(|f| match f {455 FieldValue::Str(drv_path) => {456 let clean = parse_path(drv_path);457 let span = ensure_drv_span(&clean);458 if span.is_some() {459 ACTIVITY_TO_DRV460 .lock()461 .expect("not poisoned")462 .insert(self.activity_id, clean.to_owned());463 }464 span465 }466 _ => None,467 })468 } else {469 None470 };471472 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");473474 let span = if let Some(span) = graph_span {475 #[cfg(feature = "indicatif")]476 span.pb_start();477 span478 } else {479 let parent = mapping.get(&parent);480 let _in_parent = parent.map(|p| p.enter());481 let level: Level = self.verbosity.into();482 if level == Level::ERROR {483 self.typ484 .format(&self.fields, s, |v| error_span!("action", v))485 } else if level == Level::WARN {486 self.typ487 .format(&self.fields, s, |v| warn_span!("action", v))488 } else if level == Level::INFO {489 self.typ490 .format(&self.fields, s, |v| info_span!("action", v))491 } else if level == Level::DEBUG {492 self.typ493 .format(&self.fields, s, |v| debug_span!("action", v))494 } else {495 self.typ496 .format(&self.fields, s, |v| trace_span!("action", v))497 }498 };499 if !s.trim().is_empty() {500 let s = ansi_filter(s);501 #[cfg(feature = "indicatif")]502 {503 span.pb_set_message(&s);504 }505 let _e = span.enter();506 let level: Level = self.verbosity.into();507 if level == Level::ERROR {508 error!(target: "nix", "{}", s)509 } else if level == Level::WARN {510 warn!(target: "nix", "{}", s)511 } else if level == Level::INFO {512 info!(target: "nix", "{}", s)513 } else if level == Level::DEBUG {514 if s != "querying info about missing paths" {515 debug!(target: "nix", "{}", s)516 }517 } else {518 trace!(target: "nix", "{}", s)519 }520 } else {521 #[cfg(feature = "indicatif")]522 {523 span.pb_start();524 }525 }526 mapping.insert(self.activity_id, span);527 }528 fn emit_result(&mut self, ty: u32) {529 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");530531 let Some(parent) = mapping.get(&self.activity_id) else {532 panic!("unexpected result for dead parent");533 };534535 let _in_parent = parent.enter();536 let res = ResultType::from_int(ty);537538 use FieldValue::*;539 match (&res, self.fields.as_slice()) {540 541 (ResultType::BuildLogLine, [Str(s)]) => {542 let s = ansi_filter(s);543 info!(target: "nix::build", "{s}");544 }545 546 547 548 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {549 let _act_ty = ActivityType::from_int(*act_ty as u32);550 }551 (ResultType::SetPhase, [Str(phase)]) => {552 553 debug!(target: "nix::phase", phase)554 }555 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {556 #[cfg(feature = "indicatif")]557 {558 parent.pb_set_length(*_expected as u64);559 parent.pb_set_position(*_done as u64);560 }561 }562 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),563 }564 }565}566fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {567 Box::new(StartActivityBuilder {568 activity_id,569 verbosity: Verbosity::from_int(lvl),570 typ: ActivityType::from_int(typ),571 fields: vec![],572 })573}574575fn emit_warn(v: &str) {576 warn!(target: "nix::eval", "{v}")577}578fn emit_stop(v: u64) {579 {580 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");581 mapping.remove(&v);582 }583 if let Some(drv_path) = ACTIVITY_TO_DRV.lock().expect("not poisoned").remove(&v) {584 if let Some(entry) = DRV_GRAPH.lock().expect("not poisoned").get_mut(&drv_path) {585 entry.span = None;586 }587 }588}589fn emit_log(lvl: u32, v: &[u8]) {590 let verbosity = Verbosity::from_int(lvl);591 let level: Level = verbosity.into();592 let v = String::from_utf8_lossy(v);593 if level == Level::ERROR {594 error!(target: "nix", "{v}")595 } else if level == Level::WARN {596 warn!(target: "nix", "{v}")597 } else if level == Level::INFO {598 info!(target: "nix", "{v}")599 } else if level == Level::DEBUG {600 if v != "querying info about missing paths" {601 debug!(target: "nix", "{v}")602 }603 } else {604 trace!(target: "nix", "{v}")605 }606}607608struct AnsiFiltered {609 output: String,610}611impl vte::Perform for AnsiFiltered {612 fn print(&mut self, c: char) {613 self.output.push(c);614 }615616 fn execute(&mut self, byte: u8) {617 618 if byte == b'\n' {619 self.output.push('\n');620 } else if byte == b'\t' {621 622 self.output.push('\t');623 }624 }625626 fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}627 fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}628629 fn csi_dispatch(630 &mut self,631 params: &vte::Params,632 _intermediates: &[u8],633 _ignore: bool,634 action: char,635 ) {636 use std::fmt::Write;637 if action != 'm' {638 639 return;640 }641 self.output.push_str("\x1b[");642 for (i, par) in params.iter().enumerate() {643 if i != 0 {644 let _ = write!(self.output, ";");645 }646 for (i, sub) in par.iter().enumerate() {647 if i != 0 {648 let _ = write!(self.output, ":");649 }650 let _ = write!(self.output, "{sub}");651 }652 }653 self.output.push(action);654 }655}656fn ansi_filter(i: &str) -> String {657 let mut out = AnsiFiltered {658 output: String::new(),659 };660 let mut parser = Parser::new();661662 663 for chunk in i.as_bytes().chunks(50) {664 parser.advance(&mut out, chunk);665 }666667 out.output668}669670#[derive(Debug)]671pub struct StackFrame {672 pub msg: String,673 pub pos: String,674}675676#[derive(Debug)]677pub struct ErrorInfoBuilder {678 level: Level,679 msg: String,680 pub stack_frames: Vec<StackFrame>,681}682fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder> {683 let verbosity = Verbosity::from_int(lvl);684 let level: Level = verbosity.into();685 let v = String::from_utf8_lossy(v);686 Box::new(ErrorInfoBuilder {687 level,688 msg: v.to_string(),689 stack_frames: Vec::new(),690 })691}692impl ErrorInfoBuilder {693 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]) {694 let v = String::from_utf8_lossy(v);695 let pos = String::from_utf8_lossy(pos);696 self.stack_frames.push(StackFrame {697 msg: v.to_string(),698 pos: pos.to_string(),699 });700 }701 fn emit_error_info(&mut self) {702 error!("{}", self.msg);703 for frame in &self.stack_frames {704 error!(" {} at {}", frame.msg, frame.pos)705 }706 }707}708709#[cxx::bridge]710pub mod nix_logging_cxx {711 extern "Rust" {712 type StartActivityBuilder;713 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;714 fn add_int_field(&mut self, i: i32);715 fn add_string_field(&mut self, v: &[u8]);716 fn emit(&mut self, parent: u64, s: &str);717 fn emit_result(&mut self, ty: u32);718 }719 extern "Rust" {720 type ErrorInfoBuilder;721 fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder>;722 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]);723 fn emit_error_info(&mut self);724 }725 extern "Rust" {726 fn emit_warn(v: &str);727 fn emit_stop(id: u64);728 fn emit_log(lvl: u32, v: &[u8]);729 }730 unsafe extern "C++" {731 include!("nix-eval/src/logging.hh");732733 type nix_c_context = crate::nix_raw::c_context;734735 fn apply_tracing_logger();736 unsafe fn extract_error_info(ctx: *const nix_c_context) -> Box<ErrorInfoBuilder>;737 }738}739740unsafe impl ExternType for crate::nix_raw::c_context {741 type Id = cxx::type_id!("nix_c_context");742743 type Kind = cxx::kind::Opaque;744}