git.delta.rocks / fleet / refs/commits / 3bff084b3bc8

difftreelog

feat display nix stacktraces

urvrmlrlYaroslav Bolyukin2025-10-26parent: #f5a8281.patch.diff
in: push-kyumtlkprzyotrunk

6 files changed

modifiedcmds/fleet/src/cmds/build_systems.rsdiffbeforeafterboth
--- a/cmds/fleet/src/cmds/build_systems.rs
+++ b/cmds/fleet/src/cmds/build_systems.rs
@@ -118,7 +118,7 @@
 					{
 						Ok(path) => path,
 						Err(e) => {
-							error!("failed to build host system closure: {:#}", e);
+							error!("failed to build host system closure: {:?}", e);
 							return;
 						}
 					};
modifiedcrates/nix-eval/build.rsdiffbeforeafterboth
--- a/crates/nix-eval/build.rs
+++ b/crates/nix-eval/build.rs
@@ -16,6 +16,7 @@
 	// Link nix C++ libraries for cxx
 	for lib in &[
 		"nix-util",
+		"nix-util-c",
 		"nix-store",
 		"nix-expr",
 		"nix-flake",
@@ -34,12 +35,12 @@
 
 	cxx_build::bridge("src/logging.rs")
 		.file("src/logging.cc")
-		.std("c++20")
+		.std("c++23")
 		.shared_flag(true)
 		.compile("nix-eval-logging");
 	cxx_build::bridge("src/lib.rs")
 		.file("src/lib.cc")
-		.std("c++20")
+		.std("c++23")
 		.shared_flag(true)
 		.compile("nix-eval");
modifiedcrates/nix-eval/src/lib.rsdiffbeforeafterboth
--- a/crates/nix-eval/src/lib.rs
+++ b/crates/nix-eval/src/lib.rs
@@ -13,7 +13,7 @@
 pub use anyhow::Result;
 use tracing::instrument;
 
-use self::logging::nix_logging_cxx;
+use self::logging::{ErrorInfoBuilder, nix_logging_cxx};
 use self::nix_cxx::set_fetcher_setting;
 use self::nix_raw::{
 	BindingsBuilder as c_bindings_builder, EvalState as c_eval_state, GC_SUCCESS,
@@ -179,8 +179,9 @@
 		let code = unsafe { err_code(self.0) };
 		NixErrorKind::from_int(code)
 	}
-	fn error<'t>(&self) -> Option<Cow<'t, str>> {
+	fn error<'t>(&self) -> Option<(Cow<'t, str>, Option<Box<ErrorInfoBuilder>>)> {
 		if let NixErrorKind::Generic = self.error_kind()? {
+			let ei = unsafe { logging::nix_logging_cxx::extract_error_info(self.0) };
 			let mut err_out = String::new();
 			unsafe {
 				err_info_msg(
@@ -190,13 +191,13 @@
 					(&raw mut err_out).cast(),
 				)
 			};
-			return Some(Cow::Owned(err_out));
+			return Some((Cow::Owned(err_out), Some(ei)));
 		};
 
 		// TODO: Can throw error (resulting in panic) if unable to retrieve error. Should be able to resolve by passing context as a first argument,
 		// but it looks ugly
 		let str = unsafe { err_msg(null_mut(), self.0, null_mut()) };
-		Some(unsafe { CStr::from_ptr(str) }.to_string_lossy())
+		Some((unsafe { CStr::from_ptr(str) }.to_string_lossy(), None))
 	}
 	fn clean_err(&mut self) {
 		unsafe {
@@ -205,8 +206,20 @@
 	}
 
 	fn bail_if_error(&self) -> Result<()> {
-		if let Some(err) = self.error() {
-			bail!("{err}");
+		if let Some((err, stack)) = self.error() {
+			let mut e = Err(anyhow!("{err}"));
+			if let Some(stack) = stack {
+				for ele in stack.stack_frames {
+					e = e.with_context(|| {
+						if ele.pos.is_empty() {
+							ele.msg
+						} else {
+							format!("{} at {}", ele.msg, ele.pos)
+						}
+					})
+				}
+			}
+			return e.context("<nix frames>");
 		};
 		Ok(())
 	}
modifiedcrates/nix-eval/src/logging.ccdiffbeforeafterboth
--- a/crates/nix-eval/src/logging.cc
+++ b/crates/nix-eval/src/logging.cc
@@ -1,9 +1,36 @@
-#include "nix-eval/src/logging.rs"
 #include "logging.hh"
 #include <nix/util/logging.hh>
+#include <nix/util/position.hh>
 
 using namespace nix;
 
+rust::Box<ErrorInfoBuilder> copy_error_info(const ErrorInfo &ei) {
+  auto s = ei.msg.str();
+  rust::Slice<const unsigned char> str(
+      reinterpret_cast<const unsigned char *>(s.data()), s.size());
+  auto b = new_error_info(ei.level, str);
+  if (!ei.traces.empty()) {
+    for (auto iter = ei.traces.rbegin(); iter != ei.traces.rend(); ++iter) {
+      auto msg = iter->hint.str();
+
+      rust::Slice<const unsigned char> msgv(
+          reinterpret_cast<const unsigned char *>(msg.data()), msg.size());
+
+      std::ostringstream oss;
+      if (iter->pos) {
+        iter->pos->print(oss, true);
+      }
+      std::string pos = oss.str();
+
+      rust::Slice<const unsigned char> posv(
+          reinterpret_cast<const unsigned char *>(pos.data()), pos.size());
+
+      b->push_stack_frame(msgv, posv);
+    }
+  }
+  return b;
+}
+
 struct TracingLogger : Logger {
   TracingLogger() {}
 
@@ -14,10 +41,8 @@
     emit_log(lvl, str);
   }
   void logEI(const ErrorInfo &ei) override {
-    auto s = ei.msg.str();
-    rust::Slice<const unsigned char> str(
-        reinterpret_cast<const unsigned char *>(s.data()), s.size());
-    emit_log(ei.level, str);
+    auto b = copy_error_info(ei);
+    b->emit_error_info();
   }
 
   void startActivity(ActivityId act, Verbosity lvl, ActivityType type,
@@ -74,4 +99,8 @@
   logger = std::make_unique<TracingLogger>();
   // verbosity = lvlVomit;
 }
+rust::Box<ErrorInfoBuilder>
+extract_error_info(const nix_c_context *read_context) {
+  return copy_error_info(read_context->info.value());
+}
 }
modifiedcrates/nix-eval/src/logging.hhdiffbeforeafterboth
--- a/crates/nix-eval/src/logging.hh
+++ b/crates/nix-eval/src/logging.hh
@@ -1,5 +1,12 @@
 #pragma once
+#include "nix-eval/src/logging.rs"
+#include "rust/cxx.h"
+#include <nix_api_util.h>
+#include <nix_api_util_internal.h>
+
+struct ErrorInfoBuilder;
 
 extern "C" {
 void apply_tracing_logger();
+rust::Box<ErrorInfoBuilder> extract_error_info(const nix_c_context *ctx);
 }
modifiedcrates/nix-eval/src/logging.rsdiffbeforeafterboth
before · crates/nix-eval/src/logging.rs
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: &[u8]) {304		let v = String::from_utf8_lossy(v);305		self.fields.push(FieldValue::Str(v.to_string()));306	}307	fn emit(&mut self, parent: u64, s: &str) {308		let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");309310		let parent = mapping.get(&parent);311312		// let meta = spans.alloc_metadata(313		// 	self.typ.name(),314		// 	self.verbosity.into(),315		// 	MetadataKind::Span,316		// 	"nix activity start",317		// 	None,318		// 	None,319		// 	None,320		// 	self.typ.fields(),321		// );322		//323		// let mut fields = meta.fields().iter();324		// let span = if let Some(parent) = parent {325		// 	let s = Span::new(326		// 		meta,327		// 		&match meta.fields().len() {328		// 			1 => meta.fields().value_set(329		// 				&<[_; 1]>::try_from([(330		// 					&fields.next().expect("has field"),331		// 					Some(&format_args!("Test") as &dyn tracing::Value),332		// 				)])333		// 				.expect("valid size"),334		// 			),335		// 			_ => unreachable!(),336		// 		},337		// 	);338		// 	s.follows_from(parent);339		// 	s340		// } else {341		// 	Span::new_root(342		// 		meta,343		// 		&match meta.fields().len() {344		// 			1 => meta.fields().value_set(345		// 				&<[_; 1]>::try_from([(346		// 					&fields.next().expect("has field"),347		// 					Some(&format_args!("Test") as &dyn tracing::Value),348		// 				)])349		// 				.expect("valid size"),350		// 			),351		// 			_ => unreachable!(),352		// 		},353		// 	)354		// };355		//356		// let id = span.id().expect("id created");357358		let span = {359			let _in_parent = parent.map(|p| p.enter());360			let level: Level = self.verbosity.into();361			if level == Level::ERROR {362				self.typ363					.format(&self.fields, s, |v| error_span!("action", v))364			} else if level == Level::WARN {365				self.typ366					.format(&self.fields, s, |v| warn_span!("action", v))367			} else if level == Level::INFO {368				self.typ369					.format(&self.fields, s, |v| info_span!("action", v))370			} else if level == Level::DEBUG {371				self.typ372					.format(&self.fields, s, |v| debug_span!("action", v))373			} else {374				self.typ375					.format(&self.fields, s, |v| trace_span!("action", v))376			}377		};378		if !s.trim().is_empty() {379			let s = ansi_filter(s);380			#[cfg(feature = "indicatif")]381			{382				span.pb_set_message(s);383			}384			let _e = span.enter();385			let level: Level = self.verbosity.into();386			if level == Level::ERROR {387				error!(target: "nix", "{}", s)388			} else if level == Level::WARN {389				warn!(target: "nix", "{}", s)390			} else if level == Level::INFO {391				info!(target: "nix", "{}", s)392			} else if level == Level::DEBUG {393				debug!(target: "nix", "{}", s)394			} else {395				trace!(target: "nix", "{}", s)396			}397		} else {398			#[cfg(feature = "indicatif")]399			{400				span.pb_start();401			}402		}403		mapping.insert(self.activity_id, span);404	}405	fn emit_result(&mut self, ty: u32) {406		let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");407408		let Some(parent) = mapping.get(&self.activity_id) else {409			panic!("unexpected result for dead parent");410		};411412		let _in_parent = parent.enter();413		let res = ResultType::from_int(ty);414415		use FieldValue::*;416		match (&res, self.fields.as_slice()) {417			// ResultType::FileLinked => todo!(),418			(ResultType::BuildLogLine, [Str(s)]) => {419				let s = ansi_filter(s);420				info!("{s}");421			}422			// ResultType::UntrustedPath => todo!(),423			// ResultType::CorruptedPath => todo!(),424			// ResultType::SetPhase => todo!(),425			(ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {426				let _act_ty = ActivityType::from_int(*act_ty as u32);427			}428			(ResultType::SetPhase, [Str(phase)]) => {429				// parent.pb_set_message(phase);430				debug!(target: "nix::phase", phase)431			}432			(ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {433				#[cfg(feature = "indicatif")]434				{435					parent.pb_set_length(*_expected as u64);436					parent.pb_set_position(*_done as u64);437				}438			}439			_ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),440		}441	}442}443fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {444	Box::new(StartActivityBuilder {445		activity_id,446		verbosity: Verbosity::from_int(lvl),447		typ: ActivityType::from_int(typ),448		fields: vec![],449	})450}451452fn emit_warn(v: &str) {453	warn!(target: "nix::eval", "{v}")454}455fn emit_stop(v: u64) {456	let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");457	mapping.remove(&v);458}459fn emit_log(lvl: u32, v: &[u8]) {460	let verbosity = Verbosity::from_int(lvl);461	let level: Level = verbosity.into();462	let v = String::from_utf8_lossy(v);463	if level == Level::ERROR {464		error!(target: "nix", "{v}")465	} else if level == Level::WARN {466		warn!(target: "nix", "{v}")467	} else if level == Level::INFO {468		info!(target: "nix", "{v}")469	} else if level == Level::DEBUG {470		debug!(target: "nix", "{v}")471	} else {472		trace!(target: "nix", "{v}")473	}474}475476struct AnsiFiltered {477	output: String,478}479impl vte::Perform for AnsiFiltered {480	fn print(&mut self, c: char) {481		self.output.push(c);482	}483484	fn execute(&mut self, byte: u8) {485		// We don't want \r, bells, etc486		if byte == b'\n' {487			self.output.push('\n');488		} else if byte == b'\t' {489			// TODO: align output to the correct multiplier?490			self.output.push('\t');491		}492	}493494	fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}495	fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}496497	fn csi_dispatch(498		&mut self,499		params: &vte::Params,500		_intermediates: &[u8],501		_ignore: bool,502		action: char,503	) {504		use std::fmt::Write;505		if action != 'm' {506			// Only plain colors are enabled, everything other might corrupt the output507			return;508		}509		self.output.push_str("\x1b[");510		for (i, par) in params.iter().enumerate() {511			if i != 0 {512				let _ = write!(self.output, ";");513			}514			for (i, sub) in par.iter().enumerate() {515				if i != 0 {516					let _ = write!(self.output, ":");517				}518				let _ = write!(self.output, "{sub}");519			}520		}521		self.output.push(action);522	}523}524fn ansi_filter(i: &str) -> String {525	let mut out = AnsiFiltered {526		output: String::new(),527	};528	let mut parser = Parser::new();529530	// For some reason it gets stuck with longer inputs531	for chunk in i.as_bytes().chunks(50) {532		parser.advance(&mut out, chunk);533	}534535	out.output536}537538#[cxx::bridge]539pub mod nix_logging_cxx {540	extern "Rust" {541		type StartActivityBuilder;542		fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;543		fn add_int_field(&mut self, i: i32);544		fn add_string_field(&mut self, v: &[u8]);545		fn emit(&mut self, parent: u64, s: &str);546		fn emit_result(&mut self, ty: u32);547548		fn emit_warn(v: &str);549		fn emit_stop(id: u64);550		fn emit_log(lvl: u32, v: &[u8]);551	}552	unsafe extern "C++" {553		include!("nix-eval/src/logging.hh");554555		fn apply_tracing_logger();556	}557}
after · crates/nix-eval/src/logging.rs
1use std::collections::HashMap;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()));287288#[derive(Debug)]289enum FieldValue {290	Int(i32),291	Str(String),292}293294struct StartActivityBuilder {295	activity_id: u64,296	verbosity: Verbosity,297	typ: ActivityType,298	fields: Vec<FieldValue>,299}300impl StartActivityBuilder {301	fn add_int_field(&mut self, i: i32) {302		self.fields.push(FieldValue::Int(i));303	}304	fn add_string_field(&mut self, v: &[u8]) {305		let v = String::from_utf8_lossy(v);306		self.fields.push(FieldValue::Str(v.to_string()));307	}308	fn emit(&mut self, parent: u64, s: &str) {309		let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");310311		let parent = mapping.get(&parent);312313		// let meta = spans.alloc_metadata(314		// 	self.typ.name(),315		// 	self.verbosity.into(),316		// 	MetadataKind::Span,317		// 	"nix activity start",318		// 	None,319		// 	None,320		// 	None,321		// 	self.typ.fields(),322		// );323		//324		// let mut fields = meta.fields().iter();325		// let span = if let Some(parent) = parent {326		// 	let s = Span::new(327		// 		meta,328		// 		&match meta.fields().len() {329		// 			1 => meta.fields().value_set(330		// 				&<[_; 1]>::try_from([(331		// 					&fields.next().expect("has field"),332		// 					Some(&format_args!("Test") as &dyn tracing::Value),333		// 				)])334		// 				.expect("valid size"),335		// 			),336		// 			_ => unreachable!(),337		// 		},338		// 	);339		// 	s.follows_from(parent);340		// 	s341		// } else {342		// 	Span::new_root(343		// 		meta,344		// 		&match meta.fields().len() {345		// 			1 => meta.fields().value_set(346		// 				&<[_; 1]>::try_from([(347		// 					&fields.next().expect("has field"),348		// 					Some(&format_args!("Test") as &dyn tracing::Value),349		// 				)])350		// 				.expect("valid size"),351		// 			),352		// 			_ => unreachable!(),353		// 		},354		// 	)355		// };356		//357		// let id = span.id().expect("id created");358359		let span = {360			let _in_parent = parent.map(|p| p.enter());361			let level: Level = self.verbosity.into();362			if level == Level::ERROR {363				self.typ364					.format(&self.fields, s, |v| error_span!("action", v))365			} else if level == Level::WARN {366				self.typ367					.format(&self.fields, s, |v| warn_span!("action", v))368			} else if level == Level::INFO {369				self.typ370					.format(&self.fields, s, |v| info_span!("action", v))371			} else if level == Level::DEBUG {372				self.typ373					.format(&self.fields, s, |v| debug_span!("action", v))374			} else {375				self.typ376					.format(&self.fields, s, |v| trace_span!("action", v))377			}378		};379		if !s.trim().is_empty() {380			let s = ansi_filter(s);381			#[cfg(feature = "indicatif")]382			{383				span.pb_set_message(s);384			}385			let _e = span.enter();386			let level: Level = self.verbosity.into();387			if level == Level::ERROR {388				error!(target: "nix", "{}", s)389			} else if level == Level::WARN {390				warn!(target: "nix", "{}", s)391			} else if level == Level::INFO {392				info!(target: "nix", "{}", s)393			} else if level == Level::DEBUG {394				debug!(target: "nix", "{}", s)395			} else {396				trace!(target: "nix", "{}", s)397			}398		} else {399			#[cfg(feature = "indicatif")]400			{401				span.pb_start();402			}403		}404		mapping.insert(self.activity_id, span);405	}406	fn emit_result(&mut self, ty: u32) {407		let mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");408409		let Some(parent) = mapping.get(&self.activity_id) else {410			panic!("unexpected result for dead parent");411		};412413		let _in_parent = parent.enter();414		let res = ResultType::from_int(ty);415416		use FieldValue::*;417		match (&res, self.fields.as_slice()) {418			// ResultType::FileLinked => todo!(),419			(ResultType::BuildLogLine, [Str(s)]) => {420				let s = ansi_filter(s);421				info!("{s}");422			}423			// ResultType::UntrustedPath => todo!(),424			// ResultType::CorruptedPath => todo!(),425			// ResultType::SetPhase => todo!(),426			(ResultType::SetExpected, [Int(act_ty), Int(_expected)]) => {427				let _act_ty = ActivityType::from_int(*act_ty as u32);428			}429			(ResultType::SetPhase, [Str(phase)]) => {430				// parent.pb_set_message(phase);431				debug!(target: "nix::phase", phase)432			}433			(ResultType::Progress, [Int(_done), Int(_expected), Int(_), Int(_)]) => {434				#[cfg(feature = "indicatif")]435				{436					parent.pb_set_length(*_expected as u64);437					parent.pb_set_position(*_done as u64);438				}439			}440			_ => warn!("unknown progress report: {:?}({:?})", &res, &self.fields),441		}442	}443}444fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder> {445	Box::new(StartActivityBuilder {446		activity_id,447		verbosity: Verbosity::from_int(lvl),448		typ: ActivityType::from_int(typ),449		fields: vec![],450	})451}452453fn emit_warn(v: &str) {454	warn!(target: "nix::eval", "{v}")455}456fn emit_stop(v: u64) {457	let mut mapping = NIX_SPAN_MAPPING.lock().expect("not poisoned");458	mapping.remove(&v);459}460fn emit_log(lvl: u32, v: &[u8]) {461	let verbosity = Verbosity::from_int(lvl);462	let level: Level = verbosity.into();463	let v = String::from_utf8_lossy(v);464	if level == Level::ERROR {465		error!(target: "nix", "{v}")466	} else if level == Level::WARN {467		warn!(target: "nix", "{v}")468	} else if level == Level::INFO {469		info!(target: "nix", "{v}")470	} else if level == Level::DEBUG {471		debug!(target: "nix", "{v}")472	} else {473		trace!(target: "nix", "{v}")474	}475}476477struct AnsiFiltered {478	output: String,479}480impl vte::Perform for AnsiFiltered {481	fn print(&mut self, c: char) {482		self.output.push(c);483	}484485	fn execute(&mut self, byte: u8) {486		// We don't want \r, bells, etc487		if byte == b'\n' {488			self.output.push('\n');489		} else if byte == b'\t' {490			// TODO: align output to the correct multiplier?491			self.output.push('\t');492		}493	}494495	fn osc_dispatch(&mut self, _params: &[&[u8]], _bell_terminated: bool) {}496	fn esc_dispatch(&mut self, _intermediates: &[u8], _ignore: bool, _byte: u8) {}497498	fn csi_dispatch(499		&mut self,500		params: &vte::Params,501		_intermediates: &[u8],502		_ignore: bool,503		action: char,504	) {505		use std::fmt::Write;506		if action != 'm' {507			// Only plain colors are enabled, everything other might corrupt the output508			return;509		}510		self.output.push_str("\x1b[");511		for (i, par) in params.iter().enumerate() {512			if i != 0 {513				let _ = write!(self.output, ";");514			}515			for (i, sub) in par.iter().enumerate() {516				if i != 0 {517					let _ = write!(self.output, ":");518				}519				let _ = write!(self.output, "{sub}");520			}521		}522		self.output.push(action);523	}524}525fn ansi_filter(i: &str) -> String {526	let mut out = AnsiFiltered {527		output: String::new(),528	};529	let mut parser = Parser::new();530531	// For some reason it gets stuck with longer inputs532	for chunk in i.as_bytes().chunks(50) {533		parser.advance(&mut out, chunk);534	}535536	out.output537}538539#[derive(Debug)]540pub struct StackFrame {541	pub msg: String,542	pub pos: String,543}544545#[derive(Debug)]546pub struct ErrorInfoBuilder {547	level: Level,548	msg: String,549	pub stack_frames: Vec<StackFrame>,550}551fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder> {552	let verbosity = Verbosity::from_int(lvl);553	let level: Level = verbosity.into();554	let v = String::from_utf8_lossy(v);555	Box::new(ErrorInfoBuilder {556		level,557		msg: v.to_string(),558		stack_frames: Vec::new(),559	})560}561impl ErrorInfoBuilder {562	fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]) {563		let v = String::from_utf8_lossy(v);564		let pos = String::from_utf8_lossy(pos);565		self.stack_frames.push(StackFrame {566			msg: v.to_string(),567			pos: pos.to_string(),568		});569	}570	fn emit_error_info(&mut self) {571		error!("{}", self.msg);572		for frame in &self.stack_frames {573			error!("  {} at {}", frame.msg, frame.pos)574		}575	}576}577578#[cxx::bridge]579pub mod nix_logging_cxx {580	extern "Rust" {581		type StartActivityBuilder;582		fn new_start_activity(activity_id: u64, lvl: u32, typ: u32) -> Box<StartActivityBuilder>;583		fn add_int_field(&mut self, i: i32);584		fn add_string_field(&mut self, v: &[u8]);585		fn emit(&mut self, parent: u64, s: &str);586		fn emit_result(&mut self, ty: u32);587	}588	extern "Rust" {589		type ErrorInfoBuilder;590		fn new_error_info(lvl: u32, v: &[u8]) -> Box<ErrorInfoBuilder>;591		fn push_stack_frame(&mut self, v: &[u8], pos: &[u8]);592		fn emit_error_info(&mut self);593	}594	extern "Rust" {595		fn emit_warn(v: &str);596		fn emit_stop(id: u64);597		fn emit_log(lvl: u32, v: &[u8]);598	}599	unsafe extern "C++" {600		include!("nix-eval/src/logging.hh");601602		type nix_c_context = crate::nix_raw::c_context;603604		fn apply_tracing_logger();605		unsafe fn extract_error_info(ctx: *const nix_c_context) -> Box<ErrorInfoBuilder>;606	}607}608609unsafe impl ExternType for crate::nix_raw::c_context {610	type Id = cxx::type_id!("nix_c_context");611612	type Kind = cxx::kind::Opaque;613}