ai-app/client-core/src/log_ring.rs

//! The app's own recent log, held in memory so it can be read back
//! without `logcat`.
//!
//! **Why this exists**: Iris tests iris builds on a GrapheneOS phone with
//! no `adb`, and Android forbids one app reading another's logcat, so
//! nothing outside the process can recover what it wrote. The only way a
//! line reaches her is for the app to carry its own copy. This is that
//! copy: a bounded ring every `log::info!` in the process lands in, on top
//! of whichever platform logger was already installed (`android_logger`,
//! `env_logger`) rather than instead of it -- see [`RingLogger`].
//!
//! Two consumers, both reading the same ring rather than each keeping
//! their own: the bench app's `Copy report`/`Diagnostics` (which reads
//! [`LogRing::to_text`] and [`LogRing::summary`]) and whatever hands the
//! log out of the process -- on Android, the `DevLogProvider` Dev Updater
//! queries, which reads [`LogRing::since`] and [`LogRing::newest_seq`].
//! That is why reading does not consume: a line already handed over must
//! still be in the report, and a report taken twice must say the same
//! thing.

use std::collections::VecDeque;
use std::sync::{Arc, Mutex, OnceLock};
use std::time::{SystemTime, UNIX_EPOCH};

/// How many lines a default ring holds, and how many bytes of message.
///
/// Both bounds apply -- whichever bites first -- because the two failure
/// modes are different: a flood of short lines exhausts the count, and one
/// pathological line (a stack trace, a pretty-printed JSON body) exhausts
/// the bytes. A ring bounded only by lines can hold megabytes; one bounded
/// only by bytes can be emptied by a single line.
pub const DEFAULT_MAX_LINES: usize = 2000;
pub const DEFAULT_MAX_BYTES: usize = 256 * 1024;

/// One recorded line. `seq` is assigned by the ring and only ever
/// increases, so a reader that remembers where it got to can ask for what
/// came after -- and a gap in the sequence is exactly the lines the bound
/// dropped.
#[derive(Debug, Clone, PartialEq, Eq)]
pub struct LogLine {
    pub seq: u64,
    /// Milliseconds since the unix epoch, from the app's own clock. The
    /// app's rather than the receiver's: a line is timestamped when it
    /// happened, and an upload can be minutes later or never.
    pub at_ms: u64,
    pub level: log::Level,
    pub target: String,
    pub message: String,
}

impl LogLine {
    /// Roughly what the line costs the ring. The two `String`s dominate;
    /// the fixed fields are counted as a flat overhead so a ring of empty
    /// messages still has a bound.
    fn weight(&self) -> usize {
        self.target.len() + self.message.len() + 32
    }

    /// `12:34:56.789 INFO  iris::android: the message`, the shape a
    /// person skims. Time of day only -- the date is in the report's own
    /// header, and a ring never spans one.
    pub fn format(&self) -> String {
        format!(
            "{} {:<5} {}: {}",
            clock_time(self.at_ms),
            self.level,
            self.target,
            self.message
        )
    }
}

/// `HH:MM:SS.mmm` in UTC from a unix millisecond count, without a date
/// library: the only field this needs is the time of day, and dividing out
/// the day is the whole calculation. Deliberately not local time -- the
/// phone's offset is not knowable here, and a report that says UTC is
/// comparable with the server's log, which is what it gets read against.
fn clock_time(at_ms: u64) -> String {
    let ms = at_ms % 1000;
    let secs_of_day = (at_ms / 1000) % 86_400;
    format!(
        "{:02}:{:02}:{:02}.{:03}",
        secs_of_day / 3600,
        (secs_of_day % 3600) / 60,
        secs_of_day % 60,
        ms
    )
}

/// Now, in unix milliseconds. Saturating rather than panicking on a clock
/// before the epoch: a wrong timestamp in a diagnostic is not worth taking
/// the app down for.
pub fn now_ms() -> u64 {
    SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .map(|d| d.as_millis() as u64)
        .unwrap_or(0)
}

#[derive(Debug)]
struct Inner {
    lines: VecDeque<LogLine>,
    bytes: usize,
    max_lines: usize,
    max_bytes: usize,
    next_seq: u64,
    /// How many lines the bounds have discarded since the ring was made.
    /// Reported rather than inferred, so "the log starts here" and "the
    /// log was cut off here" are distinguishable -- the unknown state the
    /// UI rules ask for.
    dropped: u64,
}

/// A bounded, shareable ring of recent log lines. Cloning shares the ring;
/// there is one per process and every holder sees the same lines.
#[derive(Debug, Clone)]
pub struct LogRing(Arc<Mutex<Inner>>);

impl LogRing {
    pub fn new(max_lines: usize, max_bytes: usize) -> Self {
        assert!(
            max_lines > 0 && max_bytes > 0,
            "a ring with no room holds nothing"
        );
        Self(Arc::new(Mutex::new(Inner {
            lines: VecDeque::new(),
            bytes: 0,
            max_lines,
            max_bytes,
            next_seq: 0,
            dropped: 0,
        })))
    }

    /// The bounds this project ships with: [`DEFAULT_MAX_LINES`] and
    /// [`DEFAULT_MAX_BYTES`].
    pub fn with_defaults() -> Self {
        Self::new(DEFAULT_MAX_LINES, DEFAULT_MAX_BYTES)
    }

    /// A poisoned lock is a bug in a panicking logger, not a reason to
    /// take the app down a second time -- the ring is a diagnostic, and
    /// losing it must not be worse than the fault it was recording.
    fn with<R>(&self, f: impl FnOnce(&mut Inner) -> R) -> R {
        let mut guard = match self.0.lock() {
            Ok(guard) => guard,
            Err(poisoned) => poisoned.into_inner(),
        };
        f(&mut guard)
    }

    /// Records a line, evicting the oldest until both bounds hold again.
    pub fn push(&self, level: log::Level, target: &str, message: String) {
        self.with(|inner| {
            let line = LogLine {
                seq: inner.next_seq,
                at_ms: now_ms(),
                level,
                target: target.to_string(),
                message,
            };
            inner.next_seq += 1;
            inner.bytes += line.weight();
            inner.lines.push_back(line);
            // `!is_empty()` rather than `len() > 1`: one line larger than
            // the whole byte bound is kept, because dropping it would
            // leave the ring silently empty while lines were arriving.
            while inner.lines.len() > inner.max_lines
                || (inner.bytes > inner.max_bytes && inner.lines.len() > 1)
            {
                if let Some(evicted) = inner.lines.pop_front() {
                    inner.bytes -= evicted.weight();
                    inner.dropped += 1;
                }
            }
        })
    }

    /// Every line held, oldest first.
    pub fn snapshot(&self) -> Vec<LogLine> {
        self.with(|inner| inner.lines.iter().cloned().collect())
    }

    /// The lines with a sequence number at or after `seq`, oldest first,
    /// and the sequence to ask from next time. Does not consume: see this
    /// module's doc for why.
    pub fn since(&self, seq: u64) -> (Vec<LogLine>, u64) {
        self.with(|inner| {
            let lines: Vec<LogLine> = inner
                .lines
                .iter()
                .filter(|line| line.seq >= seq)
                .cloned()
                .collect();
            let next = lines.last().map(|line| line.seq + 1).unwrap_or(seq);
            (lines, next)
        })
    }

    pub fn len(&self) -> usize {
        self.with(|inner| inner.lines.len())
    }

    pub fn is_empty(&self) -> bool {
        self.len() == 0
    }

    pub fn dropped(&self) -> u64 {
        self.with(|inner| inner.dropped)
    }

    /// The sequence number of the newest line held, or `None` for a ring
    /// nothing has been written to.
    ///
    /// What a reader needs to notice that this process **restarted**: the
    /// ring is in memory, so a new process starts again at zero, and a
    /// reader holding a cursor from the previous one would otherwise ask
    /// for lines after a number nothing will reach for hours and see
    /// nothing at all -- silently, which is worse than seeing the log
    /// begin again. Answering `None` rather than 0 for an empty ring is
    /// the same distinction [`Self::summary`] draws: "nothing has been
    /// logged" is not a sequence number.
    pub fn newest_seq(&self) -> Option<u64> {
        self.with(|inner| inner.lines.back().map(|line| line.seq))
    }

    /// When the newest line was written, in unix milliseconds, or `None`
    /// for a ring nothing has been written to.
    pub fn last_at_ms(&self) -> Option<u64> {
        self.with(|inner| inner.lines.back().map(|line| line.at_ms))
    }

    /// Every line held, formatted one per line -- what `Copy report`
    /// appends.
    pub fn to_text(&self) -> String {
        self.snapshot()
            .iter()
            .map(LogLine::format)
            .collect::<Vec<_>>()
            .join("\n")
    }

    /// One line for a diagnostics pane: how much is held, how much was
    /// dropped, and when the last line arrived. "no lines yet" is its own
    /// wording rather than a count of zero with a made-up time, because
    /// "nothing has been logged" and "logging is not running" would
    /// otherwise look the same.
    pub fn summary(&self) -> String {
        let (len, dropped, last) = self.with(|inner| {
            (
                inner.lines.len(),
                inner.dropped,
                inner.lines.back().map(|line| line.at_ms),
            )
        });
        match last {
            None => "app log: no lines yet".to_string(),
            Some(at) => {
                let dropped = if dropped > 0 {
                    format!(", {dropped} dropped")
                } else {
                    String::new()
                };
                format!(
                    "app log: {len} lines held{dropped}, last {}",
                    clock_time(at)
                )
            }
        }
    }
}

/// A `log` backend that records into a [`LogRing`] **and** forwards to the
/// logger the platform already installs, so nothing that reads the
/// platform's log (`logcat`, a terminal) changes.
///
/// The inner logger is passed in rather than chosen here: `client-core`
/// has no business depending on `android_logger` or `env_logger`, and
/// which one is right is exactly what differs between the two platforms
/// (the sharing rule in AGENTS.md).
pub struct RingLogger {
    ring: LogRing,
    inner: Box<dyn log::Log>,
}

impl RingLogger {
    pub fn new(ring: LogRing, inner: Box<dyn log::Log>) -> Self {
        Self { ring, inner }
    }
}

impl log::Log for RingLogger {
    /// True for anything `log`'s own max level lets through: the ring
    /// wants everything, even where the platform logger would filter it
    /// out. The filter is applied per-logger in [`Self::log`] instead.
    fn enabled(&self, _metadata: &log::Metadata) -> bool {
        true
    }

    fn log(&self, record: &log::Record) {
        self.ring
            .push(record.level(), record.target(), record.args().to_string());
        if self.inner.enabled(record.metadata()) {
            self.inner.log(record);
        }
    }

    fn flush(&self) {
        self.inner.flush();
    }
}

/// Installs a [`RingLogger`] as the process logger and answers the ring it
/// records into.
///
/// Fails only if a logger is already installed, which is a programmer
/// error (two initialisation paths) rather than a recoverable condition --
/// the caller is named in the error so it is findable.
pub fn install(
    ring: LogRing,
    inner: Box<dyn log::Log>,
    max_level: log::LevelFilter,
) -> Result<(), log::SetLoggerError> {
    log::set_boxed_logger(Box::new(RingLogger::new(ring, inner)))?;
    log::set_max_level(max_level);
    Ok(())
}

/// The one ring this process records into.
///
/// **A deliberate process-global, where this project's rules otherwise say
/// pass context explicitly.** What is being modelled is already one: `log`
/// has exactly one backend per process, set once, and every `log::info!`
/// anywhere in the binary goes to it. A ring handed around as a parameter
/// would be a *second* answer to "which lines exist" -- the report would
/// show one ring while the logger filled another, and which one a caller
/// got would depend on how far down the call tree it was. The tests above
/// all use their own [`LogRing`], so nothing here needs this to be
/// testable.
static PROCESS_RING: OnceLock<LogRing> = OnceLock::new();

/// The process's ring, created on first use with the default bounds.
/// Safe to call before [`install_process_logger`] -- it will simply be
/// empty.
pub fn process_ring() -> &'static LogRing {
    PROCESS_RING.get_or_init(LogRing::with_defaults)
}

/// Installs [`process_ring`] as the recording half of the process logger,
/// forwarding to `inner` (the platform's own logger, already configured).
/// The platform half of AGENTS.md's sharing rule is `inner`; everything
/// else is shared.
pub fn install_process_logger(
    inner: Box<dyn log::Log>,
    max_level: log::LevelFilter,
) -> Result<(), log::SetLoggerError> {
    install(process_ring().clone(), inner, max_level)
}

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

    fn fill(ring: &LogRing, count: usize) {
        for n in 0..count {
            ring.push(Level::Info, "test", format!("line {n}"));
        }
    }

    #[test]
    fn lines_come_back_oldest_first() {
        let ring = LogRing::new(10, 1 << 20);
        fill(&ring, 3);
        let text: Vec<String> = ring.snapshot().into_iter().map(|l| l.message).collect();
        assert_eq!(text, ["line 0", "line 1", "line 2"]);
    }

    #[test]
    fn the_line_bound_drops_the_oldest_and_says_how_many() {
        let ring = LogRing::new(3, 1 << 20);
        fill(&ring, 5);
        let text: Vec<String> = ring.snapshot().into_iter().map(|l| l.message).collect();
        assert_eq!(text, ["line 2", "line 3", "line 4"], "the newest survive");
        assert_eq!(ring.len(), 3);
        assert_eq!(ring.dropped(), 2, "and the loss is reported, not silent");
    }

    #[test]
    fn the_byte_bound_bites_before_the_line_bound_when_lines_are_large() {
        // Room for 1000 lines but only a few hundred bytes.
        let ring = LogRing::new(1000, 300);
        for n in 0..10 {
            ring.push(Level::Info, "t", format!("{n}{}", "x".repeat(100)));
        }
        assert!(
            ring.len() < 10,
            "the byte bound evicted: {} held",
            ring.len()
        );
        assert!(ring.dropped() > 0);
        assert!(
            ring.snapshot().last().unwrap().message.starts_with('9'),
            "and it evicted from the old end"
        );
    }

    /// The case the `len() > 1` guard exists for: one line larger than the
    /// whole bound must still be readable, or a ring that is over budget
    /// reads as a ring nothing was written to.
    #[test]
    fn one_oversized_line_is_kept_rather_than_leaving_the_ring_empty() {
        let ring = LogRing::new(100, 64);
        ring.push(Level::Error, "t", "y".repeat(5000));
        assert_eq!(ring.len(), 1);
        assert_eq!(ring.dropped(), 0);
    }

    #[test]
    fn sequence_numbers_only_increase_and_survive_eviction() {
        let ring = LogRing::new(2, 1 << 20);
        fill(&ring, 5);
        let seqs: Vec<u64> = ring.snapshot().into_iter().map(|l| l.seq).collect();
        assert_eq!(seqs, [3, 4], "a gap is exactly what was dropped");
    }

    #[test]
    fn since_returns_only_what_is_new_and_the_next_cursor() {
        let ring = LogRing::new(100, 1 << 20);
        fill(&ring, 3);
        let (first, cursor) = ring.since(0);
        assert_eq!(first.len(), 3);
        assert_eq!(cursor, 3);

        let (none, cursor) = ring.since(cursor);
        assert!(none.is_empty(), "nothing new yet");
        assert_eq!(cursor, 3, "and the cursor does not move");

        ring.push(Level::Warn, "test", "later".into());
        let (more, cursor) = ring.since(cursor);
        assert_eq!(more.len(), 1);
        assert_eq!(more[0].message, "later");
        assert_eq!(cursor, 4);
    }

    /// The restart signal: a reader that saw sequence 4 and is now told
    /// the newest is 0 knows the process is not the one it was reading.
    #[test]
    fn the_newest_sequence_says_where_the_ring_is_and_nothing_for_an_empty_one() {
        let ring = LogRing::new(100, 1 << 20);
        assert_eq!(ring.newest_seq(), None, "an empty ring has no newest line");
        fill(&ring, 5);
        assert_eq!(ring.newest_seq(), Some(4));

        let restarted = LogRing::new(100, 1 << 20);
        fill(&restarted, 1);
        assert_eq!(
            restarted.newest_seq(),
            Some(0),
            "a fresh ring starts again, which is exactly what a reader has to notice"
        );
    }

    #[test]
    fn reading_does_not_consume() {
        let ring = LogRing::new(100, 1 << 20);
        fill(&ring, 2);
        let (sent, _) = ring.since(0);
        assert_eq!(sent.len(), 2);
        assert_eq!(ring.len(), 2, "the report still has them after an upload");
        assert_eq!(ring.to_text().lines().count(), 2);
    }

    #[test]
    fn an_empty_ring_says_so_rather_than_reporting_a_time() {
        let ring = LogRing::with_defaults();
        assert_eq!(ring.summary(), "app log: no lines yet");
        assert_eq!(ring.last_at_ms(), None);
        assert!(ring.is_empty());
    }

    #[test]
    fn the_summary_names_dropped_lines_only_when_there_are_some() {
        let ring = LogRing::new(2, 1 << 20);
        fill(&ring, 2);
        assert!(!ring.summary().contains("dropped"), "{}", ring.summary());
        fill(&ring, 2);
        assert!(ring.summary().contains("2 dropped"), "{}", ring.summary());
    }

    #[test]
    fn a_line_formats_as_time_level_target_message() {
        let line = LogLine {
            seq: 0,
            // 1970-01-01T12:34:56.789Z, so the arithmetic is checkable by
            // hand rather than against another clock.
            at_ms: (12 * 3600 + 34 * 60 + 56) * 1000 + 789,
            level: Level::Info,
            target: "iris::android".into(),
            message: "surface created".into(),
        }
        .format();
        assert_eq!(line, "12:34:56.789 INFO  iris::android: surface created");
    }

    /// The forwarding half: a line reaches the ring *and* the logger the
    /// platform already had, and one the inner logger filters out is still
    /// in the ring.
    #[test]
    fn the_ring_logger_forwards_to_the_inner_logger() {
        use log::Log;
        struct Collect(Arc<Mutex<Vec<String>>>, log::Level);
        impl Log for Collect {
            fn enabled(&self, metadata: &log::Metadata) -> bool {
                metadata.level() <= self.1
            }
            fn log(&self, record: &log::Record) {
                self.0.lock().unwrap().push(record.args().to_string());
            }
            fn flush(&self) {}
        }

        let seen = Arc::new(Mutex::new(Vec::new()));
        let ring = LogRing::with_defaults();
        let logger = RingLogger::new(ring.clone(), Box::new(Collect(seen.clone(), Level::Info)));
        logger.log(
            &log::Record::builder()
                .args(format_args!("kept"))
                .level(Level::Info)
                .target("t")
                .build(),
        );
        logger.log(
            &log::Record::builder()
                .args(format_args!("filtered"))
                .level(Level::Debug)
                .target("t")
                .build(),
        );

        assert_eq!(
            *seen.lock().unwrap(),
            ["kept"],
            "the inner logger's own filter still applies"
        );
        let held: Vec<String> = ring.snapshot().into_iter().map(|l| l.message).collect();
        assert_eq!(held, ["kept", "filtered"], "the ring keeps both");
    }
}