1use std::collections::HashMap;2use std::fmt::Arguments;3use std::sync::{LazyLock, Mutex};45use tracing::{6 Level, Span, debug, debug_span, error, error_span, info, info_span, trace, trace_span, warn,7 warn_span,8};9#[cfg(feature = "indicatif")]10use tracing_indicatif::span_ext::IndicatifSpanExt as _;11use vte::Parser;1213#[derive(Debug)]14enum ActivityType {15 Unknown = 0,16 CopyPath = 100,17 FileTransfer = 101,18 Realise = 102,19 CopyPaths = 103,20 Builds = 104,21 Build = 105,22 OptimiseStore = 106,23 VerifyPaths = 107,24 Substitute = 108,25 QueryPathInfo = 109,26 PostBuildHook = 110,27 BuildWaiting = 111,28 FetchTree = 112,29}3031fn strip_prefix_suffix<'s, 'p>(a: &'s str, pref: &'p str, suff: &'p str) -> Option<&'s str> {32 a.strip_prefix(pref)?.strip_suffix(suff)33}3435fn parse_path(path: &str) -> &str {36 strip_prefix_suffix(path, "\x1b[35;1m", "\x1b[0m").unwrap_or(path)37}3839fn parse_drv(drv: &str) -> &str {40 let drv = parse_path(drv);41 if let Some(pkg) = drv.strip_prefix("/nix/store/") {42 let mut it = pkg.splitn(2, '-');43 it.next();44 if let Some(pkg) = it.next() {45 return pkg;46 }47 }48 drv49}50fn parse_host(host: &str) -> &str {51 if host.is_empty() || host == "local" {52 return "local";53 }54 55 host.strip_prefix("https://").unwrap_or(host)56}5758impl ActivityType {59 fn name(&self) -> &'static str {60 match self {61 ActivityType::Unknown => "nix",62 ActivityType::CopyPath => "nix::copy-path",63 ActivityType::FileTransfer => "nix::file-transfer",64 ActivityType::Realise => "nix::realise",65 ActivityType::CopyPaths => "nix::copy-paths",66 ActivityType::Builds => "nix::builds",67 ActivityType::Build => "nix::build",68 ActivityType::OptimiseStore => "nix::optimise-store",69 ActivityType::VerifyPaths => "nix::verify-paths",70 ActivityType::Substitute => "nix::substitute",71 ActivityType::QueryPathInfo => "nix::query-path-info",72 ActivityType::PostBuildHook => "nix::post-build-hook",73 ActivityType::BuildWaiting => "nix::build-waiting",74 ActivityType::FetchTree => "nix::fetch-tree",75 }76 }77 fn format(78 &self,79 values: &[FieldValue],80 s: &str,81 into: impl FnOnce(Arguments<'_>) -> Span,82 ) -> Span {83 use FieldValue::*;84 match (self, values) {85 (ActivityType::QueryPathInfo, [Str(drv), Str(host)]) => {86 let drv = parse_drv(drv);87 let host = parse_host(host);88 debug_span!(target: "nix::query-path-info", "querying", drv, host)89 }90 (ActivityType::Substitute, [Str(drv), Str(host)]) => {91 let drv = parse_drv(drv);92 let host = parse_host(host);93 debug_span!(target: "nix::substitute", "substituting", drv, host)94 }95 (ActivityType::CopyPath, [Str(drv), Str(from), Str(to)]) => {96 let drv = parse_drv(drv);97 let from = parse_host(from);98 let to = parse_host(to);99 debug_span!(target: "nix::copy-path", "copying", drv, from, to)100 }101 (ActivityType::Build, [Str(drv), Str(host), Int(_), Int(_)]) => {102 let drv = parse_drv(drv);103 let host = parse_host(host);104 info_span!(target: "nix::build", "building", drv, host)105 }106 (ActivityType::FileTransfer, [Str(file)]) => {107 info_span!(target: "nix::file-transfer", "downloading", file)108 }109 (ActivityType::Realise, []) => {110 debug_span!(target: "nix::realise", "realising")111 }112 (ActivityType::CopyPaths, []) => {113 debug_span!(target: "nix::copy-paths", "copying paths")114 }115 (ActivityType::Unknown, [])116 if s.starts_with("copying \"") && s.ends_with("\" to the store") =>117 {118 let tree = s119 .trim_start_matches("copying \"")120 .trim_end_matches("\" to the store");121 debug_span!(target: "nix::trees", "copying", tree)122 }123 (ActivityType::Unknown, [])124 if s.starts_with("copying '") && s.ends_with("' to the store") =>125 {126 let tree = s127 .trim_start_matches("copying '")128 .trim_end_matches("' to the store");129 debug_span!(target: "nix::trees", "copying", tree)130 }131 (ActivityType::Unknown, []) if s.starts_with("hashing '") && s.ends_with("'") => {132 let tree = s.trim_start_matches("hashing '").trim_end_matches("'");133 debug_span!(target: "nix::trees", "hashing", tree)134 }135 (ActivityType::Unknown, []) if s.starts_with("connecting to '") && s.ends_with("'") => {136 let host = s137 .trim_start_matches("connecting to '")138 .trim_end_matches("'");139 debug_span!(target: "nix::remote", "connecting", host)140 }141 (ActivityType::Unknown, [])142 if s.starts_with("copying outputs from '") && s.ends_with("'") =>143 {144 let host = s145 .trim_start_matches("copying outputs from '")146 .trim_end_matches("'");147 debug_span!(target: "nix::remote", "copying outputs", host)148 }149 (ActivityType::Unknown, [])150 if s.starts_with("copying dependencies to '") && s.ends_with("'") =>151 {152 let host = s153 .trim_start_matches("copying dependencies to '")154 .trim_end_matches("'");155 debug_span!(target: "nix::remote", "copying dependencies", host)156 }157 (ActivityType::Unknown, [])158 if s.starts_with("waiting for the upload lock to '") && s.ends_with("'") =>159 {160 let host = s161 .trim_start_matches("waiting for the upload lock to '")162 .trim_end_matches("'");163 debug_span!(target: "nix::remote", "waiting for upload lock", host)164 }165 (ActivityType::BuildWaiting, [])166 if s.starts_with("waiting for a machine to build '") && s.ends_with("'") =>167 {168 let drv = parse_drv(169 s.trim_start_matches("waiting for a machine to build '")170 .trim_end_matches("'"),171 );172 debug_span!(target: "nix::build-waiting", "waiting for available builder", drv)173 }174 (ActivityType::Unknown, []) if s == "querying info about missing paths" => {175 debug_span!(target: "nix::remote", "querying")176 }177 _ => into(format_args!("{}({values:?})", self.name())),178 }179 }180 fn from_int(v: u32) -> Self {181 match v {182 0 => Self::Unknown,183 100 => Self::CopyPath,184 101 => Self::FileTransfer,185 102 => Self::Realise,186 103 => Self::CopyPaths,187 104 => Self::Builds,188 105 => Self::Build,189 106 => Self::OptimiseStore,190 107 => Self::VerifyPaths,191 108 => Self::Substitute,192 109 => Self::QueryPathInfo,193 110 => Self::PostBuildHook,194 111 => Self::BuildWaiting,195 112 => Self::FetchTree,196 _ => {197 warn!("unknown nix action: {v}");198 Self::Unknown199 }200 }201 }202}203204#[derive(Debug)]205enum ResultType {206 FileLinked = 100,207 BuildLogLine = 101,208 UntrustedPath = 102,209 CorruptedPath = 103,210 SetPhase = 104,211 Progress = 105,212 SetExpected = 106,213 PostBuildLogLine = 107,214 FetchStatus = 108,215216 Unknown = 999,217}218impl ResultType {219 fn from_int(v: u32) -> Self {220 match v {221 100 => Self::FileLinked,222 101 => Self::BuildLogLine,223 102 => Self::UntrustedPath,224 103 => Self::CorruptedPath,225 104 => Self::SetPhase,226 105 => Self::Progress,227 106 => Self::SetExpected,228 107 => Self::PostBuildLogLine,229 108 => Self::FetchStatus,230231 _ => {232 warn!("unknown nix result: {v}");233 Self::Unknown234 }235 }236 }237}238#[derive(Clone, Copy)]239enum Verbosity {240 Error,241 Warn,242 Notice,243 Info,244 Talkative,245 Chatty,246 Debug,247 Vomit,248}249impl From<Verbosity> for tracing::Level {250 fn from(val: Verbosity) -> Self {251 match val {252 Verbosity::Error => Level::ERROR,253 Verbosity::Warn => Level::WARN,254 Verbosity::Notice => Level::WARN,255 Verbosity::Info => Level::INFO,256 Verbosity::Talkative => Level::DEBUG,257 Verbosity::Chatty => Level::DEBUG,258 Verbosity::Debug => Level::DEBUG,259 Verbosity::Vomit => Level::TRACE,260 }261 }262}263impl Verbosity {264 fn from_int(u: u32) -> Self {265 [266 Self::Error,267 Self::Warn,268 Self::Notice,269 Self::Info,270 Self::Talkative,271 Self::Chatty,272 Self::Debug,273 Self::Vomit,274 ]275 .get(u as usize)276 .cloned()277 .unwrap_or_else(|| {278 warn!("unknown log level: {u}");279 Verbosity::Vomit280 })281 }282}283284static NIX_SPAN_MAPPING: LazyLock<Mutex<HashMap<u64, Span>>> =285 LazyLock::new(|| Mutex::new(HashMap::new()));286287#[derive(Debug)]288enum FieldValue {289 Int(i32),290 Str(String),291}292293struct StartActivityBuilder {294 activity_id: u64,295 verbosity: Verbosity,296 typ: ActivityType,297 fields: Vec<FieldValue>,298}299impl StartActivityBuilder {300 fn add_int_field(&mut self, i: i32) {301 self.fields.push(FieldValue::Int(i));302 }303 fn add_string_field(&mut self, v: &str) {304 self.fields.push(FieldValue::Str(v.to_owned()));305 }306 fn emit(&mut self, parent: u64, s: &str) {307 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");308309 let parent = mapping.get(&parent);310311 312 313 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 356357 let span = {358 let _in_parent = parent.map(|p| p.enter());359 let level: Level = self.verbosity.into();360 if level == Level::ERROR {361 self.typ362 .format(&self.fields, s, |v| error_span!("action", v))363 } else if level == Level::WARN {364 self.typ365 .format(&self.fields, s, |v| warn_span!("action", v))366 } else if level == Level::INFO {367 self.typ368 .format(&self.fields, s, |v| info_span!("action", v))369 } else if level == Level::DEBUG {370 self.typ371 .format(&self.fields, s, |v| debug_span!("action", v))372 } else {373 self.typ374 .format(&self.fields, s, |v| trace_span!("action", v))375 }376 };377 if !s.trim().is_empty() {378 let s = ansi_filter(s);379 #[cfg(feature = "indicatif")]380 {381 span.pb_set_message(s);382 }383 let _e = span.enter();384 let level: Level = self.verbosity.into();385 if level == Level::ERROR {386 error!(target: "nix", "{}", s)387 } else if level == Level::WARN {388 warn!(target: "nix", "{}", s)389 } else if level == Level::INFO {390 info!(target: "nix", "{}", s)391 } else if level == Level::DEBUG {392 debug!(target: "nix", "{}", s)393 } else {394 trace!(target: "nix", "{}", s)395 }396 } else {397 #[cfg(feature = "indicatif")]398 {399 span.pb_start();400 }401 }402 mapping.insert(self.activity_id, span);403 }404 fn emit_result(&mut self, ty: u32) {405 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");406407 let Some(parent) = mapping.get(&self.activity_id) else {408 panic!("unexpected result for dead parent");409 };410411 let _in_parent = parent.enter();412 let res = ResultType::from_int(ty);413414 use FieldValue::*;415 match (&res, self.fields.as_slice()) {416 417 (ResultType::BuildLogLine, [Str(s)]) => {418 let s = ansi_filter(s);419 info!("{s}");420 }421 422 423 424 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {425 let _act_ty = ActivityType::from_int(*act_ty as u32);426 }427 (ResultType::SetPhase, [Str(phase)]) => {428 429 debug!(target: "nix::phase", phase)430 }431 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {432 #[cfg(feature = "indicatif")]433 {434 parent.pb_set_length(*_expected as u64);435 parent.pb_set_position(*_done as u64);436 }437 }438 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),439 }440 }441}442fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {443 Box::new(StartActivityBuilder {444 activity_id,445 verbosity: Verbosity::from_int(lvl),446 typ: ActivityType::from_int(typ),447 fields: vec![],448 })449}450451fn emit_warn(v: &str) {452 warn!(target: "nix::eval", "{v}")453}454fn emit_stop(v: u64) {455 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");456 mapping.remove(&v);457}458fn emit_log(lvl: u32, v: &str) {459 let verbosity = Verbosity::from_int(lvl);460 let level: Level = verbosity.into();461 if level == Level::ERROR {462 error!(target: "nix", "{v}")463 } else if level == Level::WARN {464 warn!(target: "nix", "{v}")465 } else if level == Level::INFO {466 info!(target: "nix", "{v}")467 } else if level == Level::DEBUG {468 debug!(target: "nix", "{v}")469 } else {470 trace!(target: "nix", "{v}")471 }472}473474struct AnsiFiltered {475 output: String,476}477impl vte::Perform for AnsiFiltered {478 fn print(&mut self, c: char) {479 self.output.push(c);480 }481482 fn execute(&mut self, byte: u8) {483 484 if byte == b'\n' {485 self.output.push('\n');486 } else if byte == b'\t' {487 488 self.output.push('\t');489 }490 }491492 fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}493 fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}494495 fn csi_dispatch(496 &mut self,497 params: &vte::Params,498 _intermediates: &[u8],499 _ignore: bool,500 action: char,501 ) {502 use std::fmt::Write;503 if action != 'm' {504 505 return;506 }507 self.output.push_str("IDK\x1b[");508 for (i, par) in params.iter().enumerate() {509 if i != 0 {510 let _ = write!(self.output, ";");511 }512 for (i, sub) in par.iter().enumerate() {513 if i != 0 {514 let _ = write!(self.output, ":");515 }516 let _ = write!(self.output, "{sub}");517 }518 }519 self.output.push(action);520 }521}522fn ansi_filter(i: &str) -> String {523 let mut out = AnsiFiltered {524 output: String::new(),525 };526 let mut parser = Parser::new();527528 529 for chunk in i.as_bytes().chunks(50) {530 parser.advance(&mut out, chunk);531 }532533 out.output534}535536#[cxx::bridge]537pub mod nix_logging_cxx {538 extern "Rust" {539 type StartActivityBuilder;540 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;541 fn add_int_field(&mut self, i: i32);542 fn add_string_field(&mut self, v: &str);543 fn emit(&mut self, parent: u64, s: &str);544 fn emit_result(&mut self, ty: u32);545546 fn emit_warn(v: &str);547 fn emit_stop(id: u64);548 fn emit_log(lvl: u32, v: &str);549 }550 unsafe extern "C++" {551 include!("nix-eval/src/logging.hh");552553 fn apply_tracing_logger();554 }555}