ai-app/app-rust/tests/input_log_roundtrip.rs

//! Layer 1 of docs/RUST.md's "Three test layers", for the diagnostics
//! themselves rather than a widget: `iris::diagnostics::set_trace` gates
//! `iris::input`/`iris::frame` (Iris's 2026-09-07 request, "add another
//! button to copy input event info ... instrument a lot of the code with
//! timings"), and `docs/REVIEW-2026-09-07.md`'s D1 found that the switch
//! existed but four older per-frame `debug!` lines were not wired to it,
//! filling the app's 2000-line log ring with frame spam before `Copy
//! report` had a chance to include anything else. This is what a fix to
//! that has to prove, both directions:
//!
//! 1. **Off** (the default): replaying a real gesture through a real
//!    screen leaves the ring holding nothing below `info` -- so the
//!    lines D1 named, and everything this pass gated the same way, really
//!    are silent by default rather than merely "usually quiet."
//! 2. **On**: the same replay produces `iris::input` lines that
//!    `report_to_touch.py` turns back into the exact `TouchScript` that
//!    was replayed, and `iris::frame` lines with real, non-zero
//!    durations dated on the harness's own clock.
//!
//! **Single capturing logger, single test function** (this file's only
//! `#[test]`): `log::set_logger` can succeed exactly once per process, and
//! AGENTS.md's "tracing caches callsite interest process-wide" lesson is
//! the general form of why every exercise of a logging path has to share
//! one subscriber -- so if a second test here ever needs the ring's
//! contents, it must extend this one rather than install its own.

use std::process::{Command, Stdio};
use std::sync::{Mutex, OnceLock};

use ai_app::ui::fixture::{PHONE_FRAME_MS, PHONE_SCALE, phone_size};
use iris::harness::{Harness, TouchScript};

/// Records every line's level and formatted message -- enough to answer
/// both "is the ring quiet" (no line at `Debug` or below) and "what did
/// tracing actually write" (the `iris::input` lines, read back by
/// `report_to_touch.py`).
struct CaptureLogger {
    lines: Mutex<Vec<(log::Level, String)>>,
}

static LOGGER: OnceLock<CaptureLogger> = OnceLock::new();

impl log::Log for CaptureLogger {
    fn enabled(&self, _metadata: &log::Metadata) -> bool {
        true
    }
    fn log(&self, record: &log::Record) {
        self.lines
            .lock()
            .unwrap()
            .push((record.level(), record.args().to_string()));
    }
    fn flush(&self) {}
}

/// Installs the capture logger at `Debug` -- the same level
/// `iris/android-app/src/lib.rs`'s `JNI_OnLoad` installs at, which is
/// exactly why `iris::diagnostics::trace_enabled` has to be the gate
/// (its own module doc) rather than the level.
fn logger() -> &'static CaptureLogger {
    let logger = LOGGER.get_or_init(|| CaptureLogger {
        lines: Mutex::new(Vec::new()),
    });
    // Ignore "already set": a previous call in this same test binary
    // already won, and it is the same logger either way.
    let _ = log::set_logger(logger);
    log::set_max_level(log::LevelFilter::Debug);
    logger
}

fn drain(logger: &CaptureLogger) -> Vec<(log::Level, String)> {
    std::mem::take(&mut *logger.lines.lock().unwrap())
}

fn opened() -> (Harness, ai_app::ui::TranscriptScreen) {
    let mut h = Harness::new(phone_size(), PHONE_SCALE);
    let opened = ai_app::ui::fixture::open(&mut h.rsc, &mut h.state).expect("the fixture folds");
    h.frame(0);
    h.frame(PHONE_FRAME_MS);
    (h, opened.screen)
}

#[test]
fn tracing_is_silent_off_and_round_trips_the_flick_on() {
    let logger = logger();

    // --- (1) off: a real flick through a real screen leaves the ring
    // with nothing at `Debug` or below.
    iris::diagnostics::set_trace(false);
    drain(logger); // whatever `opened()` itself logged while building
    let (mut h, screen) = opened();
    drain(logger); // and whatever opening logged
    let flick = TouchScript::parse(include_str!("../touch/flick-120hz.touch"))
        .unwrap_or_else(|e| panic!("flick-120hz.touch: {e}"));
    h.replay(&flick);
    let _ = (screen.list)(&mut h.rsc); // touch the screen the same way a real caller would
    let quiet = drain(logger);
    let debug_lines: Vec<_> = quiet
        .iter()
        .filter(|(level, _)| *level == log::Level::Debug)
        .collect();
    assert!(
        debug_lines.is_empty(),
        "tracing is off, but the ring would still have held these `debug!` lines: {debug_lines:#?}"
    );

    // --- (2) on: the same replay, from a fresh screen so the anchor and
    // sequence numbers match `flick-120hz.touch` exactly again.
    iris::diagnostics::set_trace(true);
    let (mut h, screen) = opened();
    drain(logger);
    h.replay(&flick);
    let _ = (screen.list)(&mut h.rsc);
    let traced = drain(logger);
    iris::diagnostics::set_trace(false); // leave it off for any test after this one

    let input_lines: Vec<&str> = traced
        .iter()
        .filter(|(_, msg)| msg.contains("iris input: action="))
        .map(|(_, msg)| msg.as_str())
        .collect();
    assert_eq!(
        input_lines.len(),
        flick.samples.len(),
        "expected one `iris::input` line per replayed sample, got:\n{input_lines:#?}"
    );
    let frame_lines: Vec<&str> = traced
        .iter()
        .filter(|(_, msg)| msg.starts_with("iris frame:"))
        .map(|(_, msg)| msg.as_str())
        .collect();
    assert!(
        !frame_lines.is_empty(),
        "expected at least one `iris::frame` line once tracing was on"
    );
    for line in &frame_lines {
        // `layout=` and `draw=` are `{:?}`-formatted `Duration`s, so a real
        // one reads like `12.34µs`/`1.2ms`, never the bare `0ns` a
        // no-op frame would print.
        assert!(
            !line.contains("layout=0ns"),
            "a frame that redrew should not report zero layout time: {line}"
        );
    }

    // --- the round trip: pipe every `iris::input` line through
    // `report_to_touch.py` and parse the result back into a `TouchScript`,
    // which must equal the one that was replayed. `report_to_touch.py`
    // is prefix-agnostic (it `search`es for the marker), so handing it
    // the bare message is the same as handing it a real ring line.
    let report = input_lines.join("\n");
    let script_path = concat!(
        env!("CARGO_MANIFEST_DIR"),
        "/../iris/benches/report_to_touch.py"
    );
    let mut child = Command::new("python3")
        .arg(script_path)
        .stdin(Stdio::piped())
        .stdout(Stdio::piped())
        .stderr(Stdio::piped())
        .spawn()
        .expect("python3 must be on PATH to run report_to_touch.py");
    {
        use std::io::Write;
        child
            .stdin
            .take()
            .unwrap()
            .write_all(report.as_bytes())
            .unwrap();
    }
    let output = child.wait_with_output().expect("report_to_touch.py exited");
    assert!(
        output.status.success(),
        "report_to_touch.py failed: {}",
        String::from_utf8_lossy(&output.stderr)
    );
    let touch_text = String::from_utf8(output.stdout).expect("report_to_touch.py wrote UTF-8");
    let round_tripped =
        TouchScript::parse(&touch_text).unwrap_or_else(|e| panic!("round-tripped script: {e}"));

    assert_eq!(
        round_tripped.samples.len(),
        flick.samples.len(),
        "round trip produced a different number of samples:\n{touch_text}"
    );
    for (original, back) in flick.samples.iter().zip(round_tripped.samples.iter()) {
        assert_eq!(original.t_ms, back.t_ms);
        assert_eq!(original.action, back.action);
        assert_eq!(original.pos, back.pos);
    }
}