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 _;1112#[derive(Debug)]13enum ActivityType {14 Unknown = 0,15 CopyPath = 100,16 FileTransfer = 101,17 Realise = 102,18 CopyPaths = 103,19 Builds = 104,20 Build = 105,21 OptimiseStore = 106,22 VerifyPaths = 107,23 Substitute = 108,24 QueryPathInfo = 109,25 PostBuildHook = 110,26 BuildWaiting = 111,27 FetchTree = 112,28}2930fn strip_prefix_suffix<'s, 'p>(a: &'s str, pref: &'p str, suff: &'p str) -> Option<&'s str> {31 a.strip_prefix(pref)?.strip_suffix(suff)32}3334fn parse_path(path: &str) -> &str {35 strip_prefix_suffix(path, "\x1b[35;1m", "\x1b[0m").unwrap_or(path)36}3738fn parse_drv(drv: &str) -> &str {39 let drv = parse_path(drv);40 if let Some(pkg) = drv.strip_prefix("/nix/store/") {41 let mut it = pkg.splitn(2, '-');42 it.next();43 if let Some(pkg) = it.next() {44 return pkg;45 }46 }47 drv48}49fn parse_host(host: &str) -> &str {50 if host.is_empty() || host == "local" {51 return "local";52 }53 54 host.strip_prefix("https://").unwrap_or(host)55}5657impl ActivityType {58 fn name(&self) -> &'static str {59 match self {60 ActivityType::Unknown => "nix",61 ActivityType::CopyPath => "nix::copy-path",62 ActivityType::FileTransfer => "nix::file-transfer",63 ActivityType::Realise => "nix::realise",64 ActivityType::CopyPaths => "nix::copy-paths",65 ActivityType::Builds => "nix::builds",66 ActivityType::Build => "nix::build",67 ActivityType::OptimiseStore => "nix::optimise-store",68 ActivityType::VerifyPaths => "nix::verify-paths",69 ActivityType::Substitute => "nix::substitute",70 ActivityType::QueryPathInfo => "nix::query-path-info",71 ActivityType::PostBuildHook => "nix::post-build-hook",72 ActivityType::BuildWaiting => "nix::build-waiting",73 ActivityType::FetchTree => "nix::fetch-tree",74 }75 }76 fn format(77 &self,78 values: &[FieldValue],79 s: &str,80 into: impl FnOnce(Arguments<'_>) -> Span,81 ) -> Span {82 use FieldValue::*;83 match (self, values) {84 (ActivityType::QueryPathInfo, [Str(drv), Str(host)]) => {85 let drv = parse_drv(drv);86 let host = parse_host(host);87 debug_span!(target: "nix::query-path-info", "querying", drv, host)88 }89 (ActivityType::Substitute, [Str(drv), Str(host)]) => {90 let drv = parse_drv(drv);91 let host = parse_host(host);92 debug_span!(target: "nix::substitute", "substituting", drv, host)93 }94 (ActivityType::CopyPath, [Str(drv), Str(from), Str(to)]) => {95 let drv = parse_drv(drv);96 let from = parse_host(from);97 let to = parse_host(to);98 debug_span!(target: "nix::copy-path", "copying", drv, from, to)99 }100 (ActivityType::Build, [Str(drv), Str(host), Int(_), Int(_)]) => {101 let drv = parse_drv(drv);102 let host = parse_host(host);103 info_span!(target: "nix::build", "building", drv, host)104 }105 (ActivityType::FileTransfer, [Str(file)]) => {106 info_span!(target: "nix::file-transfer", "downloading", file)107 }108 (ActivityType::Realise, []) => {109 debug_span!(target: "nix::realise", "realising")110 }111 (ActivityType::CopyPaths, []) => {112 debug_span!(target: "nix::copy-paths", "copying paths")113 }114 (ActivityType::Unknown, [])115 if s.starts_with("copying \"") && s.ends_with("\" to the store") =>116 {117 let tree = s118 .trim_start_matches("copying \"")119 .trim_end_matches("\" to the store");120 debug_span!(target: "nix::trees", "copying", tree)121 }122 (ActivityType::Unknown, [])123 if s.starts_with("copying '") && s.ends_with("' to the store") =>124 {125 let tree = s126 .trim_start_matches("copying '")127 .trim_end_matches("' to the store");128 debug_span!(target: "nix::trees", "copying", tree)129 }130 (ActivityType::Unknown, []) if s.starts_with("hashing '") && s.ends_with("'") => {131 let tree = s.trim_start_matches("hashing '").trim_end_matches("'");132 debug_span!(target: "nix::trees", "hashing", tree)133 }134 (ActivityType::Unknown, []) if s.starts_with("connecting to '") && s.ends_with("'") => {135 let host = s136 .trim_start_matches("connecting to '")137 .trim_end_matches("'");138 debug_span!(target: "nix::remote", "connecting", host)139 }140 (ActivityType::Unknown, [])141 if s.starts_with("copying outputs from '") && s.ends_with("'") =>142 {143 let host = s144 .trim_start_matches("copying outputs from '")145 .trim_end_matches("'");146 debug_span!(target: "nix::remote", "copying outputs", host)147 }148 (ActivityType::Unknown, [])149 if s.starts_with("copying dependencies to '") && s.ends_with("'") =>150 {151 let host = s152 .trim_start_matches("copying dependencies to '")153 .trim_end_matches("'");154 debug_span!(target: "nix::remote", "copying dependencies", host)155 }156 (ActivityType::Unknown, [])157 if s.starts_with("waiting for the upload lock to '") && s.ends_with("'") =>158 {159 let host = s160 .trim_start_matches("waiting for the upload lock to '")161 .trim_end_matches("'");162 debug_span!(target: "nix::remote", "waiting for upload lock", host)163 }164 (ActivityType::BuildWaiting, [])165 if s.starts_with("waiting for a machine to build '") && s.ends_with("'") =>166 {167 let drv = parse_drv(168 s.trim_start_matches("waiting for a machine to build '")169 .trim_end_matches("'"),170 );171 debug_span!(target: "nix::build-waiting", "waiting for available builder", drv)172 }173 (ActivityType::Unknown, []) if s == "querying info about missing paths" => {174 debug_span!(target: "nix::remote", "querying")175 }176 _ => into(format_args!("{}({values:?})", self.name())),177 }178 }179 fn from_int(v: u32) -> Self {180 match v {181 0 => Self::Unknown,182 100 => Self::CopyPath,183 101 => Self::FileTransfer,184 102 => Self::Realise,185 103 => Self::CopyPaths,186 104 => Self::Builds,187 105 => Self::Build,188 106 => Self::OptimiseStore,189 107 => Self::VerifyPaths,190 108 => Self::Substitute,191 109 => Self::QueryPathInfo,192 110 => Self::PostBuildHook,193 111 => Self::BuildWaiting,194 112 => Self::FetchTree,195 _ => {196 warn!("unknown nix action: {v}");197 Self::Unknown198 }199 }200 }201}202203#[derive(Debug)]204enum ResultType {205 FileLinked = 100,206 BuildLogLine = 101,207 UntrustedPath = 102,208 CorruptedPath = 103,209 SetPhase = 104,210 Progress = 105,211 SetExpected = 106,212 PostBuildLogLine = 107,213 FetchStatus = 108,214215 Unknown = 999,216}217impl ResultType {218 fn from_int(v: u32) -> Self {219 match v {220 100 => Self::FileLinked,221 101 => Self::BuildLogLine,222 102 => Self::UntrustedPath,223 103 => Self::CorruptedPath,224 104 => Self::SetPhase,225 105 => Self::Progress,226 106 => Self::SetExpected,227 107 => Self::PostBuildLogLine,228 108 => Self::FetchStatus,229230 _ => {231 warn!("unknown nix result: {v}");232 Self::Unknown233 }234 }235 }236}237#[derive(Clone, Copy)]238enum Verbosity {239 Error,240 Warn,241 Notice,242 Info,243 Talkative,244 Chatty,245 Debug,246 Vomit,247}248impl From<Verbosity> for tracing::Level {249 fn from(val: Verbosity) -> Self {250 match val {251 Verbosity::Error => Level::ERROR,252 Verbosity::Warn => Level::WARN,253 Verbosity::Notice => Level::WARN,254 Verbosity::Info => Level::INFO,255 Verbosity::Talkative => Level::DEBUG,256 Verbosity::Chatty => Level::DEBUG,257 Verbosity::Debug => Level::DEBUG,258 Verbosity::Vomit => Level::TRACE,259 }260 }261}262impl Verbosity {263 fn from_int(u: u32) -> Self {264 [265 Self::Error,266 Self::Warn,267 Self::Notice,268 Self::Info,269 Self::Talkative,270 Self::Chatty,271 Self::Debug,272 Self::Vomit,273 ]274 .get(u as usize)275 .cloned()276 .unwrap_or_else(|| {277 warn!("unknown log level: {u}");278 Verbosity::Vomit279 })280 }281}282283static NIX_SPAN_MAPPING: LazyLock<Mutex<HashMap<u64, Span>>> =284 LazyLock::new(|| Mutex::new(HashMap::new()));285286#[derive(Debug)]287enum FieldValue {288 Int(i32),289 Str(String),290}291292struct StartActivityBuilder {293 activity_id: u64,294 verbosity: Verbosity,295 typ: ActivityType,296 fields: Vec<FieldValue>,297}298impl StartActivityBuilder {299 fn add_int_field(&mut self, i: i32) {300 self.fields.push(FieldValue::Int(i));301 }302 fn add_string_field(&mut self, v: &str) {303 self.fields.push(FieldValue::Str(v.to_owned()));304 }305 fn emit(&mut self, parent: u64, s: &str) {306 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");307308 let parent = mapping.get(&parent);309310 311 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 355356 let span = {357 let _in_parent = parent.map(|p| p.enter());358 let level: Level = self.verbosity.into();359 if level == Level::ERROR {360 self.typ361 .format(&self.fields, s, |v| error_span!("action", v))362 } else if level == Level::WARN {363 self.typ364 .format(&self.fields, s, |v| warn_span!("action", v))365 } else if level == Level::INFO {366 self.typ367 .format(&self.fields, s, |v| info_span!("action", v))368 } else if level == Level::DEBUG {369 self.typ370 .format(&self.fields, s, |v| debug_span!("action", v))371 } else {372 self.typ373 .format(&self.fields, s, |v| trace_span!("action", v))374 }375 };376 if !s.trim().is_empty() {377 #[cfg(feature = "indicatif")]378 {379 span.pb_set_message(s);380 }381 let _e = span.enter();382 let level: Level = self.verbosity.into();383 if level == Level::ERROR {384 error!(target: "nix", "{}", s)385 } else if level == Level::WARN {386 warn!(target: "nix", "{}", s)387 } else if level == Level::INFO {388 info!(target: "nix", "{}", s)389 } else if level == Level::DEBUG {390 debug!(target: "nix", "{}", s)391 } else {392 trace!(target: "nix", "{}", s)393 }394 } else {395 #[cfg(feature = "indicatif")]396 {397 span.pb_start();398 }399 }400 mapping.insert(self.activity_id, span);401 }402 fn emit_result(&mut self, ty: u32) {403 let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");404405 let Some(parent) = mapping.get(&self.activity_id) else {406 panic!("unexpected result for dead parent");407 };408409 let _in_parent = parent.enter();410 let res = ResultType::from_int(ty);411412 use FieldValue::*;413 match (&res, self.fields.as_slice()) {414 415 (ResultType::BuildLogLine, [Str(s)]) => {416 info!("{s:?}");417 }418 419 420 421 (ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {422 let _act_ty = ActivityType::from_int(*act_ty as u32);423 }424 (ResultType::SetPhase, [Str(phase)]) => {425 426 debug!(target: "nix::phase", phase)427 }428 (ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {429 #[cfg(feature = "indicatif")]430 {431 parent.pb_set_length(*_expected as u64);432 parent.pb_set_position(*_done as u64);433 }434 }435 _ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),436 }437 }438}439fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {440 Box::new(StartActivityBuilder {441 activity_id,442 verbosity: Verbosity::from_int(lvl),443 typ: ActivityType::from_int(typ),444 fields: vec![],445 })446}447448fn emit_warn(v: &str) {449 warn!(target: "nix::eval", "{v}")450}451fn emit_stop(v: u64) {452 let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");453 mapping.remove(&v);454}455fn emit_log(lvl: u32, v: &str) {456 let verbosity = Verbosity::from_int(lvl);457 let level: Level = verbosity.into();458 if level == Level::ERROR {459 error!(target: "nix", "{v}")460 } else if level == Level::WARN {461 warn!(target: "nix", "{v}")462 } else if level == Level::INFO {463 info!(target: "nix", "{v}")464 } else if level == Level::DEBUG {465 debug!(target: "nix", "{v}")466 } else {467 trace!(target: "nix", "{v}")468 }469}470471#[cxx::bridge]472pub mod nix_logging_cxx {473 extern "Rust" {474 type StartActivityBuilder;475 fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;476 fn add_int_field(&mut self, i: i32);477 fn add_string_field(&mut self, v: &str);478 fn emit(&mut self, parent: u64, s: &str);479 fn emit_result(&mut self, ty: u32);480481 fn emit_warn(v: &str);482 fn emit_stop(id: u64);483 fn emit_log(lvl: u32, v: &str);484 }485 unsafe extern "C++" {486 include!("nix-eval/src/logging.hh");487488 fn apply_tracing_logger();489 }490}