//! Sqlite-backed full build-log capture — stdout + stderr per //! `nixos-container` / `nix build` invocation, accumulated live. //! Schema, indices, retention, and the rationale for replacing //! the old ring buffer: `docs/persistence.md::/var/lib/hyperhive/build_logs.sqlite`. use std::path::Path; use std::sync::{Arc, Mutex, OnceLock}; use std::time::{SystemTime, UNIX_EPOCH}; use anyhow::{Context, Result}; use rusqlite::{Connection, OptionalExtension, params}; use serde::Serialize; use tokio::sync::broadcast; /// Process-singleton handle, set once at coordinator startup. Lets /// the `lifecycle` module's `run` / `prebuild_toplevel` access the /// writer without threading an `Arc` through every /// `pub async fn` entry point in the lifecycle surface — there are /// 10+ callsites and the handle is the same `Arc` everywhere /// anyway. Set by `Coordinator::open`. static GLOBAL: OnceLock> = OnceLock::new(); /// Install the process-wide `BuildLogs` handle. Idempotent: a second /// call (e.g. test harness setup) silently keeps the first handle. pub fn install(handle: Arc) { let _ = GLOBAL.set(handle); } /// Fetch the process-wide handle, or `None` if `install` hasn't run /// yet (e.g. early in startup before `Coordinator::open`, or in unit /// tests that don't bother with the global). Callers must gracefully /// no-op when this returns `None`. #[must_use] pub fn global() -> Option> { GLOBAL.get().cloned() } /// Retain failed-build rows for 30 days — they're what the operator /// needs to investigate when diagnosing a regression. const KEEP_FAIL_SECS: i64 = 30 * 24 * 3600; /// Retain successful-build rows for 24 hours — useful for diffing /// what changed across a recent rebuild, but past a day the log is /// noise. In-progress rows are never reaped (they have /// `finished_at IS NULL`). const KEEP_OK_SECS: i64 = 24 * 3600; const SCHEMA: &str = " CREATE TABLE IF NOT EXISTS build_logs ( id INTEGER PRIMARY KEY AUTOINCREMENT, agent TEXT NOT NULL, kind TEXT NOT NULL, cmdline TEXT NOT NULL, started_at INTEGER NOT NULL, finished_at INTEGER, status TEXT, stdout TEXT NOT NULL DEFAULT '', stderr TEXT NOT NULL DEFAULT '' ); CREATE INDEX IF NOT EXISTS idx_build_logs_agent_started ON build_logs (agent, started_at DESC); CREATE INDEX IF NOT EXISTS idx_build_logs_status_finished ON build_logs (status, finished_at) WHERE finished_at IS NOT NULL; "; /// Status of a finished build attempt. Stored as the literal string in /// the `status` column; `NULL` while the attempt is still in progress. #[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize)] #[serde(rename_all = "snake_case")] pub enum BuildStatus { /// Child exited with success. Ok, /// Child exited non-zero (build / eval failure). Fail, } impl BuildStatus { fn as_str(self) -> &'static str { match self { Self::Ok => "ok", Self::Fail => "fail", } } } /// Header-only row returned by `list_recent_for_agent`. Carries the /// metadata the dashboard's agent-card chip needs (status + age + /// id-to-open) without the multi-MB stdout/stderr payload. #[derive(Debug, Clone, Serialize)] pub struct BuildLogHeader { pub id: i64, pub agent: String, pub kind: String, pub cmdline: String, pub started_at: i64, pub finished_at: Option, pub status: Option, /// Elapsed seconds from `started_at` to `finished_at`. `None` while /// the build is still in progress. pub runtime_secs: Option, } /// Full row with stdout/stderr text inlined. Returned by `get_full`, /// backs the side-panel viewer's payload. #[derive(Debug, Clone, Serialize)] pub struct BuildLogFull { #[serde(flatten)] pub header: BuildLogHeader, pub stdout: String, pub stderr: String, } /// Incremental text returned by `get_progress`. Carries only the new /// bytes since the caller's last cursor positions so the SSE stream /// handler can send deltas without re-transmitting the full log. #[derive(Debug, Clone)] pub struct BuildLogProgress { /// New stdout bytes beyond `stdout_cursor`. pub stdout_append: String, /// New stderr bytes beyond `stderr_cursor`. pub stderr_append: String, /// `Some(unix_ts)` once the build is finished. pub finished_at: Option, /// Terminal status string (`"ok"` / `"fail"`) once finished. pub status: Option, } /// Channel capacity for per-build append notifications. 64 slots is /// plenty — the consumer reads fast relative to line-append rate and /// any lag means "read now, you have new content" rather than a lost /// data line. const NOTIFY_CAP: usize = 64; /// Sqlite-backed build-log store. `Arc`-friendly: all /// methods take `&self`, internal `Mutex` serializes /// access. pub struct BuildLogs { conn: Mutex, /// Broadcast channel that fires with the `id` of the row that just /// had a line appended or was finished. The SSE stream handler /// subscribes once per open panel and drives delta reads from this. /// `send()` is non-async and silently drops frames when there are /// no subscribers — safe to call from sync append/finish paths. notify_tx: broadcast::Sender, } impl BuildLogs { pub fn open(db_dir: &Path) -> Result { std::fs::create_dir_all(db_dir) .with_context(|| format!("create build_logs db parent {}", db_dir.display()))?; let path = db_dir.join("build_logs.sqlite"); let conn = Connection::open(&path) .with_context(|| format!("open build_logs db {}", path.display()))?; conn.execute_batch(SCHEMA) .context("apply build_logs schema")?; let (notify_tx, _) = broadcast::channel(NOTIFY_CAP); Ok(Self { conn: Mutex::new(conn), notify_tx, }) } /// Subscribe to per-build append/finish notifications. Each emitted /// value is the `id` of the row that changed. The SSE stream handler /// calls this once and filters for its target id. pub fn subscribe_notifications(&self) -> broadcast::Receiver { self.notify_tx.subscribe() } /// Open a row for a new build attempt. Returns the assigned id /// — the caller threads it through `append_stdout` / `append_stderr` /// while the child runs and into `finish` once it exits. pub fn start(&self, agent: &str, kind: &str, cmdline: &str) -> Result { let now = now_secs(); let conn = self.conn.lock().unwrap(); conn.execute( "INSERT INTO build_logs (agent, kind, cmdline, started_at) VALUES (?1, ?2, ?3, ?4)", params![agent, kind, cmdline, now], ) .context("insert build_logs row")?; Ok(conn.last_insert_rowid()) } /// Append a single stdout line. Best-effort: errors are logged /// but never returned to the caller, so a transient sqlite blip /// never tears down a rebuild's stdout pump. pub fn append_stdout(&self, id: i64, line: &str) { self.append(id, "stdout", line); } /// Append a single stderr line. Same best-effort contract as /// `append_stdout`. pub fn append_stderr(&self, id: i64, line: &str) { self.append(id, "stderr", line); } fn append(&self, id: i64, column: &'static str, line: &str) { // `column` is hard-coded by the caller (`stdout` / `stderr`) // — never user-supplied — so the string-format here is safe // and lets us reuse one helper for both streams. let sql = format!("UPDATE build_logs SET {column} = {column} || ?1 || x'0a' WHERE id = ?2"); let conn = self.conn.lock().unwrap(); if let Err(e) = conn.execute(&sql, params![line, id]) { tracing::warn!( build_log_id = id, column = column, error = ?e, "build_logs: append failed (dropping line)" ); } drop(conn); // Notify SSE stream subscribers — non-blocking, no-op when no // subscribers are watching (e.g. no panel is open). Lagged // receivers (channel full) automatically drop frames; the SSE // handler re-reads the full delta on the next notification it // does receive, so no content is lost, only an intermediate // wake-up is coalesced. let _ = self.notify_tx.send(id); } /// Finalize a build attempt. Sets `finished_at` to now and /// `status` to the terminal state. Best-effort. pub fn finish(&self, id: i64, status: BuildStatus) { let now = now_secs(); let conn = self.conn.lock().unwrap(); if let Err(e) = conn.execute( "UPDATE build_logs SET finished_at = ?1, status = ?2 WHERE id = ?3", params![now, status.as_str(), id], ) { tracing::warn!( build_log_id = id, error = ?e, "build_logs: finish failed" ); } drop(conn); // Final notification so the SSE stream handler sees the // finished_at and status, closes the connection cleanly. let _ = self.notify_tx.send(id); } /// Return incremental log content beyond the given byte cursors. /// Used by the SSE stream handler to compute deltas between polls. /// /// `stdout_cursor` / `stderr_cursor` are byte offsets into the /// stored `stdout` / `stderr` columns from the previous read. /// Slicing is safe because cursors are always derived from prior /// `String::len()` values (valid UTF-8 boundaries). /// /// Returns `None` when the row no longer exists (vacuum reap during /// a long-open panel). pub fn get_progress( &self, id: i64, stdout_cursor: usize, stderr_cursor: usize, ) -> Result> { let conn = self.conn.lock().unwrap(); let mut stmt = conn.prepare( "SELECT stdout, stderr, finished_at, status \ FROM build_logs WHERE id = ?1", )?; let row = stmt .query_row(params![id], |r| { Ok(( r.get::<_, String>(0)?, r.get::<_, String>(1)?, r.get::<_, Option>(2)?, r.get::<_, Option>(3)?, )) }) .optional()?; match row { None => Ok(None), Some((stdout, stderr, finished_at, status)) => { let stdout_append = stdout.get(stdout_cursor..).unwrap_or("").to_string(); let stderr_append = stderr.get(stderr_cursor..).unwrap_or("").to_string(); Ok(Some(BuildLogProgress { stdout_append, stderr_append, finished_at, status, })) } } } /// Return the most recent `limit` rows for `agent`, newest first. /// Headers only (no stdout/stderr blobs) — keeps `/api/state` /// payloads light. Limit is hard-clamped to 50 to bound worst-case /// payload regardless of caller input. pub fn list_recent_for_agent(&self, agent: &str, limit: usize) -> Result> { let limit = limit.min(50); let conn = self.conn.lock().unwrap(); let mut stmt = conn.prepare( "SELECT id, agent, kind, cmdline, started_at, finished_at, status FROM build_logs WHERE agent = ?1 ORDER BY started_at DESC LIMIT ?2", )?; let rows = stmt.query_map( params![agent, i64::try_from(limit).unwrap_or(50)], row_to_header, )?; let mut out = Vec::new(); for r in rows { out.push(r?); } Ok(out) } /// Return the most recent `limit` rows across all agents, newest first. /// Same header-only shape as `list_recent_for_agent`. Limit clamped to 100. pub fn list_recent_all(&self, limit: usize) -> Result> { let limit = limit.min(100); let conn = self.conn.lock().unwrap(); let mut stmt = conn.prepare( "SELECT id, agent, kind, cmdline, started_at, finished_at, status FROM build_logs ORDER BY started_at DESC LIMIT ?1", )?; let rows = stmt.query_map(params![i64::try_from(limit).unwrap_or(100)], row_to_header)?; let mut out = Vec::new(); for r in rows { out.push(r?); } Ok(out) } /// Fetch a single full row (with stdout/stderr text) by id. /// Returns `None` when the id doesn't exist (vacuum sweep already /// reaped it, or the operator passed a stale id from a refresh /// race). pub fn get_full(&self, id: i64) -> Result> { let conn = self.conn.lock().unwrap(); let mut stmt = conn.prepare( "SELECT id, agent, kind, cmdline, started_at, finished_at, status, stdout, stderr FROM build_logs WHERE id = ?1", )?; let row = stmt .query_row(params![id], |r| { let started_at: i64 = r.get(4)?; let finished_at: Option = r.get(5)?; let runtime_secs = compute_runtime_secs(started_at, finished_at); Ok(BuildLogFull { header: BuildLogHeader { id: r.get(0)?, agent: r.get(1)?, kind: r.get(2)?, cmdline: r.get(3)?, started_at, finished_at, status: r.get(6)?, runtime_secs, }, stdout: r.get(7)?, stderr: r.get(8)?, }) }) .optional()?; Ok(row) } /// Drop rows past their retention window. Returns the number of /// rows deleted. Called from the existing hourly vacuum loop — /// see `stats_vacuum` for the call site. /// /// Rule: /// - `status = 'fail'` rows kept for `KEEP_FAIL_SECS` past their /// `finished_at` (failures are what operators dig into). /// - `status = 'ok'` rows kept for `KEEP_OK_SECS` past their /// `finished_at` (successes are mostly noise after a day). /// - In-flight rows (`finished_at IS NULL`) are never touched — /// a long-running build shouldn't disappear from its own log /// viewer mid-stream. pub fn vacuum(&self) -> Result { let now = now_secs(); let conn = self.conn.lock().unwrap(); let fail_cutoff = now - KEEP_FAIL_SECS; let ok_cutoff = now - KEEP_OK_SECS; let removed = conn.execute( "DELETE FROM build_logs WHERE finished_at IS NOT NULL AND ( (status = 'fail' AND finished_at < ?1) OR (status = 'ok' AND finished_at < ?2) )", params![fail_cutoff, ok_cutoff], )?; Ok(u64::try_from(removed).unwrap_or(0)) } } /// Spawn the hourly retention sweep. Mirrors `stats_vacuum::spawn` / /// `events_vacuum::spawn` in cadence + shutdown handling. Runs once /// at startup before its first sleep so a long-uptime instance /// doesn't accumulate a backlog the first hour after restart. pub fn spawn_vacuum(coord: &Arc) { use std::time::Duration; let logs = coord.build_logs.clone(); let mut shutdown = coord.shutdown_rx(); let interval = Duration::from_hours(1); tokio::spawn(async move { loop { match logs.vacuum() { Ok(0) => {} Ok(n) => tracing::info!(removed = n, "build_logs vacuum"), Err(e) => tracing::warn!(error = ?e, "build_logs vacuum failed"), } tokio::select! { () = tokio::time::sleep(interval) => {} _ = shutdown.changed() => { tracing::info!("build_logs vacuum: shutdown signal received"); break; } } } }); } fn compute_runtime_secs(started_at: i64, finished_at: Option) -> Option { finished_at.map(|f| f - started_at) } fn row_to_header(r: &rusqlite::Row) -> rusqlite::Result { let started_at: i64 = r.get(4)?; let finished_at: Option = r.get(5)?; let runtime_secs = compute_runtime_secs(started_at, finished_at); Ok(BuildLogHeader { id: r.get(0)?, agent: r.get(1)?, kind: r.get(2)?, cmdline: r.get(3)?, started_at, finished_at, status: r.get(6)?, runtime_secs, }) } fn now_secs() -> i64 { SystemTime::now() .duration_since(UNIX_EPOCH) .ok() .and_then(|d| i64::try_from(d.as_secs()).ok()) .unwrap_or(0) } #[cfg(test)] mod tests { use super::*; fn tmpdb() -> (tempfile::TempDir, BuildLogs) { let dir = tempfile::tempdir().expect("tempdir"); let db = BuildLogs::open(dir.path()).expect("open"); (dir, db) } #[test] fn start_appends_finish_flow() { let (_d, db) = tmpdb(); let id = db .start("alice", "prebuild", "nix build foo") .expect("start"); db.append_stdout(id, "building '/nix/store/abc.drv'"); db.append_stderr(id, "error: line 12"); db.append_stderr(id, " at /nix/store/.../module.nix:5"); db.finish(id, BuildStatus::Fail); let full = db.get_full(id).expect("get").expect("Some"); assert_eq!(full.header.agent, "alice"); assert_eq!(full.header.kind, "prebuild"); assert_eq!(full.header.status.as_deref(), Some("fail")); assert!(full.header.finished_at.is_some()); assert!(full.stdout.contains("/nix/store/abc.drv")); assert!(full.stderr.contains("error: line 12")); assert!(full.stderr.contains("module.nix:5")); // Lines are terminator-delimited so each contributes a trailing // newline — the viewer joins on the existing newlines rather // than re-inserting them. assert!(full.stderr.ends_with('\n')); } #[test] fn list_recent_orders_newest_first_and_clamps() { let (_d, db) = tmpdb(); // Three attempts, two for alice + one for bob. Without sleeping // sqlite's `INTEGER` started_at ties at 1-sec resolution, so we // assert id-ordering (autoincrement) is the tiebreaker — list // sorts by started_at DESC but the ORDER BY still produces the // last-inserted row first when timestamps match. let id_a1 = db.start("alice", "run", "cmd one").expect("start"); let _id_b = db.start("bob", "run", "cmd two").expect("start"); let id_a2 = db.start("alice", "run", "cmd three").expect("start"); db.finish(id_a1, BuildStatus::Ok); let alice_rows = db.list_recent_for_agent("alice", 10).expect("list"); assert_eq!(alice_rows.len(), 2); // Without distinct started_at values both rows share `now`, // but list_recent already orders by `started_at DESC` then // sqlite's natural insertion-order tiebreak. We rely only on // both IDs being present + correct count + agent isolation. let ids: std::collections::HashSet = alice_rows.iter().map(|h| h.id).collect(); assert!(ids.contains(&id_a1)); assert!(ids.contains(&id_a2)); let bob_rows = db.list_recent_for_agent("bob", 10).expect("list"); assert_eq!(bob_rows.len(), 1); // Limit clamp at 50. let huge = db.list_recent_for_agent("alice", 999_999).expect("list"); assert!(huge.len() <= 50); } #[test] fn get_full_returns_none_for_missing_id() { let (_d, db) = tmpdb(); let missing = db.get_full(999_999).expect("get"); assert!(missing.is_none()); } #[test] fn vacuum_drops_old_finished_only_per_status() { let (_d, db) = tmpdb(); let id_fresh_fail = db.start("alice", "run", "fresh fail").expect("start"); let id_old_fail = db.start("alice", "run", "old fail").expect("start"); let id_old_ok = db.start("alice", "run", "old ok").expect("start"); let id_running = db.start("alice", "run", "still running").expect("start"); db.finish(id_fresh_fail, BuildStatus::Fail); db.finish(id_old_fail, BuildStatus::Fail); db.finish(id_old_ok, BuildStatus::Ok); // Backdate two rows past their retention windows. fresh_fail // stays within KEEP_FAIL_SECS so it survives; old_fail goes // beyond; old_ok goes past KEEP_OK_SECS but inside // KEEP_FAIL_SECS — proves the per-status rule. let now = now_secs(); { let conn = db.conn.lock().unwrap(); conn.execute( "UPDATE build_logs SET finished_at = ?1 WHERE id = ?2", params![now - KEEP_FAIL_SECS - 60, id_old_fail], ) .unwrap(); conn.execute( "UPDATE build_logs SET finished_at = ?1 WHERE id = ?2", params![now - KEEP_OK_SECS - 60, id_old_ok], ) .unwrap(); } let removed = db.vacuum().expect("vacuum"); assert_eq!(removed, 2, "old_fail + old_ok should be vacuumed"); assert!(db.get_full(id_fresh_fail).unwrap().is_some()); assert!(db.get_full(id_old_fail).unwrap().is_none()); assert!(db.get_full(id_old_ok).unwrap().is_none()); // Running row must survive vacuum regardless of retention // windows — finished_at IS NULL gates it out. assert!(db.get_full(id_running).unwrap().is_some()); } #[test] fn append_after_finish_still_appends() { // Defensive: if a child's stdout pump fires one last line // between the wait-syscall returning and `finish` running, the // append should land on the row (status already set, but the // log stays consistent with what happened). let (_d, db) = tmpdb(); let id = db.start("alice", "run", "cmd").expect("start"); db.finish(id, BuildStatus::Ok); db.append_stdout(id, "post-finish trailing line"); let full = db.get_full(id).expect("get").expect("Some"); assert!(full.stdout.contains("post-finish trailing line")); } }