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: &[u8]) {304 let v = String::from_utf8_lossy(v);305 self.fields.push(FieldValue::Str(v.to_string()));306 }307 fn emit(&mut self, parent: u64, s: &str) {308 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");309310 let parent = mapping.get(&parent);311312 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 356 357358 let span = {359 let _in_parent = parent.map(|p| p.enter());360 let level: Level = self.verbosity.into();361 if level == Level::ERROR {362 self.typ363 .format(&self.fields, s, |v| error_span!("action", v))364 } else if level == Level::WARN {365 self.typ366 .format(&self.fields, s, |v| warn_span!("action", v))367 } else if level == Level::INFO {368 self.typ369 .format(&self.fields, s, |v| info_span!("action", v))370 } else if level == Level::DEBUG {371 self.typ372 .format(&self.fields, s, |v| debug_span!("action", v))373 } else {374 self.typ375 .format(&self.fields, s, |v| trace_span!("action", v))376 }377 };378 if !s.trim().is_empty() {379 let s = ansi_filter(s);380 #[cfg(feature = "indicatif")]381 {382 span.pb_set_message(s);383 }384 let _e = span.enter();385 let level: Level = self.verbosity.into();386 if level == Level::ERROR {387 error!(target: "nix", "{}", s)388 } else if level == Level::WARN {389 warn!(target: "nix", "{}", s)390 } else if level == Level::INFO {391 info!(target: "nix", "{}", s)392 } else if level == Level::DEBUG {393 debug!(target: "nix", "{}", s)394 } else {395 trace!(target: "nix", "{}", s)396 }397 } else {398 #[cfg(feature = "indicatif")]399 {400 span.pb_start();401 }402 }403 mapping.insert(self.activity_id, span);404 }405 fn emit_result(&mut self, ty: u32) {406 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");407408 let Some(parent) = mapping.get(&self.activity_id) else {409 panic!("unexpected result for dead parent");410 };411412 let _in_parent = parent.enter();413 let res = ResultType::from_int(ty);414415 use FieldValue::*;416 match (&res, self.fields.as_slice()) {417 418 (ResultType::BuildLogLine, [Str(s)]) => {419 let s = ansi_filter(s);420 info!("{s}");421 }422 423 424 425 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {426 let _act_ty = ActivityType::from_int(*act_ty as u32);427 }428 (ResultType::SetPhase, [Str(phase)]) => {429 430 debug!(target: "nix::phase", phase)431 }432 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {433 #[cfg(feature = "indicatif")]434 {435 parent.pb_set_length(*_expected as u64);436 parent.pb_set_position(*_done as u64);437 }438 }439 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),440 }441 }442}443fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {444 Box::new(StartActivityBuilder {445 activity_id,446 verbosity: Verbosity::from_int(lvl),447 typ: ActivityType::from_int(typ),448 fields: vec![],449 })450}451452fn emit_warn(v: &str) {453 warn!(target: "nix::eval", "{v}")454}455fn emit_stop(v: u64) {456 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");457 mapping.remove(&v);458}459fn emit_log(lvl: u32, v: &[u8]) {460 let verbosity = Verbosity::from_int(lvl);461 let level: Level = verbosity.into();462 let v = String::from_utf8_lossy(v);463 if level == Level::ERROR {464 error!(target: "nix", "{v}")465 } else if level == Level::WARN {466 warn!(target: "nix", "{v}")467 } else if level == Level::INFO {468 info!(target: "nix", "{v}")469 } else if level == Level::DEBUG {470 debug!(target: "nix", "{v}")471 } else {472 trace!(target: "nix", "{v}")473 }474}475476struct AnsiFiltered {477 output: String,478}479impl vte::Perform for AnsiFiltered {480 fn print(&mut self, c: char) {481 self.output.push(c);482 }483484 fn execute(&mut self, byte: u8) {485 486 if byte == b'\n' {487 self.output.push('\n');488 } else if byte == b'\t' {489 490 self.output.push('\t');491 }492 }493494 fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}495 fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}496497 fn csi_dispatch(498 &mut self,499 params: &vte::Params,500 _intermediates: &[u8],501 _ignore: bool,502 action: char,503 ) {504 use std::fmt::Write;505 if action != 'm' {506 507 return;508 }509 self.output.push_str("\x1b[");510 for (i, par) in params.iter().enumerate() {511 if i != 0 {512 let _ = write!(self.output, ";");513 }514 for (i, sub) in par.iter().enumerate() {515 if i != 0 {516 let _ = write!(self.output, ":");517 }518 let _ = write!(self.output, "{sub}");519 }520 }521 self.output.push(action);522 }523}524fn ansi_filter(i: &str) -> String {525 let mut out = AnsiFiltered {526 output: String::new(),527 };528 let mut parser = Parser::new();529530 531 for chunk in i.as_bytes().chunks(50) {532 parser.advance(&mut out, chunk);533 }534535 out.output536}537538#[cxx::bridge]539pub mod nix_logging_cxx {540 extern "Rust" {541 type StartActivityBuilder;542 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;543 fn add_int_field(&mut self, i: i32);544 fn add_string_field(&mut self, v: &[u8]);545 fn emit(&mut self, parent: u64, s: &str);546 fn emit_result(&mut self, ty: u32);547548 fn emit_warn(v: &str);549 fn emit_stop(id: u64);550 fn emit_log(lvl: u32, v: &[u8]);551 }552 unsafe extern "C++" {553 include!("nix-eval/src/logging.hh");554555 fn apply_tracing_logger();556 }557}