git.delta.rocks / jrsonnet / refs/commits / cd7c759361f6

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	// https/ssh is the default54	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		// let meta = spans.alloc_metadata(311		// 	self.typ.name(),312		// 	self.verbosity.into(),313		// 	MetadataKind::Span,314		// 	"nix activity start",315		// 	None,316		// 	None,317		// 	None,318		// 	self.typ.fields(),319		// );320		//321		// let mut fields = meta.fields().iter();322		// let span = if let Some(parent) = parent {323		// 	let s = Span::new(324		// 		meta,325		// 		&match meta.fields().len() {326		// 			1 => meta.fields().value_set(327		// 				&<[_; 1]>::try_from([(328		// 					&fields.next().expect("has field"),329		// 					Some(&format_args!("Test") as &dyn tracing::Value),330		// 				)])331		// 				.expect("valid size"),332		// 			),333		// 			_ => unreachable!(),334		// 		},335		// 	);336		// 	s.follows_from(parent);337		// 	s338		// } else {339		// 	Span::new_root(340		// 		meta,341		// 		&match meta.fields().len() {342		// 			1 => meta.fields().value_set(343		// 				&<[_; 1]>::try_from([(344		// 					&fields.next().expect("has field"),345		// 					Some(&format_args!("Test") as &dyn tracing::Value),346		// 				)])347		// 				.expect("valid size"),348		// 			),349		// 			_ => unreachable!(),350		// 		},351		// 	)352		// };353		//354		// let id = span.id().expect("id created");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			// ResultType::FileLinked => todo!(),415			(ResultType::BuildLogLine, [Str(s)]) => {416				info!("{s:?}");417			}418			// ResultType::UntrustedPath => todo!(),419			// ResultType::CorruptedPath => todo!(),420			// ResultType::SetPhase => todo!(),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				// parent.pb_set_message(phase);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}