//! 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>, } impl Tracer { pub fn new(path: Option<&str>) -> std::io::Result { 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=` 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!("", s.len()), Value::Int(_) => "".to_string(), Value::Blob(b) => format!("", b.len()), other => format!("", 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!("", 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)")); } }