git.delta.rocks / jrsonnet / refs/commits / 064468b85673

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::{info, info_span, warn, Span};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 '") && msg.ends_with("' is dirty"))116					&& !msg.starts_with("\u{1b}[35;1mwarning:\u{1b}[0m not writing modified lock file of flake")117					&& msg != "\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" {118						if let Some(raw_msg) = raw_msg {119							if !msg.is_empty() {120								info!(target: "nix", "{}\n{}", raw_msg.trim_end(), msg.trim_end())121							} else {122								info!(target: "nix", "{}", raw_msg.trim_end())123							}124						} else {125							info!(target: "nix", "{}", msg.trim_end())126						}127					}128				}129				NixLog::Start {130					ref fields,131					typ,132					id,133					..134				} if typ == 105 && !fields.is_empty() => {135					if let [LogField::String(drv), ..] = &fields[..] {136						let mut drv = drv.as_str();137						if let Some(pkg) = drv.strip_prefix("/nix/store/") {138							let mut it = pkg.splitn(2, '-');139							it.next();140							if let Some(pkg) = it.next() {141								drv = pkg;142							}143						}144						info!(target: "nix","building {}", drv);145						let span = info_span!("build", drv);146						#[cfg(feature = "indicatif")]147						span.pb_start();148						self.spans.insert(id, span);149					} else {150						warn!("bad build log: {:?}", log)151					}152				}153				NixLog::Start {154					ref fields,155					typ,156					id,157					..158				} if typ == 100 && fields.len() >= 3 => {159					if let [LogField::String(drv), LogField::String(from), LogField::String(to), ..] =160						&fields[..]161					{162						let mut drv = drv.as_str();163164						if let Some(pkg) = drv.strip_prefix("/nix/store/") {165							let mut it = pkg.splitn(2, '-');166							it.next();167							if let Some(pkg) = it.next() {168								drv = pkg;169							}170						}171						info!(target: "nix","copying {} {} -> {}", drv, from, to);172						let span = info_span!("copy", from, to, drv);173						#[cfg(feature = "indicatif")]174						span.pb_start();175						self.spans.insert(id, span);176					} else {177						warn!("bad copy log: {:?}", log)178					}179				}180				NixLog::Start { text, typ, id, .. }181					if typ == 0 || typ == 102 || typ == 103 || typ == 104 =>182				{183					if !text.is_empty()184						&& text != "querying info about missing paths"185						&& text != "copying 0 paths"186						// Too much spam on lazy-trees branch187						&& !(text.starts_with("copying '") && text.ends_with("' to the store"))188					{189						let span = info_span!("job");190						#[cfg(feature = "indicatif")]191						{192							span.pb_start();193							span.pb_set_message(&process_message(text.trim()));194						}195						self.spans.insert(id, span);196						info!(target: "nix", "{}", text);197					}198				}199				NixLog::Start {200					text,201					level: 0,202					typ: 108,203					..204				} if text.is_empty() => {205					// Cache lookup? Coupled with copy log206				}207				NixLog::Start {208					text,209					level: 4,210					typ: 109,211					..212				} if text.starts_with("querying info about ") => {213					// Cache lookup214				}215				NixLog::Start {216					text,217					level: 4,218					typ: 101,219					..220				} if text.starts_with("downloading ") => {221					// NAR downloading, coupled with copy log222				}223				NixLog::Start {224					text,225					level: 1,226					typ: 111,227					..228				} if text.starts_with("waiting for a machine to build ") => {229					// Useless repeating notification about build230				}231				NixLog::Start {232					text,233					level: 3,234					typ: 111,235					..236				} if text.starts_with("resolved derivation: ") => {237					// CA resolved238				}239				NixLog::Start {240					text,241					level: 1,242					typ: 111,243					id,244					..245				} if text.starts_with("waiting for lock on ") => {246					let mut drv = text.strip_prefix("waiting for lock on ").unwrap();247					if let Some(txt) = drv.strip_prefix("\u{1b}[35;1m'") {248						drv = txt;249					}250					if let Some(txt) = drv.strip_suffix("'\u{1b}[0m") {251						drv = txt;252					}253					if let Some(txt) = drv.split("', '").next() {254						drv = txt;255					}256					if let Some(pkg) = drv.strip_prefix("/nix/store/") {257						let mut it = pkg.splitn(2, '-');258						it.next();259						if let Some(pkg) = it.next() {260							drv = pkg;261						}262					}263					let span = info_span!("waiting on drv", drv);264					#[cfg(feature = "indicatif")]265					span.pb_start();266					self.spans.insert(id, span);267					// Concurrent build of the same message268				}269				NixLog::Stop { id, .. } => {270					self.spans.remove(&id);271				}272				NixLog::Result { fields, id, typ } if typ == 101 && !fields.is_empty() => {273					if let Some(span) = self.spans.get(&id) {274						if let LogField::String(s) = &fields[0] {275							#[cfg(feature = "indicatif")]276							span.pb_set_message(&process_message(s.trim()));277							#[cfg(not(feature = "indicatif"))]278							{279								let _span = span.enter();280								info!("{}", process_message(s));281							}282						} else {283							warn!("bad fields: {fields:?}");284						}285					} else {286						warn!("unknown result id: {id} {typ} {fields:?}");287					}288					// dbg!(fields, id, typ);289				}290				NixLog::Result { fields, id, typ } if typ == 105 && fields.len() >= 4 => {291					if let Some(span) = self.spans.get(&id) {292						if let [LogField::Num(done), LogField::Num(expected), LogField::Num(_running), LogField::Num(_failed)] =293							&fields[..4]294						{295							#[cfg(feature = "indicatif")]296							{297								span.pb_set_length(*expected);298								span.pb_set_position(*done);299							}300							let _ = (span, done, expected);301						} else {302							warn!("bad fields: {fields:?}");303						}304					} else {305						// warn!("unknown result id: {id} {typ} {fields:?}");306						// Unaccounted progress.307					}308					// dbg!(fields, id, typ);309				}310				NixLog::Result { typ, .. } if typ == 104 || typ == 106 => {311					// Set phase, expected312				}313				_ => warn!("unknown log: {:?}", log),314			};315		} else {316			let e = e.trim();317			if e.starts_with("Failed tcsetattr(TCSADRAIN): ") {318				return;319			}320			info!("{e}")321		}322	}323}