git.delta.rocks / jrsonnet / refs/heads / trunk

1//! Collection of handlers, which transform program-specific stdout format to tracing23use std::{4	collections::HashMap,5	sync::{Arc, LazyLock, Mutex},6};78use regex::Regex;9use serde::Deserialize;10use tracing::{Span, info, info_span, warn};11#[cfg(feature = "indicatif")]12use tracing_indicatif::span_ext::IndicatifSpanExt as _;1314pub trait Handler: Send {15	fn handle_line(&mut self, e: &str);16}1718/// Handler wrapper, which can be cloned.19pub struct ClonableHandler<H>(Arc<Mutex<H>>);20impl<H> Clone for ClonableHandler<H> {21	fn clone(&self) -> Self {22		Self(self.0.clone())23	}24}25impl<H> ClonableHandler<H> {26	pub fn new(inner: H) -> Self {27		Self(Arc::new(Mutex::new(inner)))28	}29}30impl<H: Handler> Handler for ClonableHandler<H> {31	fn handle_line(&mut self, e: &str) {32		self.0.lock().unwrap().handle_line(e)33	}34}3536/// Converts command output to tracing lines37pub struct PlainHandler;38impl Handler for PlainHandler {39	fn handle_line(&mut self, e: &str) {40		info!(target: "log", "{e}");41	}42}4344/// Ignores output45pub struct NoopHandler;46impl Handler for NoopHandler {47	fn handle_line(&mut self, _e: &str) {}48}4950/// Transform nix internal-json logs to tracing spans.51#[derive(Default)]52pub struct NixHandler {53	spans: HashMap<u64, Span>,54}55#[derive(Deserialize, Debug)]56#[serde(untagged)]57enum LogField {58	String(String),59	Num(u64),60}6162/// Nix internal-json log line type63#[derive(Deserialize, Debug)]64#[serde(rename_all = "camelCase", tag = "action")]65#[allow(dead_code)]66enum NixLog {67	Msg {68		level: u32,69		msg: String,70		raw_msg: Option<String>,71	},72	Start {73		id: u64,74		level: u32,75		#[serde(default)]76		fields: Vec<LogField>,77		text: String,78		#[serde(rename = "type")]79		typ: u32,80	},81	Stop {82		id: u64,83	},84	Result {85		id: u64,86		#[serde(rename = "type")]87		typ: u32,88		#[serde(default)]89		fields: Vec<LogField>,90	},91}92fn process_message(m: &str) -> String {93	// Supposed to remove formatting characters except colors, as some programs try to reset cursor position etc.94	static OSC_CLEANER: LazyLock<Regex> =95		LazyLock::new(|| Regex::new(r"\x1B\]([^\x07\x1C]*[\x07\x1C])?|\r").unwrap());96	static DETABBER: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"\t").unwrap());97	let m = OSC_CLEANER.replace_all(m, "");98	// Indicatif can't format tabs. This is not the correct tab formatting, as correct one should be aligned,99	// and not just be replaced with the constant number of spaces, but it's ok for now, as statuses are single-line.100	DETABBER.replace_all(m.as_ref(), "  ").to_string()101}102impl Handler for NixHandler {103	fn handle_line(&mut self, e: &str) {104		if let Some(e) = e.strip_prefix("@nix ") {105			let log: NixLog = match serde_json::from_str(e) {106				Ok(l) => l,107				Err(err) => {108					warn!("failed to parse nix log line {:?}: {}", e, err);109					return;110				}111			};112			match log {113				NixLog::Msg { msg, raw_msg, .. } => {114					#[allow(clippy::nonminimal_bool)]115					if !(msg.starts_with("\u{1b}[35;1mwarning:\u{1b}[0m Git tree '")116						&& msg.ends_with("' is dirty"))117						&& !msg.starts_with(118							"\u{1b}[35;1mwarning:\u{1b}[0m not writing modified lock file of flake",119						) && msg120						!= "\u{1b}[35;1mwarning:\u{1b}[0m \u{1b}[31;1merror:\u{1b}[0m SQLite database '\u{1b}[35;1m/nix/var/nix/db/db.sqlite\u{1b}[0m' is busy"121					{122						if let Some(raw_msg) = raw_msg {123							if !msg.is_empty() {124								info!(target: "nix", "{}\n{}", raw_msg.trim_end(), msg.trim_end())125							} else {126								info!(target: "nix", "{}", raw_msg.trim_end())127							}128						} else {129							info!(target: "nix", "{}", msg.trim_end())130						}131					}132				}133				NixLog::Start {134					ref fields,135					typ,136					id,137					..138				} if typ == 105 && !fields.is_empty() => {139					if let [LogField::String(drv), ..] = &fields[..] {140						let mut drv = drv.as_str();141						if let Some(pkg) = drv.strip_prefix("/nix/store/") {142							let mut it = pkg.splitn(2, '-');143							it.next();144							if let Some(pkg) = it.next() {145								drv = pkg;146							}147						}148						info!(target: "nix","building {}", drv);149						let span = info_span!("build", drv);150						#[cfg(feature = "indicatif")]151						span.pb_start();152						self.spans.insert(id, span);153					} else {154						warn!("bad build log: {:?}", log)155					}156				}157				NixLog::Start {158					ref fields,159					typ,160					id,161					..162				} if typ == 100 && fields.len() >= 3 => {163					if let [164						LogField::String(drv),165						LogField::String(from),166						LogField::String(to),167						..,168					] = &fields[..]169					{170						let mut drv = drv.as_str();171172						if let Some(pkg) = drv.strip_prefix("/nix/store/") {173							let mut it = pkg.splitn(2, '-');174							it.next();175							if let Some(pkg) = it.next() {176								drv = pkg;177							}178						}179						info!(target: "nix","copying {} {} -> {}", drv, from, to);180						let span = info_span!("copy", from, to, drv);181						#[cfg(feature = "indicatif")]182						span.pb_start();183						self.spans.insert(id, span);184					} else {185						warn!("bad copy log: {:?}", log)186					}187				}188				NixLog::Start { text, typ, id, .. }189					if typ == 0 || typ == 102 || typ == 103 || typ == 104 =>190				{191					if !text.is_empty()192						&& text != "querying info about missing paths"193						&& text != "copying 0 paths"194						// Too much spam on lazy-trees branch195						&& !(text.starts_with("copying '") && text.ends_with("' to the store"))196					{197						let span = info_span!("job");198						#[cfg(feature = "indicatif")]199						{200							span.pb_start();201							span.pb_set_message(&process_message(text.trim()));202						}203						self.spans.insert(id, span);204						info!(target: "nix", "{}", text);205					}206				}207				NixLog::Start {208					text,209					level: 0,210					typ: 108,211					..212				} if text.is_empty() => {213					// Cache lookup? Coupled with copy log214				}215				NixLog::Start {216					text,217					level: 4,218					typ: 109,219					..220				} if text.starts_with("querying info about ") => {221					// Cache lookup222				}223				NixLog::Start {224					text,225					level: 4,226					typ: 101,227					..228				} if text.starts_with("downloading ") => {229					// NAR downloading, coupled with copy log230				}231				NixLog::Start {232					text,233					level: 1,234					typ: 111,235					..236				} if text.starts_with("waiting for a machine to build ") => {237					// Useless repeating notification about build238				}239				NixLog::Start {240					text,241					level: 3,242					typ: 111,243					..244				} if text.starts_with("resolved derivation: ") => {245					// CA resolved246				}247				NixLog::Start {248					text,249					level: 1,250					typ: 111,251					id,252					..253				} if text.starts_with("waiting for lock on ") => {254					let mut drv = text.strip_prefix("waiting for lock on ").unwrap();255					if let Some(txt) = drv.strip_prefix("\u{1b}[35;1m'") {256						drv = txt;257					}258					if let Some(txt) = drv.strip_suffix("'\u{1b}[0m") {259						drv = txt;260					}261					if let Some(txt) = drv.split("', '").next() {262						drv = txt;263					}264					if let Some(pkg) = drv.strip_prefix("/nix/store/") {265						let mut it = pkg.splitn(2, '-');266						it.next();267						if let Some(pkg) = it.next() {268							drv = pkg;269						}270					}271					let span = info_span!("waiting on drv", drv);272					#[cfg(feature = "indicatif")]273					span.pb_start();274					self.spans.insert(id, span);275					// Concurrent build of the same message276				}277				NixLog::Stop { id, .. } => {278					self.spans.remove(&id);279				}280				NixLog::Result { fields, id, typ } if typ == 101 && !fields.is_empty() => {281					if let Some(span) = self.spans.get(&id) {282						if let LogField::String(s) = &fields[0] {283							#[cfg(feature = "indicatif")]284							span.pb_set_message(&process_message(s.trim()));285							#[cfg(not(feature = "indicatif"))]286							{287								let _span = span.enter();288								info!("{}", process_message(s));289							}290						} else {291							warn!("bad fields: {fields:?}");292						}293					} else {294						warn!("unknown result id: {id} {typ} {fields:?}");295					}296					// dbg!(fields, id, typ);297				}298				NixLog::Result { fields, id, typ } if typ == 105 && fields.len() >= 4 => {299					if let Some(span) = self.spans.get(&id) {300						if let [301							LogField::Num(done),302							LogField::Num(expected),303							LogField::Num(_running),304							LogField::Num(_failed),305						] = &fields[..4]306						{307							#[cfg(feature = "indicatif")]308							{309								span.pb_set_length(*expected);310								span.pb_set_position(*done);311							}312							let _ = (span, done, expected);313						} else {314							warn!("bad fields: {fields:?}");315						}316					} else {317						// warn!("unknown result id: {id} {typ} {fields:?}");318						// Unaccounted progress.319					}320					// dbg!(fields, id, typ);321				}322				NixLog::Result { typ, .. } if typ == 104 || typ == 106 => {323					// Set phase, expected324				}325				_ => warn!("unknown log: {:?}", log),326			};327		} else {328			let e = e.trim();329			if e.starts_with("Failed tcsetattr(TCSADRAIN): ") {330				return;331			}332			info!("{e}")333		}334	}335}