git.delta.rocks / jrsonnet / refs/commits / d8bac4e1b3aa

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