git.delta.rocks / jrsonnet / refs/commits / 521a65806d80

1use std::collections::HashMap;2use std::fmt::Arguments;3use std::sync::{LazyLock, Mutex};45use tracing::{6	Level, Metadata, Span, debug, debug_span, error, error_span, event, info, info_span, trace,7	trace_span, warn, warn_span,8};9use tracing_indicatif::span_ext::IndicatifSpanExt as _;1011#[derive(Debug)]12enum ActivityType {13	Unknown = 0,14	CopyPath = 100,15	FileTransfer = 101,16	Realise = 102,17	CopyPaths = 103,18	Builds = 104,19	Build = 105,20	OptimiseStore = 106,21	VerifyPaths = 107,22	Substitute = 108,23	QueryPathInfo = 109,24	PostBuildHook = 110,25	BuildWaiting = 111,26	FetchTree = 112,27}2829fn strip_prefix_suffix<'s, 'p>(a: &'s str, pref: &'p str, suff: &'p str) -> Option<&'s str> {30	a.strip_prefix(pref)?.strip_suffix(suff)31}3233fn parse_path(path: &str) -> &str {34	let path = strip_prefix_suffix(path, "\x1b[35;1m", "\x1b[0m").unwrap_or(path);35	path36}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 Into<tracing::Level> for Verbosity {249	fn into(self) -> tracing::Level {250		match self {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}282283#[derive(Hash, PartialEq, Eq, Clone, Copy)]284enum MetadataKind {285	Span,286	Event,287}288// impl MetadataKind {289// 	fn kind(&self) -> Kind {290// 		match self {291// 			MetadataKind::Span => Kind::SPAN,292// 			MetadataKind::Event => Kind::EVENT,293// 		}294// 	}295// }296297#[derive(Hash, PartialEq, Eq)]298struct ForeignMetadataInfo {299	target: &'static str,300	level: Level,301	kind: MetadataKind,302	name: &'static str,303	module: Option<&'static str>,304	file: Option<&'static str>,305	line: Option<u32>,306	names: &'static [&'static str],307}308309struct FakeCallsite;310impl tracing::callsite::Callsite for FakeCallsite {311	fn set_interest(&self, interest: tracing::subscriber::Interest) {312		unreachable!()313	}314315	fn metadata(&self) -> &Metadata<'_> {316		unreachable!()317	}318}319const FAKE_CALLSITE: FakeCallsite = FakeCallsite;320321#[cfg(false)]322#[derive(Default)]323struct ForeignSpanData {324	interned: HashSet<&'static str>,325	metadatas: HashMap<ForeignMetadataInfo, &'static Metadata<'static>>,326}327#[cfg(false)]328impl ForeignSpanData {329	fn intern(&mut self, s: &str) -> &'static str {330		if let Some(v) = self.interned.get(s) {331			return *v;332		}333		let leaked: Box<str> = s.into();334		let leaked = Box::leak(leaked);335		self.interned.insert(leaked);336		return leaked;337	}338	fn alloc_metadata<'t>(339		&'t mut self,340		target: &'static str,341		level: Level,342		kind: MetadataKind,343		name: &'static str,344		module: Option<&'static str>,345		file: Option<&'static str>,346		line: Option<u32>,347		names: &'static [&'static str],348	) -> &'static Metadata<'static> {349		let info = ForeignMetadataInfo {350			target,351			level,352			kind,353			name,354			module,355			file,356			line,357			names,358		};359		if let Some(v) = self.metadatas.get(&info) {360			return *v;361		}362		let fake = FakeCallsite;363		let metadata = Box::leak::<'static>(Box::new(Metadata::new(364			name,365			target,366			level,367			file,368			line,369			module,370			FieldSet::new(names, tracing::callsite::Identifier(&FAKE_CALLSITE)),371			kind.kind(),372		)));373374		let meta_raw = &raw const *metadata;375		let fields_raw = &raw const *metadata.fields();376377		// SAFETY: FieldSet struct should be inside of metadata struct... Which we assume here, but do not test378		// FIXME: Safety comment above might be invalidated at any time, this should actually be covered by unit test (or, better: runtime assertion... Somehow.)379		let fields_offset = unsafe { fields_raw.cast::<u8>().offset_from(meta_raw.cast()) };380		let field_set = unsafe {381			((&raw mut *metadata).cast::<()>())382				.byte_offset(fields_offset)383				.cast::<FieldSet>()384		};385		// FIXME: metadata borrow here invalidates our &mut borrow of 'static Metadata, and 'static FieldSet so this construction should be replaced with raw pointers or idk.386		// Something should be better done inside of tracing crate itself, someting like interior mutability.387		let callsite = Box::leak(Box::new(tracing::callsite::DefaultCallsite::new(metadata)));388		unsafe { *field_set = FieldSet::new(names, tracing::callsite::Identifier(callsite)) };389390		tracing::callsite::register(&*callsite);391392		self.metadatas.insert(info, metadata);393		return metadata;394	}395}396397#[cfg(false)]398static FOREIGN_SPAN_DATA: LazyLock<Mutex<ForeignSpanData>> =399	LazyLock::new(|| Mutex::new(ForeignSpanData::default()));400static NIX_SPAN_MAPPING: LazyLock<Mutex<HashMap<u64, Span>>> =401	LazyLock::new(|| Mutex::new(HashMap::new()));402403#[derive(Debug)]404enum FieldValue {405	Int(i32),406	Str(String),407}408409struct StartActivityBuilder {410	activity_id: u64,411	verbosity: Verbosity,412	typ: ActivityType,413	fields: Vec<FieldValue>,414}415impl StartActivityBuilder {416	fn add_int_field(&mut self, i: i32) {417		self.fields.push(FieldValue::Int(i));418	}419	fn add_string_field(&mut self, v: &str) {420		self.fields.push(FieldValue::Str(v.to_owned()));421	}422	fn emit(&mut self, parent: u64, s: &str) {423		let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");424425		let parent = mapping.get(&parent);426427		// let meta = spans.alloc_metadata(428		// 	self.typ.name(),429		// 	self.verbosity.into(),430		// 	MetadataKind::Span,431		// 	"nix activity start",432		// 	None,433		// 	None,434		// 	None,435		// 	self.typ.fields(),436		// );437		//438		// let mut fields = meta.fields().iter();439		// let span = if let Some(parent) = parent {440		// 	let s = Span::new(441		// 		meta,442		// 		&match meta.fields().len() {443		// 			1 => meta.fields().value_set(444		// 				&<[_; 1]>::try_from([(445		// 					&fields.next().expect("has field"),446		// 					Some(&format_args!("Test") as &dyn tracing::Value),447		// 				)])448		// 				.expect("valid size"),449		// 			),450		// 			_ => unreachable!(),451		// 		},452		// 	);453		// 	s.follows_from(parent);454		// 	s455		// } else {456		// 	Span::new_root(457		// 		meta,458		// 		&match meta.fields().len() {459		// 			1 => meta.fields().value_set(460		// 				&<[_; 1]>::try_from([(461		// 					&fields.next().expect("has field"),462		// 					Some(&format_args!("Test") as &dyn tracing::Value),463		// 				)])464		// 				.expect("valid size"),465		// 			),466		// 			_ => unreachable!(),467		// 		},468		// 	)469		// };470		//471		// let id = span.id().expect("id created");472473		let span = {474			let _in_parent = parent.map(|p| p.enter());475			let level: Level = self.verbosity.into();476			if level == Level::ERROR {477				self.typ478					.format(&self.fields, s, |v| error_span!("action", v))479			} else if level == Level::WARN {480				self.typ481					.format(&self.fields, s, |v| warn_span!("action", v))482			} else if level == Level::INFO {483				self.typ484					.format(&self.fields, s, |v| info_span!("action", v))485			} else if level == Level::DEBUG {486				self.typ487					.format(&self.fields, s, |v| debug_span!("action", v))488			} else {489				self.typ490					.format(&self.fields, s, |v| trace_span!("action", v))491			}492		};493		if !s.trim().is_empty() {494			span.pb_set_message(s);495			let _e = span.enter();496			let level: Level = self.verbosity.into();497			if level == Level::ERROR {498				error!(target: "nix", "{}", s)499			} else if level == Level::WARN {500				warn!(target: "nix", "{}", s)501			} else if level == Level::INFO {502				info!(target: "nix", "{}", s)503			} else if level == Level::DEBUG {504				debug!(target: "nix", "{}", s)505			} else {506				trace!(target: "nix", "{}", s)507			}508		} else {509			span.pb_start();510		}511		mapping.insert(self.activity_id, span);512	}513	fn emit_result(&mut self, ty: u32) {514		let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");515516		let Some(parent) = mapping.get(&self.activity_id) else {517			panic!("unexpected result for dead parent");518		};519520		let _in_parent = parent.enter();521		let res = ResultType::from_int(ty);522523		use FieldValue::*;524		match (&res, self.fields.as_slice()) {525			// ResultType::FileLinked => todo!(),526			(ResultType::BuildLogLine, [Str(s)]) => {527				info!("{s:?}");528			}529			// ResultType::UntrustedPath => todo!(),530			// ResultType::CorruptedPath => todo!(),531			// ResultType::SetPhase => todo!(),532			(ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {533				let _act_ty = ActivityType::from_int(*act_ty as u32);534			}535			(ResultType::SetPhase, [Str(phase)]) => {536				// parent.pb_set_message(phase);537				debug!(target: "nix::phase", phase)538			}539			(ResultType::Progress, [Int(done), Int(expected), Int(_), Int(_)]) => {540				parent.pb_set_length(*expected as u64);541				parent.pb_set_position(*done as u64);542			}543			_ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),544		}545	}546}547fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {548	Box::new(StartActivityBuilder {549		activity_id,550		verbosity: Verbosity::from_int(lvl),551		typ: ActivityType::from_int(typ),552		fields: vec![],553	})554}555556fn emit_warn(v: &str) {557	warn!(target: "nix::eval", "{v}")558}559fn emit_stop(v: u64) {560	let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");561	mapping.remove(&v);562}563fn emit_log(lvl: u32, v: &str) {564	let verbosity = Verbosity::from_int(lvl);565	let level: Level = verbosity.into();566	if level == Level::ERROR {567		error!(target: "nix", "{v}")568	} else if level == Level::WARN {569		warn!(target: "nix", "{v}")570	} else if level == Level::INFO {571		info!(target: "nix", "{v}")572	} else if level == Level::DEBUG {573		debug!(target: "nix", "{v}")574	} else {575		trace!(target: "nix", "{v}")576	}577}578579// fn start_activity(act: u64, lvl: u32, act_ty: u32, s: &str, parent: u32) {580// 	tracing::Span::new(meta, values)581// }582583#[cxx::bridge]584pub mod nix_logging_cxx {585	extern "Rust" {586		type StartActivityBuilder;587		fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;588		fn add_int_field(&mut self, i: i32);589		fn add_string_field(&mut self, v: &str);590		fn emit(&mut self, parent: u64, s: &str);591		fn emit_result(&mut self, ty: u32);592593		fn emit_warn(v: &str);594		fn emit_stop(id: u64);595		fn emit_log(lvl: u32, v: &str);596	}597	unsafe extern "C++" {598		include!("nix-eval/src/logging.hh");599600		fn apply_tracing_logger();601	}602}