OpenFUT/openfut-blaze-host/src/trace.rs

//! Diagnostics and the normalized structural trace.
//!
//! Two outputs with different jobs:
//!
//! * **The log** is for a human watching a live run. Free-form, timestamped.
//! * **The trace** is for `diff`. One line per frame, deterministic, with every
//!   volatile value masked so a Python session and a Rust session of the same
//!   conversation produce identical text.
//!
//! Masking is what makes the trace useful. A session key, a server timestamp
//! and an auth token differ on every run by design, so comparing raw bytes
//! across two live servers can only ever fail. Their *presence, tag, type and
//! length* are what must match, and that is what the trace records.
//!
//! Nothing here writes a credential: masked values are replaced before they
//! reach the line, not truncated after.

use std::fmt::Write as _;
use std::io::Write as _;
use std::sync::Mutex;
use std::time::{SystemTime, UNIX_EPOCH};

use openfut_adapter_fifa17::blaze::ids;
use openfut_protocol_blaze::fire2::{Frame, Header, MsgType};
use openfut_protocol_blaze::heat2::{self, Struct, Value};

/// Tags whose values legitimately differ between two runs of the same
/// conversation. Masked in the trace so it stays diffable.
///
/// Deliberately a denylist of *known-volatile* tags rather than an allowlist:
/// a new field appearing in a response should show up as a diff, not be hidden.
const VOLATILE_TAGS: &[&str] = &[
    "KEY",  // session key
    "AUTH", // auth token (also a credential-shaped value)
    "STIM", // server time
    "LLOG", "LAST", "LADT", "LATH", // login / auth timestamps
    "GDAY", "DTCR", // grant/create dates (stable today, timestamp-shaped)
    "SESS", // telemetry session echo (string form)
];

fn now_millis() -> u128 {
    SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .map(|d| d.as_millis())
        .unwrap_or(0)
}

pub fn log(msg: &str) {
    let ms = now_millis();
    eprintln!("[{}.{:03}] {msg}", ms / 1000, ms % 1000);
}

/// Describe a frame header the way the Python responder logs it, so the two
/// logs can be read side by side.
pub fn describe(header: &Header) -> String {
    let is_notify = header.msg_type == MsgType::Notification;
    format!(
        "{} msgType={} msgNum={} userIdx={} opts=0x{:02x} meta={}B payload={}B",
        ids::describe(header.component, header.command, is_notify),
        header.msg_type.name(),
        header.msg_num,
        header.user_index,
        header.options,
        header.metadata_len,
        header.payload_len
    )
}

/// A deterministic, volatile-masked rendering of one frame.
pub struct Tracer {
    sink: Option<Mutex<std::fs::File>>,
}

impl Tracer {
    pub fn new(path: Option<&str>) -> std::io::Result<Tracer> {
        Ok(Tracer {
            sink: match path {
                Some(p) => Some(Mutex::new(std::fs::File::create(p)?)),
                None => None,
            },
        })
    }

    pub fn disabled() -> Tracer {
        Tracer { sink: None }
    }

    pub fn enabled(&self) -> bool {
        self.sink.is_some()
    }

    pub fn write_line(&self, line: &str) {
        if let Some(sink) = &self.sink {
            if let Ok(mut f) = sink.lock() {
                let _ = writeln!(f, "{line}");
                let _ = f.flush();
            }
        }
    }

    pub fn frame(&self, conn: u64, direction: &str, index: &str, frame: &Frame) {
        if !self.enabled() {
            return;
        }
        self.write_line(&trace_line(conn, direction, index, frame));
    }
}

/// `conn-0001 TX 1.0 Authentication::login REPLY num=12 uidx=0 payload=201 tdf=<digest>`
pub fn trace_line(conn: u64, direction: &str, index: &str, frame: &Frame) -> String {
    let h = &frame.header;
    let is_notify = h.msg_type == MsgType::Notification;
    let body = if frame.payload.is_empty() {
        "(empty)".to_string()
    } else {
        match heat2::decode(&frame.payload) {
            Ok(s) => format!("{:016x}", structure_digest(&s)),
            Err(_) => "DECODE-FAILED".to_string(),
        }
    };
    format!(
        "conn-{conn:04} {direction} {index} {} {} num={} uidx={} payload={} tdf={}",
        ids::describe(h.component, h.command, is_notify),
        h.msg_type.name(),
        h.msg_num,
        h.user_index,
        frame.payload.len(),
        body
    )
}

/// A masked, human-readable dump of a decoded body. Used by the probe's
/// verbose mode when a digest mismatch needs explaining.
pub fn masked_dump(s: &Struct) -> String {
    let mut out = String::new();
    write_masked(s, 0, &mut out);
    out
}

fn write_masked(s: &Struct, depth: usize, out: &mut String) {
    // Sort so two implementations that differ only in member order still
    // produce identical text. (They should not — the encoder sorts — but the
    // trace must not be the thing that hides it if they do.)
    let mut fields: Vec<_> = s.iter().collect();
    fields.sort_by_key(|(t, _)| *t);

    for (tag, value) in fields {
        let pad = "  ".repeat(depth);
        let label = tag.to_label();
        let volatile = VOLATILE_TAGS.contains(&label.as_str());
        match value {
            Value::Struct(inner) => {
                let _ = writeln!(out, "{pad}{label} (struct)");
                write_masked(inner, depth + 1, out);
            }
            Value::List { elem, items } => {
                let _ = writeln!(out, "{pad}{label} (list[{}] x{})", elem.name(), items.len());
                for it in items {
                    if let Value::Struct(inner) = it {
                        write_masked(inner, depth + 1, out);
                    }
                }
            }
            Value::Map { key, val, entries } => {
                let _ = writeln!(
                    out,
                    "{pad}{label} (map[{}->{}] x{})",
                    key.name(),
                    val.name(),
                    entries.len()
                );
            }
            other => {
                let rendered = if volatile {
                    masked_scalar(other)
                } else {
                    render_scalar(other)
                };
                let _ = writeln!(
                    out,
                    "{pad}{label} ({}) = {rendered}",
                    other.type_id().name()
                );
            }
        }
    }
}

/// Replace the value but keep its shape, so a length or type change still diffs.
fn masked_scalar(v: &Value) -> String {
    match v {
        Value::String(s) => format!("<masked:str:{}>", s.len()),
        Value::Int(_) => "<masked:int>".to_string(),
        Value::Blob(b) => format!("<masked:blob:{}>", b.len()),
        other => format!("<masked:{}>", other.type_id().name()),
    }
}

fn render_scalar(v: &Value) -> String {
    match v {
        Value::Int(n) => n.to_string(),
        Value::String(s) => format!("{s:?}"),
        Value::Blob(b) => format!("<blob:{}>", b.len()),
        Value::VarList(items) => format!("{items:?}"),
        Value::Float(f) => format!("{f}"),
        Value::ObjType { component, ty } => format!("({component},{ty})"),
        Value::ObjId { component, ty, id } => format!("({component},{ty},{id})"),
        other => other.type_id().name().to_string(),
    }
}

/// FNV-1a over the masked dump: a stable structural fingerprint.
///
/// Hand-rolled because it is eight lines and pulling a hashing crate into a
/// diagnostics path would be the heavier choice. Not a security hash and never
/// used as one.
pub fn structure_digest(s: &Struct) -> u64 {
    let mut hash: u64 = 0xcbf2_9ce4_8422_2325;
    for byte in masked_dump(s).as_bytes() {
        hash ^= *byte as u64;
        hash = hash.wrapping_mul(0x1000_0000_01b3);
    }
    hash
}

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

    fn frame_with(body: Struct) -> Frame {
        Frame::new(0x0001, 0x000A, 12, MsgType::Reply, heat2::encode(&body))
    }

    #[test]
    fn volatile_values_are_masked_but_their_shape_survives() {
        let a = Struct::new()
            .with("KEY", Value::String("aaaaaaaa".into()))
            .with("UID", Value::Int(33068179));
        let b = Struct::new()
            .with("KEY", Value::String("bbbbbbbb".into()))
            .with("UID", Value::Int(33068179));
        // Different session keys of the same length: identical trace.
        assert_eq!(structure_digest(&a), structure_digest(&b));

        // A different length is a real change and must still diff.
        let c = Struct::new()
            .with("KEY", Value::String("short".into()))
            .with("UID", Value::Int(33068179));
        assert_ne!(structure_digest(&a), structure_digest(&c));
    }

    #[test]
    fn non_volatile_values_are_not_masked() {
        let a = Struct::new().with("UID", Value::Int(1));
        let b = Struct::new().with("UID", Value::Int(2));
        assert_ne!(structure_digest(&a), structure_digest(&b));
    }

    #[test]
    fn a_new_field_shows_up_as_a_difference() {
        // The denylist must not hide additions.
        let a = Struct::new().with("UID", Value::Int(1));
        let b = Struct::new()
            .with("UID", Value::Int(1))
            .with("NEWF", Value::Int(0));
        assert_ne!(structure_digest(&a), structure_digest(&b));
    }

    #[test]
    fn trace_line_is_stable_across_sessions() {
        let a = frame_with(Struct::new().with("KEY", Value::String("k1-aaaaaa".into())));
        let b = frame_with(Struct::new().with("KEY", Value::String("k2-bbbbbb".into())));
        assert_eq!(
            trace_line(1, "TX", "1.0", &a),
            trace_line(1, "TX", "1.0", &b)
        );
        assert!(trace_line(1, "TX", "1.0", &a).contains("Authentication::login"));
    }

    #[test]
    fn no_masked_value_leaks_into_the_line() {
        let secret = "SUPER-SECRET-SESSION-KEY";
        let f = frame_with(Struct::new().with("KEY", Value::String(secret.into())));
        let line = trace_line(1, "TX", "1.0", &f);
        assert!(!line.contains(secret));
        assert!(!masked_dump(&heat2::decode(&f.payload).unwrap()).contains(secret));
    }

    #[test]
    fn an_undecodable_body_is_reported_not_hidden() {
        let f = Frame::new(9, 7, 1, MsgType::Reply, vec![0xFF; 8]);
        assert!(trace_line(1, "TX", "1.0", &f).contains("DECODE-FAILED"));
    }

    #[test]
    fn empty_payloads_are_distinguishable_from_failures() {
        let f = Frame::new(9, 7, 1, MsgType::Reply, vec![]);
        assert!(trace_line(1, "TX", "1.0", &f).contains("(empty)"));
    }
}