facett-core/src/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() {
// Drive a *private* sink to a unique temp file instead of the process-global
// `sink()` + `$FACETT_TRACE`. The global `OnceLock` is initialised by the
// first trace anywhere in the test binary (e.g. `harness::trail`), so the old
// env-var path was racy under parallel tests — the sink could already be
// bound to the default file before this test set the env var, and the read
// would `NotFound`. `emit_into` is the exact code path the public API drives,
// so this still exercises the real JSONL writer — now deterministically.
let path = std::env::temp_dir().join(format!("facett_trace_test_{}.jsonl", std::process::id()));
let file = std::fs::File::create(&path).unwrap();
let s = Sink {
inner: std::sync::Mutex::new(Inner { seq: 0, file: Some(file) }),
path: path.display().to_string(),
};
emit_into(&s, "trace.session", Phase::Event, &serde_json::json!({ "file": s.path }));
emit_into(&s, "facet.render", Phase::In, &serde_json::json!({ "title": "graph", "size": [800.0, 600.0] }));
emit_into(
&s,
"facet.render",
Phase::Out,
&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);
let _ = std::fs::remove_file(&path);
}
#[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");
}
}