facett_core/

trace.rs

//! Structured event trace — the **machine-readable** sibling of
//! [`harness::trail`](crate::harness::trail).
//!
//! `harness::trail` is a human free-form line (`facett ACTION … [RENDER] tiny
//! size=800x600 → 412 verts`). 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 test matrix) can read back
//! **exactly the data a facet rendered** — its `state_json`, the vertex proof,
//! the inputs it was handed — not a summary and not a screenshot.
//!
//! Mirrors nornir viz's `$NORNIR_VIZ_TRACE`: one JSON object per line (JSONL) at
//! `$FACETT_TRACE` (default `/tmp/facett_trace.jsonl`), truncated on launch:
//!
//! ```json
//! {"seq":3,"ts_ms":1733961825678,"stamp":"01:23:45.678",
//!  "span":"facet.render","phase":"in","data":{"title":"graph","size":[800.0,600.0]}}
//! {"seq":4,...,"span":"facet.render","phase":"out","data":{"title":"graph","vertices":412,"drew":true,"state":{…}}}
//! ```
//!
//! ## The contract
//! - **span** — the operation name (`facet.render`, and whatever a live facet
//!   emits for its own interactions).
//! - **phase** — `in` (params accepted), `out` (result produced), `end` (a unit
//!   of work finished), or `event` (a point-in-time fact). Pair an `in` with its
//!   later `out`/`end` of the same `span` by adjacency.
//! - **data** — the real, structured payload (a `serde_json::Value`, the same
//!   currency as [`Facet::state_json`](crate::Facet::state_json)), so the
//!   consumer parses fields rather than scraping a formatted string.
//!
//! Dependency-free, like the rest of `harness`: the stamp comes from
//! `SystemTime` (no chrono) and the payload is a `serde_json::Value` (no
//! serde-derive). Cheap: a `Mutex<File>` `writeln!` + a global atomic seq. Call
//! sites emit on edge-triggered events only, never per-frame.

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

/// Phase of an instrumented operation — lets a consumer correlate the inputs a
/// call accepted with the data it produced.
#[derive(Clone, Copy, Debug, PartialEq, Eq)]
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.
    Event,
}

impl Phase {
    fn as_str(self) -> &'static str {
        match self {
            Phase::In => "in",
            Phase::Out => "out",
            Phase::End => "end",
            Phase::Event => "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 harness sinks).
        let file = std::fs::File::create(&path).ok();
        let s = Sink { inner: Mutex::new(Inner { seq: 0, file }), path };
        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 (a `serde_json::Value` — typically a facet's
/// `state_json` or a small `json!({…})` of its inputs). Writes a single JSONL
/// line to `$FACETT_TRACE`; never panics (best-effort I/O).
pub fn emit(span: &str, phase: Phase, data: &serde_json::Value) {
    emit_into(sink(), span, phase, data);
}

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

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

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

/// Convenience: a point-in-time fact (a selection, a mode switch).
pub fn emit_event(span: &str, data: &serde_json::Value) {
    emit(span, Phase::Event, data);
}

fn emit_into(s: &Sink, span: &str, phase: Phase, data: &serde_json::Value) {
    let now = std::time::SystemTime::now()
        .duration_since(std::time::UNIX_EPOCH)
        .unwrap_or_default();
    let ts_ms = now.as_millis() as u64;
    let stamp = stamp_from_ms(ts_ms);
    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.as_str(),
        "data": data,
    });
    if let Some(f) = g.file.as_mut() {
        let _ = writeln!(f, "{line}");
        let _ = f.flush();
    }
}

/// `HH:MM:SS.mmm` (UTC, no tz dep) — only the time-of-day matters to follow a
/// trace, so this is intentionally dependency-free rather than chrono-accurate
/// (matches `harness::now_stamp`).
fn stamp_from_ms(total_ms: u64) -> String {
    let ms = total_ms % 1000;
    let secs = total_ms / 1000;
    let h = (secs / 3600) % 24;
    let m = (secs / 60) % 60;
    let s = secs % 60;
    format!("{h:02}:{m:02}:{s:02}.{ms:03}")
}

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

    #[test]
    fn writes_jsonl_lines_with_real_payload() {
        let path = "/tmp/facett_trace_test.jsonl";
        // edition 2024: env mutation is `unsafe` (single-threaded test, fine).
        unsafe { std::env::set_var("FACETT_TRACE", path) };
        emit_in("facet.render", &serde_json::json!({ "title": "graph", "size": [800.0, 600.0] }));
        emit_out(
            "facet.render",
            &serde_json::json!({ "title": "graph", "vertices": 412, "drew": true }),
        );
        let body = std::fs::read_to_string(path).unwrap();
        let lines: Vec<&str> = body.lines().collect();
        // session header + the two emits.
        assert!(lines.len() >= 3, "expected >=3 lines, got {}", lines.len());
        for l in &lines {
            let v: serde_json::Value = serde_json::from_str(l).unwrap();
            assert!(v.get("seq").is_some());
            assert!(v.get("span").is_some());
            assert!(v.get("phase").is_some());
            assert!(v.get("data").is_some());
        }
        // The render payload round-trips as real structured data, not a string.
        let last: serde_json::Value = serde_json::from_str(lines.last().unwrap()).unwrap();
        assert_eq!(last["span"], "facet.render");
        assert_eq!(last["phase"], "out");
        assert_eq!(last["data"]["vertices"], 412);
    }

    #[test]
    fn stamp_shape_is_hms_millis() {
        let s = stamp_from_ms(3_661_123); // 01:01:01.123
        assert_eq!(s, "01:01:01.123");
    }
}