git.delta.rocks / jrsonnet / refs/commits / 754b45cdacd0

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