facett_trace/

lib.rs

//! **facett-trace** — a structured event trace: the **machine-readable** sibling
//! of a free-form action log.
//!
//! An action log is a human free-form trail (`tab=Bench`, `reload … → 3
//! release(s)`). This is its typed counterpart: every instrumented operation
//! emits its INPUT parameters and its OUTPUT *data* as real JSON payloads, so an
//! external agent (or a headless test matrix) can read back **exactly the data
//! the UI rendered** — the bubble table, the bench rows, the server response —
//! not a summary and not a screenshot.
//!
//! Adopted verbatim from nornir's `src/viz/trace.rs`; it was already zero-coupling
//! (generic over `serde::Serialize`). The only change is the output-path env var:
//! `$FACETT_TRACE` (default `/tmp/facett_trace.jsonl`), truncated on launch.
//!
//! One JSON object per line (JSONL):
//!
//! ```json
//! {"seq":7,"ts_ms":1733961825678,"stamp":"01:23:45.678",
//!  "span":"knowledge.scan","phase":"in","data":{"workspace_root":"…","repos":["njord"]}}
//! {"seq":8,...,"span":"knowledge.scan.repo","phase":"end","data":{"repo":"njord","symbols":642,…}}
//! {"seq":9,...,"span":"knowledge.scan","phase":"out","data":{"repos_ok":1,"repos_total":1,"ms":83}}
//! {"seq":10,...,"span":"knowledge.render","phase":"end","data":{"bubbles":[{"repo":"njord",…}]}}
//! ```
//!
//! ## The contract
//! - **span** — the operation name (`knowledge.scan`, `ui.tab`, `server.reload`).
//! - **phase** — `in` (params accepted), `out` (result produced), `end` (a unit
//!   of work finished), or `event` (a point-in-time fact, e.g. a tab switch).
//!   Pair an `in` with its later `out`/`end` of the same `span` by adjacency —
//!   the UI is single-threaded, so within one operation they don't interleave.
//! - **data** — the real, structured payload. Emit typed structs (serialized via
//!   serde), never a pre-formatted string, so the consumer parses fields.
//!
//! Cheap by design: a `Mutex<File>` `writeln!` + a global atomic seq. Call sites
//! only emit on edge-triggered events (a scan, a click, an RPC), never per-frame.

use std::io::Write;
use std::sync::{Mutex, OnceLock};

use serde::Serialize;

/// Phase of an instrumented operation. Lets a consumer correlate the inputs a
/// call accepted with the data it produced.
#[derive(Clone, Copy, Debug, Serialize)]
#[serde(rename_all = "lowercase")]
pub enum Phase {
    /// Inputs accepted — the parameters that drive the operation.
    In,
    /// Output produced — the result data the operation returns.
    Out,
    /// A unit of work finished (use when there's no separate in/out split).
    End,
    /// A point-in-time fact with no duration (a tab switch, a selection).
    Event,
}

struct Sink {
    inner: Mutex<Inner>,
    path: String,
}

struct Inner {
    seq: u64,
    file: Option<std::fs::File>,
}

static SINK: OnceLock<Sink> = OnceLock::new();

fn sink() -> &'static Sink {
    SINK.get_or_init(|| {
        let path = std::env::var("FACETT_TRACE")
            .unwrap_or_else(|_| "/tmp/facett_trace.jsonl".to_string());
        // Truncate on launch so each session's trace starts clean (matches the
        // single-snapshot semantics of the rest of the facett harness sinks).
        let file = std::fs::File::create(&path).ok();
        let s = Sink { inner: Mutex::new(Inner { seq: 0, file }), path };
        // A session header so the consumer knows the trace (re)started and where.
        emit_into(&s, "trace.session", Phase::Event, &serde_json::json!({ "file": s.path }));
        s
    })
}

/// Emit one structured event: `span` is the operation, `phase` its stage, and
/// `data` the real payload (any `Serialize` — a typed struct, ideally). Writes a
/// single JSONL line to `$FACETT_TRACE`; never panics (best-effort I/O).
pub fn emit<T: Serialize>(span: &str, phase: Phase, data: &T) {
    emit_into(sink(), span, phase, data);
}

/// Convenience: the inputs a call accepted.
pub fn emit_in<T: Serialize>(span: &str, data: &T) {
    emit(span, Phase::In, data);
}

/// Convenience: the data a call produced.
pub fn emit_out<T: Serialize>(span: &str, data: &T) {
    emit(span, Phase::Out, data);
}

/// Convenience: a unit of work finished (no separate in/out).
pub fn emit_end<T: Serialize>(span: &str, data: &T) {
    emit(span, Phase::End, data);
}

/// Convenience: a point-in-time fact (tab switch, selection).
pub fn emit_event<T: Serialize>(span: &str, data: &T) {
    emit(span, Phase::Event, data);
}

fn emit_into<T: Serialize>(s: &Sink, span: &str, phase: Phase, data: &T) {
    let now = chrono::Local::now();
    let stamp = now.format("%H:%M:%S%.3f").to_string();
    let ts_ms = now.timestamp_millis();
    let Ok(mut g) = s.inner.lock() else { return };
    g.seq += 1;
    let line = serde_json::json!({
        "seq": g.seq,
        "ts_ms": ts_ms,
        "stamp": stamp,
        "span": span,
        "phase": phase,
        // Serialize the payload through serde_json::to_value so a failure to
        // serialize degrades to null instead of dropping the whole event.
        "data": serde_json::to_value(data).unwrap_or(serde_json::Value::Null),
    });
    if let Some(f) = g.file.as_mut() {
        let _ = writeln!(f, "{line}");
        let _ = f.flush();
    }
}

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

    #[derive(Serialize)]
    struct Payload {
        repo: String,
        symbols: usize,
    }

    /// inject-assert: emit a handful of events to a `$FACETT_TRACE` override path,
    /// read the JSONL back, and assert the seq / ts_ms / stamp / span / phase /
    /// data contract fields — proving the typed payload round-trips as REAL
    /// structured data (not a string), and that the env-var path override is honoured.
    ///
    /// Note: the sink is a process-global `OnceLock`, so the `$FACETT_TRACE` path
    /// it picks up is whichever was set before its FIRST `emit`. This test is the
    /// only one in the crate that emits, so it owns that first init.
    #[test]
    fn writes_jsonl_lines_with_real_payload_to_env_path() {
        let dir = tempfile::tempdir().unwrap();
        let path = dir.path().join("facett_trace_test.jsonl");
        // edition 2024: env mutation is `unsafe` (single-threaded test, fine).
        unsafe { std::env::set_var("FACETT_TRACE", &path) };

        emit_in("knowledge.scan", &serde_json::json!({ "repos": ["njord"] }));
        emit_end("knowledge.scan.repo", &Payload { repo: "njord".into(), symbols: 642 });
        emit_event("ui.tab", &serde_json::json!({ "tab": "Bench" }));

        let body = std::fs::read_to_string(&path).expect("the env-var override path was written");
        let lines: Vec<&str> = body.lines().collect();
        // session header + the three emits.
        assert!(lines.len() >= 4, "expected >=4 lines, got {}", lines.len());

        // Every line is valid JSON carrying the full contract.
        let mut last_seq = 0u64;
        for l in &lines {
            let v: serde_json::Value = serde_json::from_str(l).unwrap();
            assert!(v.get("seq").is_some(), "seq present");
            assert!(v.get("ts_ms").and_then(|t| t.as_u64()).map(|t| t > 0).unwrap_or(false), "ts_ms is a real epoch-ms");
            assert!(v.get("stamp").and_then(|s| s.as_str()).map(|s| s.len() >= 8).unwrap_or(false), "stamp is HH:MM:SS.mmm");
            assert!(v.get("span").is_some(), "span present");
            assert!(v.get("phase").is_some(), "phase present");
            assert!(v.get("data").is_some(), "data present");
            // seq is strictly monotonic.
            let seq = v["seq"].as_u64().unwrap();
            assert!(seq > last_seq, "seq strictly increases: {seq} after {last_seq}");
            last_seq = seq;
        }

        // The first emitted line is the session header pointing at our path.
        let header: serde_json::Value = serde_json::from_str(lines[0]).unwrap();
        assert_eq!(header["span"], "trace.session");
        assert_eq!(header["phase"], "event");
        assert_eq!(header["data"]["file"], path.to_str().unwrap());

        // The repo payload round-trips as real structured data, not a string —
        // and its phase serialises lowercase per the contract.
        let repo_line = lines.iter().map(|l| serde_json::from_str::<serde_json::Value>(l).unwrap())
            .find(|v| v["span"] == "knowledge.scan.repo").unwrap();
        assert_eq!(repo_line["phase"], "end");
        assert_eq!(repo_line["data"]["symbols"], 642);
        assert_eq!(repo_line["data"]["repo"], "njord");

        // The `in` and `event` phases are present and lowercase too.
        let scan = lines.iter().map(|l| serde_json::from_str::<serde_json::Value>(l).unwrap())
            .find(|v| v["span"] == "knowledge.scan").unwrap();
        assert_eq!(scan["phase"], "in");
        assert_eq!(scan["data"]["repos"], serde_json::json!(["njord"]));
        let tab = lines.iter().map(|l| serde_json::from_str::<serde_json::Value>(l).unwrap())
            .find(|v| v["span"] == "ui.tab").unwrap();
        assert_eq!(tab["phase"], "event");
        assert_eq!(tab["data"]["tab"], "Bench");
    }
}