git.delta.rocks / fleet / refs/commits / 992c7b63e98f

1use std::collections::{HashMap, VecDeque};2use std::fmt::Arguments;3use std::sync::{LazyLock, Mutex};45use cxx::ExternType;6use tracing::{7	Level, Span, debug, debug_span, error, error_span, info, info_span, trace, trace_span, warn,8	warn_span,9};10#[cfg(feature = "indicatif")]11use tracing_indicatif::span_ext::IndicatifSpanExt as _;12use vte::Parser;1314#[derive(Debug)]15enum ActivityType {16	Unknown = 0,17	CopyPath = 100,18	FileTransfer = 101,19	Realise = 102,20	CopyPaths = 103,21	Builds = 104,22	Build = 105,23	OptimiseStore = 106,24	VerifyPaths = 107,25	Substitute = 108,26	QueryPathInfo = 109,27	PostBuildHook = 110,28	BuildWaiting = 111,29	FetchTree = 112,30}3132fn strip_prefix_suffix<'s, 'p>(a: &'s str, pref: &'p str, suff: &'p str) -> Option<&'s str> {33	a.strip_prefix(pref)?.strip_suffix(suff)34}3536fn parse_path(path: &str) -> &str {37	strip_prefix_suffix(path, "\x1b[35;1m", "\x1b[0m").unwrap_or(path)38}3940fn parse_drv(drv: &str) -> &str {41	let drv = parse_path(drv);42	if let Some(pkg) = drv.strip_prefix("/nix/store/") {43		let mut it = pkg.splitn(2, '-');44		it.next();45		if let Some(pkg) = it.next() {46			return pkg;47		}48	}49	drv50}51fn parse_host(host: &str) -> &str {52	if host.is_empty() || host == "local" {53		return "local";54	}55	// https/ssh is the default56	host.strip_prefix("https://").unwrap_or(host)57}5859impl ActivityType {60	fn name(&self) -> &'static str {61		match self {62			ActivityType::Unknown => "nix",63			ActivityType::CopyPath => "nix::copy-path",64			ActivityType::FileTransfer => "nix::file-transfer",65			ActivityType::Realise => "nix::realise",66			ActivityType::CopyPaths => "nix::copy-paths",67			ActivityType::Builds => "nix::builds",68			ActivityType::Build => "nix::build",69			ActivityType::OptimiseStore => "nix::optimise-store",70			ActivityType::VerifyPaths => "nix::verify-paths",71			ActivityType::Substitute => "nix::substitute",72			ActivityType::QueryPathInfo => "nix::query-path-info",73			ActivityType::PostBuildHook => "nix::post-build-hook",74			ActivityType::BuildWaiting => "nix::build-waiting",75			ActivityType::FetchTree => "nix::fetch-tree",76		}77	}78	fn format(79		&self,80		values: &[FieldValue],81		s: &str,82		into: impl FnOnce(Arguments<'_>) -> Span,83	) -> Span {84		use FieldValue::*;85		match (self, values) {86			(ActivityType::QueryPathInfo, [Str(drv), Str(host)]) => {87				let drv = parse_drv(drv);88				let host = parse_host(host);89				debug_span!(target: "nix::query-path-info", "querying", drv, host)90			}91			(ActivityType::Substitute, [Str(drv), Str(host)]) => {92				let drv = parse_drv(drv);93				let host = parse_host(host);94				debug_span!(target: "nix::substitute", "substituting", drv, host)95			}96			(ActivityType::CopyPath, [Str(drv), Str(from), Str(to)]) => {97				let drv = parse_drv(drv);98				let from = parse_host(from);99				let to = parse_host(to);100				debug_span!(target: "nix::copy-path", "copying", drv, from, to)101			}102			(ActivityType::Build, [Str(drv), Str(host), Int(_), Int(_)]) => {103				let drv = parse_drv(drv);104				let host = parse_host(host);105				info_span!(target: "nix::build", "building", drv, host)106			}107			(ActivityType::FileTransfer, [Str(file)]) => {108				info_span!(target: "nix::file-transfer", "downloading", file)109			}110			(ActivityType::Realise, []) => {111				debug_span!(target: "nix::realise", "realising")112			}113			(ActivityType::CopyPaths, []) => {114				debug_span!(target: "nix::copy-paths", "copying paths")115			}116			(ActivityType::Unknown, [])117				if s.starts_with("copying \"") && s.ends_with("\" to the store") =>118			{119				let tree = s120					.trim_start_matches("copying \"")121					.trim_end_matches("\" to the store");122				debug_span!(target: "nix::trees", "copying", tree)123			}124			(ActivityType::Unknown, [])125				if s.starts_with("copying '") && s.ends_with("' to the store") =>126			{127				let tree = s128					.trim_start_matches("copying '")129					.trim_end_matches("' to the store");130				debug_span!(target: "nix::trees", "copying", tree)131			}132			(ActivityType::Unknown, []) if s.starts_with("hashing '") && s.ends_with("'") => {133				let tree = s.trim_start_matches("hashing '").trim_end_matches("'");134				debug_span!(target: "nix::trees", "hashing", tree)135			}136			(ActivityType::Unknown, []) if s.starts_with("connecting to '") && s.ends_with("'") => {137				let host = s138					.trim_start_matches("connecting to '")139					.trim_end_matches("'");140				debug_span!(target: "nix::remote", "connecting", host)141			}142			(ActivityType::Unknown, [])143				if s.starts_with("copying outputs from '") && s.ends_with("'") =>144			{145				let host = s146					.trim_start_matches("copying outputs from '")147					.trim_end_matches("'");148				debug_span!(target: "nix::remote", "copying outputs", host)149			}150			(ActivityType::Unknown, [])151				if s.starts_with("copying dependencies to '") && s.ends_with("'") =>152			{153				let host = s154					.trim_start_matches("copying dependencies to '")155					.trim_end_matches("'");156				debug_span!(target: "nix::remote", "copying dependencies", host)157			}158			(ActivityType::Unknown, [])159				if s.starts_with("waiting for the upload lock to '") && s.ends_with("'") =>160			{161				let host = s162					.trim_start_matches("waiting for the upload lock to '")163					.trim_end_matches("'");164				debug_span!(target: "nix::remote", "waiting for upload lock", host)165			}166			(ActivityType::BuildWaiting, [])167				if s.starts_with("waiting for a machine to build '") && s.ends_with("'") =>168			{169				let drv = parse_drv(170					s.trim_start_matches("waiting for a machine to build '")171						.trim_end_matches("'"),172				);173				debug_span!(target: "nix::build-waiting", "waiting for available builder", drv)174			}175			(ActivityType::Unknown, []) if s == "querying info about missing paths" => {176				debug_span!(target: "nix::remote", "querying")177			}178			_ => into(format_args!("{}({values:?})", self.name())),179		}180	}181	fn from_int(v: u32) -> Self {182		match v {183			0 => Self::Unknown,184			100 => Self::CopyPath,185			101 => Self::FileTransfer,186			102 => Self::Realise,187			103 => Self::CopyPaths,188			104 => Self::Builds,189			105 => Self::Build,190			106 => Self::OptimiseStore,191			107 => Self::VerifyPaths,192			108 => Self::Substitute,193			109 => Self::QueryPathInfo,194			110 => Self::PostBuildHook,195			111 => Self::BuildWaiting,196			112 => Self::FetchTree,197			_ => {198				warn!("unknown nix action: {v}");199				Self::Unknown200			}201		}202	}203}204205#[derive(Debug)]206enum ResultType {207	FileLinked = 100,208	BuildLogLine = 101,209	UntrustedPath = 102,210	CorruptedPath = 103,211	SetPhase = 104,212	Progress = 105,213	SetExpected = 106,214	PostBuildLogLine = 107,215	FetchStatus = 108,216217	Unknown = 999,218}219impl ResultType {220	fn from_int(v: u32) -> Self {221		match v {222			100 => Self::FileLinked,223			101 => Self::BuildLogLine,224			102 => Self::UntrustedPath,225			103 => Self::CorruptedPath,226			104 => Self::SetPhase,227			105 => Self::Progress,228			106 => Self::SetExpected,229			107 => Self::PostBuildLogLine,230			108 => Self::FetchStatus,231232			_ => {233				warn!("unknown nix result: {v}");234				Self::Unknown235			}236		}237	}238}239#[derive(Clone, Copy)]240enum Verbosity {241	Error,242	Warn,243	Notice,244	Info,245	Talkative,246	Chatty,247	Debug,248	Vomit,249}250impl From<Verbosity> for tracing::Level {251	fn from(val: Verbosity) -> Self {252		match val {253			Verbosity::Error => Level::ERROR,254			Verbosity::Warn => Level::WARN,255			Verbosity::Notice => Level::WARN,256			Verbosity::Info => Level::INFO,257			Verbosity::Talkative => Level::DEBUG,258			Verbosity::Chatty => Level::DEBUG,259			Verbosity::Debug => Level::DEBUG,260			Verbosity::Vomit => Level::TRACE,261		}262	}263}264impl Verbosity {265	fn from_int(u: u32) -> Self {266		[267			Self::Error,268			Self::Warn,269			Self::Notice,270			Self::Info,271			Self::Talkative,272			Self::Chatty,273			Self::Debug,274			Self::Vomit,275		]276		.get(u as usize)277		.cloned()278		.unwrap_or_else(|| {279			warn!("unknown log level: {u}");280			Verbosity::Vomit281		})282	}283}284285static NIX_SPAN_MAPPING: LazyLock<Mutex<HashMap<u64, Span>>> =286	LazyLock::new(|| Mutex::new(HashMap::new()));287288struct DrvGraphEntry {289	name: String,290	parent: Option<String>,291	span: Option<Span>,292	refcount: usize,293}294295static DRV_GRAPH: LazyLock<Mutex<HashMap<String, DrvGraphEntry>>> =296	LazyLock::new(|| Mutex::new(HashMap::new()));297298static ACTIVITY_TO_DRV: LazyLock<Mutex<HashMap<u64, String>>> =299	LazyLock::new(|| Mutex::new(HashMap::new()));300301pub struct BuildGraphGuard {302	paths: Vec<String>,303}304305impl Drop for BuildGraphGuard {306	fn drop(&mut self) {307		let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");308		for path in &self.paths {309			if let Some(entry) = drv_graph.get_mut(path) {310				entry.refcount -= 1;311				if entry.refcount == 0 {312					drv_graph.remove(path);313				}314			}315		}316	}317}318319pub fn register_build_graph(parent: &Span, graph: &crate::drv::DrvGraph) -> BuildGraphGuard {320	let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");321	let mut paths = Vec::new();322323	drv_graph324		.entry(graph.root.clone())325		.and_modify(|e| e.refcount += 1)326		.or_insert_with(|| DrvGraphEntry {327			name: graph.nodes[&graph.root].name.clone(),328			parent: None,329			span: Some(parent.clone()),330			refcount: 1,331		});332	paths.push(graph.root.clone());333334	let mut queue = VecDeque::new();335	queue.push_back(graph.root.clone());336337	let mut visited = std::collections::HashSet::new();338	visited.insert(graph.root.clone());339340	while let Some(path) = queue.pop_front() {341		let Some(node) = graph.nodes.get(&path) else {342			continue;343		};344		for dep_path in node.input_drvs.keys() {345			if !visited.insert(dep_path.clone()) {346				continue;347			}348			let Some(dep_node) = graph.nodes.get(dep_path) else {349				continue;350			};351			if let Some(entry) = drv_graph.get_mut(dep_path) {352				entry.refcount += 1;353			} else {354				drv_graph.insert(355					dep_path.clone(),356					DrvGraphEntry {357						name: dep_node.name.clone(),358						parent: Some(path.clone()),359						span: None,360						refcount: 1,361					},362				);363			}364			paths.push(dep_path.clone());365			queue.push_back(dep_path.clone());366		}367	}368369	BuildGraphGuard { paths }370}371372fn ensure_drv_span(drv_path: &str) -> Option<Span> {373	let mut drv_graph = DRV_GRAPH.lock().expect("not poisoned");374375	if let Some(span) = drv_graph.get(drv_path).and_then(|e| e.span.clone()) {376		return Some(span);377	}378379	let mut chain = vec![];380	let mut current = drv_path.to_owned();381	loop {382		let Some(entry) = drv_graph.get(&current) else {383			break;384		};385		if entry.span.is_some() {386			chain.push(current);387			break;388		}389		chain.push(current.clone());390		match &entry.parent {391			Some(p) => current = p.clone(),392			None => break,393		}394	}395396	if chain.is_empty() {397		return None;398	}399400	for i in (0..chain.len()).rev() {401		let path = &chain[i];402		if drv_graph.get(path).unwrap().span.is_some() {403			continue;404		}405		let parent_span = chain406			.get(i + 1)407			.and_then(|p| drv_graph.get(p))408			.and_then(|e| e.span.clone());409		let name = drv_graph.get(path).unwrap().name.clone();410		let span = {411			let _enter = parent_span.as_ref().map(|s| s.enter());412			info_span!(target: "nix::build", "building", drv = %name)413		};414		drv_graph.get_mut(path).unwrap().span = Some(span);415	}416417	drv_graph.get(drv_path).and_then(|e| e.span.clone())418}419420#[derive(Debug)]421enum FieldValue {422	Int(i32),423	Str(String),424}425426struct StartActivityBuilder {427	activity_id: u64,428	verbosity: Verbosity,429	typ: ActivityType,430	fields: Vec<FieldValue>,431}432impl StartActivityBuilder {433	fn add_int_field(&mut self, i: i32) {434		self.fields.push(FieldValue::Int(i));435	}436	fn add_string_field(&mut self, v: &[u8]) {437		let v = String::from_utf8_lossy(v);438		self.fields.push(FieldValue::Str(v.to_string()));439	}440	fn emit(&mut self, parent: u64, s: &str) {441		let graph_span = if matches!(self.typ, ActivityType::Build) {442			self.fields.first().and_then(|f| match f {443				FieldValue::Str(drv_path) => {444					let clean = parse_path(drv_path);445					let span = ensure_drv_span(clean);446					if span.is_some() {447						ACTIVITY_TO_DRV448							.lock()449							.expect("not poisoned")450							.insert(self.activity_id, clean.to_owned());451					}452					span453				}454				_ => None,455			})456		} else {457			None458		};459460		let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");461462		let span = if let Some(span) = graph_span {463			#[cfg(feature = "indicatif")]464			span.pb_start();465			span466		} else {467			let parent = mapping.get(&parent);468			let _in_parent = parent.map(|p| p.enter());469			let level: Level = self.verbosity.into();470			if level == Level::ERROR {471				self.typ472					.format(&self.fields, s, |v| error_span!("action", v))473			} else if level == Level::WARN {474				self.typ475					.format(&self.fields, s, |v| warn_span!("action", v))476			} else if level == Level::INFO {477				self.typ478					.format(&self.fields, s, |v| info_span!("action", v))479			} else if level == Level::DEBUG {480				self.typ481					.format(&self.fields, s, |v| debug_span!("action", v))482			} else {483				self.typ484					.format(&self.fields, s, |v| trace_span!("action", v))485			}486		};487		if !s.trim().is_empty() {488			let s = ansi_filter(s);489			#[cfg(feature = "indicatif")]490			{491				span.pb_set_message(&s);492			}493			let _e = span.enter();494			let level: Level = self.verbosity.into();495			if level == Level::ERROR {496				error!(target: "nix", "{}", s)497			} else if level == Level::WARN {498				warn!(target: "nix", "{}", s)499			} else if level == Level::INFO {500				info!(target: "nix", "{}", s)501			} else if level == Level::DEBUG {502				debug!(target: "nix", "{}", s)503			} else {504				trace!(target: "nix", "{}", s)505			}506		} else {507			#[cfg(feature = "indicatif")]508			{509				span.pb_start();510			}511		}512		mapping.insert(self.activity_id, span);513	}514	fn emit_result(&mut self, ty: u32) {515		let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");516517		let Some(parent) = mapping.get(&self.activity_id) else {518			panic!("unexpected result for dead parent");519		};520521		let _in_parent = parent.enter();522		let res = ResultType::from_int(ty);523524		use FieldValue::*;525		match (&res, self.fields.as_slice()) {526			// ResultType::FileLinked => todo!(),527			(ResultType::BuildLogLine, [Str(s)]) => {528				let s = ansi_filter(s);529				info!("{s}");530			}531			// ResultType::UntrustedPath => todo!(),532			// ResultType::CorruptedPath => todo!(),533			// ResultType::SetPhase => todo!(),534			(ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {535				let _act_ty = ActivityType::from_int(*act_ty as u32);536			}537			(ResultType::SetPhase, [Str(phase)]) => {538				// parent.pb_set_message(phase);539				debug!(target: "nix::phase", phase)540			}541			(ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {542				#[cfg(feature = "indicatif")]543				{544					parent.pb_set_length(*_expected as u64);545					parent.pb_set_position(*_done as u64);546				}547			}548			_ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),549		}550	}551}552fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {553	Box::new(StartActivityBuilder {554		activity_id,555		verbosity: Verbosity::from_int(lvl),556		typ: ActivityType::from_int(typ),557		fields: vec![],558	})559}560561fn emit_warn(v: &str) {562	warn!(target: "nix::eval", "{v}")563}564fn emit_stop(v: u64) {565	{566		let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");567		mapping.remove(&v);568	}569	if let Some(drv_path) = ACTIVITY_TO_DRV.lock().expect("not poisoned").remove(&v) {570		if let Some(entry) = DRV_GRAPH.lock().expect("not poisoned").get_mut(&drv_path) {571			entry.span = None;572		}573	}574}575fn emit_log(lvl: u32, v: &[u8]) {576	let verbosity = Verbosity::from_int(lvl);577	let level: Level = verbosity.into();578	let v = String::from_utf8_lossy(v);579	if level == Level::ERROR {580		error!(target: "nix", "{v}")581	} else if level == Level::WARN {582		warn!(target: "nix", "{v}")583	} else if level == Level::INFO {584		info!(target: "nix", "{v}")585	} else if level == Level::DEBUG {586		debug!(target: "nix", "{v}")587	} else {588		trace!(target: "nix", "{v}")589	}590}591592struct AnsiFiltered {593	output: String,594}595impl vte::Perform for AnsiFiltered {596	fn print(&mut self, c: char) {597		self.output.push(c);598	}599600	fn execute(&mut self, byte: u8) {601		// We don't want \r, bells, etc602		if byte == b'\n' {603			self.output.push('\n');604		} else if byte == b'\t' {605			// TODO: align output to the correct multiplier?606			self.output.push('\t');607		}608	}609610	fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}611	fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}612613	fn csi_dispatch(614		&mut self,615		params: &vte::Params,616		_intermediates: &[u8],617		_ignore: bool,618		action: char,619	) {620		use std::fmt::Write;621		if action != 'm' {622			// Only plain colors are enabled, everything other might corrupt the output623			return;624		}625		self.output.push_str("\x1b[");626		for (i, par) in params.iter().enumerate() {627			if i != 0 {628				let _ = write!(self.output, ";");629			}630			for (i, sub) in par.iter().enumerate() {631				if i != 0 {632					let _ = write!(self.output, ":");633				}634				let _ = write!(self.output, "{sub}");635			}636		}637		self.output.push(action);638	}639}640fn ansi_filter(i: &str) -> String {641	let mut out = AnsiFiltered {642		output: String::new(),643	};644	let mut parser = Parser::new();645646	// For some reason it gets stuck with longer inputs647	for chunk in i.as_bytes().chunks(50) {648		parser.advance(&mut out, chunk);649	}650651	out.output652}653654#[derive(Debug)]655pub struct StackFrame {656	pub msg: String,657	pub pos: String,658}659660#[derive(Debug)]661pub struct ErrorInfoBuilder {662	level: Level,663	msg: String,664	pub stack_frames: Vec<StackFrame>,665}666fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder> {667	let verbosity = Verbosity::from_int(lvl);668	let level: Level = verbosity.into();669	let v = String::from_utf8_lossy(v);670	Box::new(ErrorInfoBuilder {671		level,672		msg: v.to_string(),673		stack_frames: Vec::new(),674	})675}676impl ErrorInfoBuilder {677	fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]) {678		let v = String::from_utf8_lossy(v);679		let pos = String::from_utf8_lossy(pos);680		self.stack_frames.push(StackFrame {681			msg: v.to_string(),682			pos: pos.to_string(),683		});684	}685	fn emit_error_info(&mut self) {686		error!("{}", self.msg);687		for frame in &self.stack_frames {688			error!("  {} at {}", frame.msg, frame.pos)689		}690	}691}692693#[cxx::bridge]694pub mod nix_logging_cxx {695	extern "Rust" {696		type StartActivityBuilder;697		fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;698		fn add_int_field(&mut self, i: i32);699		fn add_string_field(&mut self, v: &[u8]);700		fn emit(&mut self, parent: u64, s: &str);701		fn emit_result(&mut self, ty: u32);702	}703	extern "Rust" {704		type ErrorInfoBuilder;705		fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder>;706		fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]);707		fn emit_error_info(&mut self);708	}709	extern "Rust" {710		fn emit_warn(v: &str);711		fn emit_stop(id: u64);712		fn emit_log(lvl: u32, v: &[u8]);713	}714	unsafe extern "C++" {715		include!("nix-eval/src/logging.hh");716717		type nix_c_context = crate::nix_raw::c_context;718719		fn apply_tracing_logger();720		unsafe fn extract_error_info(ctx: *const nix_c_context) -> Box<ErrorInfoBuilder>;721	}722}723724unsafe impl ExternType for crate::nix_raw::c_context {725	type Id = cxx::type_id!("nix_c_context");726727	type Kind = cxx::kind::Opaque;728}