1use std::collections::HashMap;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()));287288#[derive(Debug)]289enum FieldValue {290 Int(i32),291 Str(String),292}293294struct StartActivityBuilder {295 activity_id: u64,296 verbosity: Verbosity,297 typ: ActivityType,298 fields: Vec<FieldValue>,299}300impl StartActivityBuilder {301 fn add_int_field(&mut self, i: i32) {302 self.fields.push(FieldValue::Int(i));303 }304 fn add_string_field(&mut self, v: &[u8]) {305 let v = String::from_utf8_lossy(v);306 self.fields.push(FieldValue::Str(v.to_string()));307 }308 fn emit(&mut self, parent: u64, s: &str) {309 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");310311 let parent = mapping.get(&parent);312313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358359 let span = {360 let _in_parent = parent.map(|p| p.enter());361 let level: Level = self.verbosity.into();362 if level == Level::ERROR {363 self.typ364 .format(&self.fields, s, |v| error_span!("action", v))365 } else if level == Level::WARN {366 self.typ367 .format(&self.fields, s, |v| warn_span!("action", v))368 } else if level == Level::INFO {369 self.typ370 .format(&self.fields, s, |v| info_span!("action", v))371 } else if level == Level::DEBUG {372 self.typ373 .format(&self.fields, s, |v| debug_span!("action", v))374 } else {375 self.typ376 .format(&self.fields, s, |v| trace_span!("action", v))377 }378 };379 if !s.trim().is_empty() {380 let s = ansi_filter(s);381 #[cfg(feature = "indicatif")]382 {383 span.pb_set_message(s);384 }385 let _e = span.enter();386 let level: Level = self.verbosity.into();387 if level == Level::ERROR {388 error!(target: "nix", "{}", s)389 } else if level == Level::WARN {390 warn!(target: "nix", "{}", s)391 } else if level == Level::INFO {392 info!(target: "nix", "{}", s)393 } else if level == Level::DEBUG {394 debug!(target: "nix", "{}", s)395 } else {396 trace!(target: "nix", "{}", s)397 }398 } else {399 #[cfg(feature = "indicatif")]400 {401 span.pb_start();402 }403 }404 mapping.insert(self.activity_id, span);405 }406 fn emit_result(&mut self, ty: u32) {407 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");408409 let Some(parent) = mapping.get(&self.activity_id) else {410 panic!("unexpected result for dead parent");411 };412413 let _in_parent = parent.enter();414 let res = ResultType::from_int(ty);415416 use FieldValue::*;417 match (&res, self.fields.as_slice()) {418 419 (ResultType::BuildLogLine, [Str(s)]) => {420 let s = ansi_filter(s);421 info!("{s}");422 }423 424 425 426 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {427 let _act_ty = ActivityType::from_int(*act_ty as u32);428 }429 (ResultType::SetPhase, [Str(phase)]) => {430 431 debug!(target: "nix::phase", phase)432 }433 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {434 #[cfg(feature = "indicatif")]435 {436 parent.pb_set_length(*_expected as u64);437 parent.pb_set_position(*_done as u64);438 }439 }440 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),441 }442 }443}444fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {445 Box::new(StartActivityBuilder {446 activity_id,447 verbosity: Verbosity::from_int(lvl),448 typ: ActivityType::from_int(typ),449 fields: vec![],450 })451}452453fn emit_warn(v: &str) {454 warn!(target: "nix::eval", "{v}")455}456fn emit_stop(v: u64) {457 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");458 mapping.remove(&v);459}460fn emit_log(lvl: u32, v: &[u8]) {461 let verbosity = Verbosity::from_int(lvl);462 let level: Level = verbosity.into();463 let v = String::from_utf8_lossy(v);464 if level == Level::ERROR {465 error!(target: "nix", "{v}")466 } else if level == Level::WARN {467 warn!(target: "nix", "{v}")468 } else if level == Level::INFO {469 info!(target: "nix", "{v}")470 } else if level == Level::DEBUG {471 debug!(target: "nix", "{v}")472 } else {473 trace!(target: "nix", "{v}")474 }475}476477struct AnsiFiltered {478 output: String,479}480impl vte::Perform for AnsiFiltered {481 fn print(&mut self, c: char) {482 self.output.push(c);483 }484485 fn execute(&mut self, byte: u8) {486 487 if byte == b'\n' {488 self.output.push('\n');489 } else if byte == b'\t' {490 491 self.output.push('\t');492 }493 }494495 fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}496 fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}497498 fn csi_dispatch(499 &mut self,500 params: &vte::Params,501 _intermediates: &[u8],502 _ignore: bool,503 action: char,504 ) {505 use std::fmt::Write;506 if action != 'm' {507 508 return;509 }510 self.output.push_str("\x1b[");511 for (i, par) in params.iter().enumerate() {512 if i != 0 {513 let _ = write!(self.output, ";");514 }515 for (i, sub) in par.iter().enumerate() {516 if i != 0 {517 let _ = write!(self.output, ":");518 }519 let _ = write!(self.output, "{sub}");520 }521 }522 self.output.push(action);523 }524}525fn ansi_filter(i: &str) -> String {526 let mut out = AnsiFiltered {527 output: String::new(),528 };529 let mut parser = Parser::new();530531 532 for chunk in i.as_bytes().chunks(50) {533 parser.advance(&mut out, chunk);534 }535536 out.output537}538539#[derive(Debug)]540pub struct StackFrame {541 pub msg: String,542 pub pos: String,543}544545#[derive(Debug)]546pub struct ErrorInfoBuilder {547 level: Level,548 msg: String,549 pub stack_frames: Vec<StackFrame>,550}551fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder> {552 let verbosity = Verbosity::from_int(lvl);553 let level: Level = verbosity.into();554 let v = String::from_utf8_lossy(v);555 Box::new(ErrorInfoBuilder {556 level,557 msg: v.to_string(),558 stack_frames: Vec::new(),559 })560}561impl ErrorInfoBuilder {562 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]) {563 let v = String::from_utf8_lossy(v);564 let pos = String::from_utf8_lossy(pos);565 self.stack_frames.push(StackFrame {566 msg: v.to_string(),567 pos: pos.to_string(),568 });569 }570 fn emit_error_info(&mut self) {571 error!("{}", self.msg);572 for frame in &self.stack_frames {573 error!(" {} at {}", frame.msg, frame.pos)574 }575 }576}577578#[cxx::bridge]579pub mod nix_logging_cxx {580 extern "Rust" {581 type StartActivityBuilder;582 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;583 fn add_int_field(&mut self, i: i32);584 fn add_string_field(&mut self, v: &[u8]);585 fn emit(&mut self, parent: u64, s: &str);586 fn emit_result(&mut self, ty: u32);587 }588 extern "Rust" {589 type ErrorInfoBuilder;590 fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder>;591 fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]);592 fn emit_error_info(&mut self);593 }594 extern "Rust" {595 fn emit_warn(v: &str);596 fn emit_stop(id: u64);597 fn emit_log(lvl: u32, v: &[u8]);598 }599 unsafe extern "C++" {600 include!("nix-eval/src/logging.hh");601602 type nix_c_context = crate::nix_raw::c_context;603604 fn apply_tracing_logger();605 unsafe fn extract_error_info(ctx: *const nix_c_context) -> Box<ErrorInfoBuilder>;606 }607}608609unsafe impl ExternType for crate::nix_raw::c_context {610 type Id = cxx::type_id!("nix_c_context");611612 type Kind = cxx::kind::Opaque;613}