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 _;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	// https/ssh is the default55	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		// let meta = spans.alloc_metadata(312		// 	self.typ.name(),313		// 	self.verbosity.into(),314		// 	MetadataKind::Span,315		// 	"nix activity start",316		// 	None,317		// 	None,318		// 	None,319		// 	self.typ.fields(),320		// );321		//322		// let mut fields = meta.fields().iter();323		// let span = if let Some(parent) = parent {324		// 	let s = Span::new(325		// 		meta,326		// 		&match meta.fields().len() {327		// 			1 => meta.fields().value_set(328		// 				&<[_; 1]>::try_from([(329		// 					&fields.next().expect("has field"),330		// 					Some(&format_args!("Test") as &dyn tracing::Value),331		// 				)])332		// 				.expect("valid size"),333		// 			),334		// 			_ => unreachable!(),335		// 		},336		// 	);337		// 	s.follows_from(parent);338		// 	s339		// } else {340		// 	Span::new_root(341		// 		meta,342		// 		&match meta.fields().len() {343		// 			1 => meta.fields().value_set(344		// 				&<[_; 1]>::try_from([(345		// 					&fields.next().expect("has field"),346		// 					Some(&format_args!("Test") as &dyn tracing::Value),347		// 				)])348		// 				.expect("valid size"),349		// 			),350		// 			_ => unreachable!(),351		// 		},352		// 	)353		// };354		//355		// let id = span.id().expect("id created");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			// ResultType::FileLinked => todo!(),417			(ResultType::BuildLogLine, [Str(s)]) => {418				let s = ansi_filter(s);419				info!("{s}");420			}421			// ResultType::UntrustedPath => todo!(),422			// ResultType::CorruptedPath => todo!(),423			// ResultType::SetPhase => todo!(),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				// parent.pb_set_message(phase);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		// We don't want \r, bells, etc484		if byte == b'\n' {485			self.output.push('\n');486		} else if byte == b'\t' {487			// TODO: align output to the correct multiplier?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			// Only plain colors are enabled, everything other might corrupt the output505			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	// For some reason it gets stuck with longer inputs529	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}