git.delta.rocks / jrsonnet / refs/commits / 9b6d5bfd4477

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