main
Drew Owens 0.10.5 source 1dc9df6 7d ago
//! The background-action ledger and the measured verb-timing store.
//!
//! Two facts a user needs about a bridge that drives their live CAD session
//! while they are not watching:
//!
//!   * **What did it do on its own?** Every document this bridge created, every
//!     scratch document it swept, every dialog it closed, every com-host respawn
//!     lands in an append-only ledger (`ledger.jsonl` in the scratch root) that
//!     `swx_action_ledger` reads back. Fusion calls this the quietness audit
//!     log; the shape is the same: `{at, action, detail}`.
//!   * **What does this machine actually cost?** Every slow verb records its
//!     duration in `timings.json`, and `swx_verb_times` reports count/p50/p90
//!     per verb. That is the store that should pace a progress bar — an ETA
//!     measured on THIS machine beats a constant compiled into the bridge.
//!
//! Both are best-effort: a bridge must never fail a real verb because it could
//! not write its own diary. Both are bounded, because nothing this bridge writes
//! is allowed to grow without limit.

use serde_json::{json, Map, Value};
use std::sync::Mutex;

/// Ledger lines the live file is trimmed BACK TO. Trimming happens only once the
/// file passes TWICE this (`LEDGER_HIGH_WATER`), so a merge of two capped
/// ledgers (adversary pass 41) is not cut back on the start that made it — and
/// trimming never deletes: the lines it removes go to `ledger-archive-<stamp>.jsonl`
/// in the data root, and a `ledger_archived` line says how many and where.
pub const LEDGER_MAX_LINES: usize = 2_000;
pub const LEDGER_HIGH_WATER: usize = 2 * LEDGER_MAX_LINES;
/// Samples kept per verb in the timing store — enough for a stable p90, small
/// enough that the file stays a few KB.
const TIMING_SAMPLES: usize = 50;

static LEDGER_LOCK: Mutex<()> = Mutex::new(());
static TIMING_LOCK: Mutex<()> = Mutex::new(());

fn ledger_path(root: &std::path::Path) -> std::path::PathBuf {
    root.join("ledger.jsonl")
}

fn timings_path(root: &std::path::Path) -> std::path::PathBuf {
    root.join("timings.json")
}

fn now_epoch() -> u64 {
    std::time::SystemTime::now()
        .duration_since(std::time::UNIX_EPOCH)
        .map(|d| d.as_secs())
        .unwrap_or(0)
}

/// Record one background action. `action` is a stable slug the caller can
/// branch on (`document_created`, `document_closed`, `dialog_closed`,
/// `com_host_respawn`); `detail` is free-form context for a human.
pub fn record(action: &str, detail: Value) {
    record_in(&crate::scratch::root(), action, detail)
}

/// `record` with the root made explicit, so the tests exercise the real code
/// without mutating the process environment (which would race the other tests
/// sharing this process).
pub fn record_in(root: &std::path::Path, action: &str, detail: Value) {
    let _guard = LEDGER_LOCK.lock();
    let path = ledger_path(root);
    if let Some(parent) = path.parent() {
        let _ = std::fs::create_dir_all(parent);
    }
    let mut lines: Vec<String> = std::fs::read_to_string(&path)
        .map(|s| s.lines().map(|l| l.to_string()).collect())
        .unwrap_or_default();
    // EVERY LINE CARRIES A SEQUENCE NUMBER (adversary pass 41). `at` is seconds
    // and some details say only {title, by}, so two real events could be
    // byte-identical — and a merge could not tell them from one event copied.
    // With `seq`, identity never depends on content.
    let mut seq = lines
        .iter()
        .filter_map(|l| serde_json::from_str::<Value>(l).ok()?.get("seq")?.as_u64())
        .max()
        .unwrap_or(0);
    let mut next = || {
        seq += 1;
        seq
    };
    // NEVER A SILENT CUT. Past the high-water mark the oldest lines go to an
    // ARCHIVE file first, and only if that write succeeds are they removed here,
    // with a line saying how many and where. A failed archive keeps them all.
    if lines.len() + 1 > LEDGER_HIGH_WATER {
        let drop = lines.len() + 2 - LEDGER_MAX_LINES;
        let archived: Vec<String> = lines[..drop.min(lines.len())].to_vec();
        let stamp = crate::scratch::stamp_now();
        let mut name = format!("ledger-archive-{stamp}.jsonl");
        let mut n = 2;
        while root.join(&name).exists() {
            name = format!("ledger-archive-{stamp}-{n}.jsonl");
            n += 1;
        }
        if crate::launch::write_atomic(&root.join(&name), &(archived.join("\n") + "\n")).is_ok() {
            lines.drain(0..archived.len());
            lines.push(
                json!({"at": now_epoch(), "seq": next(), "action": "ledger_archived",
                       "detail": {"lines": archived.len(), "archive": name,
                                  "why": "the live ledger passed its high-water mark; the oldest lines were moved, not deleted"}})
                .to_string(),
            );
        }
    }
    let mut entry = json!({"at": now_epoch(), "seq": next(), "action": action, "detail": detail});
    // A MEMORY SAMPLE ON EVERY LINE (0.10.5): commit available and SOLIDWORKS's
    // own share, so growth over a long run is visible after the fact.
    if let Some(mem) = crate::memory::ledger_sample() {
        entry["mem"] = mem;
    }
    lines.push(entry.to_string());
    // ATOMIC. The ledger is the one artefact that outlives the bridge — it is
    // the record of what this bridge did on somebody's machine while they were
    // not watching — and a plain `write` truncates before it fills. A kill in
    // that window would take the whole audit log, not the last line.
    let _ = crate::launch::write_atomic(&path, &(lines.join("\n") + "\n"));
}

/// The most recent `limit` actions, newest LAST (chronological, the order a
/// human reads a log in).
pub fn read(limit: usize) -> Vec<Value> {
    read_in(&crate::scratch::root(), limit)
}

pub fn read_in(root: &std::path::Path, limit: usize) -> Vec<Value> {
    let _guard = LEDGER_LOCK.lock();
    let text = std::fs::read_to_string(ledger_path(root)).unwrap_or_default();
    let all: Vec<Value> = text.lines().filter_map(|l| serde_json::from_str(l).ok()).collect();
    let start = all.len().saturating_sub(limit.max(1));
    all[start..].to_vec()
}

/// Record how long one verb took on THIS machine.
pub fn record_time(verb: &str, seconds: f64) {
    record_time_in(&crate::scratch::root(), verb, seconds)
}

pub fn record_time_in(root: &std::path::Path, verb: &str, seconds: f64) {
    if !seconds.is_finite() || seconds < 0.0 {
        return;
    }
    let _guard = TIMING_LOCK.lock();
    let path = timings_path(root);
    if let Some(parent) = path.parent() {
        let _ = std::fs::create_dir_all(parent);
    }
    let mut store: Map<String, Value> = std::fs::read_to_string(&path)
        .ok()
        .and_then(|s| serde_json::from_str::<Value>(&s).ok())
        .and_then(|v| v.as_object().cloned())
        .unwrap_or_default();
    let samples = store.entry(verb.to_string()).or_insert_with(|| json!([]));
    if let Some(arr) = samples.as_array_mut() {
        arr.push(json!(round2(seconds)));
        if arr.len() > TIMING_SAMPLES {
            let drop = arr.len() - TIMING_SAMPLES;
            arr.drain(0..drop);
        }
    }
    let _ = crate::launch::write_atomic(&path, &Value::Object(store).to_string());
}

/// `{verb: {count, p50, p90, minSec, maxSec}}` — the Fusion `verb_times.stages`
/// shape, computed from the samples this machine actually produced.
pub fn stages() -> Value {
    stages_in(&crate::scratch::root())
}

pub fn stages_in(root: &std::path::Path) -> Value {
    let _guard = TIMING_LOCK.lock();
    let store: Map<String, Value> = std::fs::read_to_string(timings_path(root))
        .ok()
        .and_then(|s| serde_json::from_str::<Value>(&s).ok())
        .and_then(|v| v.as_object().cloned())
        .unwrap_or_default();
    let mut out = Map::new();
    for (verb, samples) in store {
        let mut v: Vec<f64> =
            samples.as_array().map(|a| a.iter().filter_map(|x| x.as_f64()).collect()).unwrap_or_default();
        if v.is_empty() {
            continue;
        }
        v.sort_by(|a, b| a.partial_cmp(b).unwrap_or(std::cmp::Ordering::Equal));
        out.insert(
            verb,
            json!({
                "count": v.len(),
                "p50": percentile(&v, 0.50),
                "p90": percentile(&v, 0.90),
                "minSec": round2(v[0]),
                "maxSec": round2(v[v.len() - 1]),
            }),
        );
    }
    Value::Object(out)
}

/// Nearest-rank percentile over an ALREADY-SORTED slice. Nearest-rank (not
/// linear interpolation) because with 3 samples an interpolated "p90" invents a
/// number no run ever produced; a real observed sample is the honest answer.
pub fn percentile(sorted: &[f64], q: f64) -> f64 {
    if sorted.is_empty() {
        return 0.0;
    }
    let rank = (q * sorted.len() as f64).ceil().max(1.0) as usize;
    round2(sorted[rank.min(sorted.len()) - 1])
}

fn round2(v: f64) -> f64 {
    (v * 100.0).round() / 100.0
}

/// Time a block and file the measurement under `verb`.
pub fn timed<T>(verb: &str, f: impl FnOnce() -> T) -> T {
    let started = std::time::Instant::now();
    let out = f();
    record_time(verb, started.elapsed().as_secs_f64());
    out
}

#[cfg(test)]
mod tests {
    use super::*;

    fn temp_root(tag: &str) -> std::path::PathBuf {
        let d = std::env::temp_dir().join(format!("swx-ledger-{tag}-{}", std::process::id()));
        let _ = std::fs::remove_dir_all(&d);
        std::fs::create_dir_all(&d).unwrap();
        d
    }

    #[test]
    fn every_line_carries_a_sequence_number_that_only_goes_up() {
        let root = temp_root("seq");
        // A pre-0.9.3 ledger: no `seq` on its lines.
        std::fs::write(ledger_path(&root), "{\"at\":1,\"action\":\"old\",\"detail\":{}}\n").unwrap();
        for _ in 0..3 {
            record_in(&root, "document_closed", json!({"title": "smoke.SLDPRT", "by": "reset_workspace"}));
        }
        let seqs: Vec<u64> = std::fs::read_to_string(ledger_path(&root))
            .unwrap()
            .lines()
            .filter_map(|l| serde_json::from_str::<Value>(l).ok()?.get("seq")?.as_u64())
            .collect();
        assert_eq!(seqs, vec![1, 2, 3], "three identical events are three distinct lines");
        let _ = std::fs::remove_dir_all(&root);
    }

    #[test]
    fn the_cap_archives_instead_of_cutting() {
        let root = temp_root("archive");
        let lines: Vec<String> = (0..LEDGER_HIGH_WATER)
            .map(|i| json!({"at": i, "seq": i + 1, "action": "parameter_set", "detail": {"n": i}}).to_string())
            .collect();
        std::fs::write(ledger_path(&root), lines.join("\n") + "\n").unwrap();
        record_in(&root, "after", json!({}));
        let live: Vec<Value> = std::fs::read_to_string(ledger_path(&root))
            .unwrap()
            .lines()
            .filter_map(|l| serde_json::from_str(l).ok())
            .collect();
        let note = live.iter().find(|v| v["action"] == "ledger_archived").expect("a line says lines were moved");
        let archive = root.join(note["detail"]["archive"].as_str().unwrap());
        let archived: Vec<Value> = std::fs::read_to_string(&archive)
            .expect("the archive exists")
            .lines()
            .filter_map(|l| serde_json::from_str(l).ok())
            .collect();
        assert_eq!(note["detail"]["lines"].as_u64(), Some(archived.len() as u64));
        assert_eq!(archived.len() + live.len(), LEDGER_HIGH_WATER + 2, "nothing was lost: every line is live or archived");
        assert_eq!(archived[0]["detail"]["n"], 0, "the OLDEST lines are the ones archived");
        assert!(live.len() <= LEDGER_MAX_LINES);
        assert_eq!(live.last().unwrap()["action"], "after");
        let _ = std::fs::remove_dir_all(&root);
    }

    #[test]
    fn percentiles_are_observed_samples_not_interpolations() {
        let v = vec![1.0, 2.0, 3.0, 4.0, 10.0];
        assert_eq!(percentile(&v, 0.5), 3.0);
        assert_eq!(percentile(&v, 0.9), 10.0);
        assert_eq!(percentile(&[], 0.5), 0.0);
        // A single sample is its own p50 AND p90 — never an extrapolation.
        assert_eq!(percentile(&[7.5], 0.9), 7.5);
    }

    #[test]
    fn the_ledger_round_trips_and_stays_bounded() {
        let dir = std::env::temp_dir().join(format!("swx-ledger-{}", std::process::id()));
        let _ = std::fs::remove_dir_all(&dir);
        std::fs::create_dir_all(&dir).unwrap();

        record_in(&dir, "document_created", json!({"title": "Part1"}));
        record_in(&dir, "document_closed", json!({"title": "Part1", "saved": false}));
        let rows = read_in(&dir, 10);
        assert_eq!(rows.len(), 2);
        assert_eq!(rows[0]["action"], "document_created");
        assert_eq!(rows[1]["detail"]["saved"], false);
        assert!(rows[0]["at"].as_u64().unwrap() > 0);
        // newest LAST, and `limit` cuts from the OLD end
        assert_eq!(read_in(&dir, 1)[0]["action"], "document_closed");

        record_time_in(&dir, "swx_export", 1.0);
        record_time_in(&dir, "swx_export", 3.0);
        let s = stages_in(&dir);
        assert_eq!(s["swx_export"]["count"], 2);
        assert_eq!(s["swx_export"]["p90"], 3.0);
        assert_eq!(s["swx_export"]["minSec"], 1.0);

        // A negative or non-finite sample is refused, not stored as garbage.
        record_time_in(&dir, "swx_export", -5.0);
        record_time_in(&dir, "swx_export", f64::NAN);
        assert_eq!(stages_in(&dir)["swx_export"]["count"], 2);

        let _ = std::fs::remove_dir_all(&dir);
    }
}