//! 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::tail_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; /// How many of the ring's newest lines [`LogRing::tail_text`] includes. /// Sized for a phone's share sheet rather than for the ring itself: 150 /// lines of `HH:MM:SS.mmm LEVEL target: message` is a few KiB, comfortably /// short of whatever made pasting the full (up to 2000-line) ring into a /// chat's message box laggy on Iris's phone. The full ring is still /// reachable through `devlog`'s provider, so this only bounds what a /// report inlines. pub const COPY_REPORT_TAIL_LINES: usize = 150; /// 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, 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>); 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(&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 { 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, u64) { self.with(|inner| { let lines: Vec = 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 { 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 { 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::>() .join("\n") } /// The newest `max_lines` lines, formatted, with a first line naming /// how many older ones were left out of *this* text when the ring held /// more than that -- what `Copy report` appends instead of /// [`Self::to_text`]. /// /// Iris's own report: pasting the full ring (over a thousand lines on /// a session that ran with tracing on) into a phone's message box was /// what "causes a lot of lag" meant (docs/IRIS_TODO.md, 2026-09-07 /// night) -- nothing is actually lost, since `devlog`'s provider still /// hands Dev Updater's Runtime tab the whole ring; this only caps what /// gets inlined into a share. pub fn tail_text(&self, max_lines: usize) -> String { let lines = self.snapshot(); if lines.len() <= max_lines { return lines .iter() .map(LogLine::format) .collect::>() .join("\n"); } let omitted = lines.len() - max_lines; let tail = lines[lines.len() - max_lines..] .iter() .map(LogLine::format) .collect::>() .join("\n"); format!("{omitted} earlier lines omitted; full log in Dev Updater's Runtime tab\n{tail}") } /// 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) ) } } } } /// Whether a target belongs to this app's own crates (`iris` or /// `client_core`) rather than a dependency's -- `starts_with` guarded by an /// exact match or a `::` so an unrelated crate that merely begins with the /// same letters (there is no such crate today, but the check should not /// rely on that) is never mistaken for one of ours. fn is_own_target(target: &str) -> bool { target == "iris" || target.starts_with("iris::") || target == "client_core" || target.starts_with("client_core::") } /// Whether a line at `level` from `target` belongs in the ring, given /// whether tracing is on right now. /// /// This is the one filter docs/IRIS_TODO.md's "logs way too big" entry /// asked for, applied once here rather than at each `debug!` call site: /// Info and above always ring, from anything, because a real warning or /// error from a dependency is worth keeping. Debug and Trace ring only /// from this app's own targets, and only while tracing is switched on -- /// otherwise `naga::front`/`wgpu_core`/`jni` log at Debug unconditionally /// (the process logger's own level, set once at install and unrelated to /// tracing), which is what filled the ring with 1339 lines of it and /// dropped 4050 more before this existed. `iris`'s own Debug lines already /// self-gate on `iris::diagnostics::trace_enabled` at their call sites /// (commit 992c472); this is the backstop for lines this crate does not /// control. fn ring_accepts(level: log::Level, target: &str, trace_enabled: bool) -> bool { level <= log::Level::Info || (trace_enabled && is_own_target(target)) } /// 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, /// Whether `iris::input`/`iris::frame`-style tracing is switched on /// right now, consulted by [`ring_accepts`]. A plain fn pointer rather /// than a dependency on `iris::diagnostics::trace_enabled` directly: /// `client-core` sits below `iris` (AGENTS.md's "dependencies flow one /// direction"), so the platform crate that depends on both is the one /// that wires this closure through, the same way it already supplies /// `inner`. trace_enabled: fn() -> bool, } impl RingLogger { pub fn new(ring: LogRing, inner: Box, trace_enabled: fn() -> bool) -> Self { Self { ring, inner, trace_enabled, } } } impl log::Log for RingLogger { /// True for anything `log`'s own max level lets through: the ring /// wants everything the *inner* logger might also want, even where the /// platform logger would filter it out. Which lines the ring itself /// keeps is decided in [`Self::log`] by [`ring_accepts`]. fn enabled(&self, _metadata: &log::Metadata) -> bool { true } fn log(&self, record: &log::Record) { if ring_accepts(record.level(), record.target(), (self.trace_enabled)()) { 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, max_level: log::LevelFilter, trace_enabled: fn() -> bool, ) -> Result<(), log::SetLoggerError> { log::set_boxed_logger(Box::new(RingLogger::new(ring, inner, trace_enabled)))?; 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 = 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. `trace_enabled` is the platform's own trace toggle /// (`iris::diagnostics::trace_enabled` on Android) -- see /// [`ring_accepts`] and the field doc on `RingLogger` for why it is /// passed in rather than called directly. pub fn install_process_logger( inner: Box, max_level: log::LevelFilter, trace_enabled: fn() -> bool, ) -> Result<(), log::SetLoggerError> { install(process_ring().clone(), inner, max_level, trace_enabled) } #[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 = 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 = 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 = 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 tail_text_is_the_whole_ring_untouched_when_under_the_cap() { let ring = LogRing::new(100, 1 << 20); fill(&ring, 5); assert_eq!(ring.tail_text(150), ring.to_text()); } #[test] fn tail_text_trims_to_the_newest_lines_and_says_how_many_were_left_out() { let ring = LogRing::new(1000, 1 << 20); fill(&ring, 200); let tail = ring.tail_text(150); let mut lines = tail.lines(); assert_eq!( lines.next().unwrap(), "50 earlier lines omitted; full log in Dev Updater's Runtime tab" ); let rest: Vec<&str> = lines.collect(); assert_eq!(rest.len(), 150, "exactly the cap, after the header line"); assert!( rest[0].ends_with("line 50"), "the oldest line kept is the 50th, not line 0: {}", rest[0] ); assert!(rest.last().unwrap().ends_with("line 199")); } #[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>>, 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(); // Own target, tracing on: this is the case where the ring and the // inner logger disagree, which is the thing under test -- a // foreign target is covered separately below. let logger = RingLogger::new( ring.clone(), Box::new(Collect(seen.clone(), Level::Info)), || true, ); logger.log( &log::Record::builder() .args(format_args!("kept")) .level(Level::Info) .target("iris::test") .build(), ); logger.log( &log::Record::builder() .args(format_args!("filtered")) .level(Level::Debug) .target("iris::test") .build(), ); assert_eq!( *seen.lock().unwrap(), ["kept"], "the inner logger's own filter still applies" ); let held: Vec = ring.snapshot().into_iter().map(|l| l.message).collect(); assert_eq!( held, ["kept", "filtered"], "own-target debug still rings while tracing is on" ); } /// The bug this filter fixes: `naga`/`wgpu_core`/`jni` log at Debug /// unconditionally, and used to flood the ring even though nothing in /// this app asked for their Debug output. A foreign target's Debug /// line must not ring even while tracing is on -- tracing controls /// this app's own diagnostics, not a dependency's chatter. #[test] fn a_foreign_targets_debug_line_never_rings_even_while_tracing_is_on() { use log::Log; struct Discard; impl Log for Discard { fn enabled(&self, _: &log::Metadata) -> bool { true } fn log(&self, _: &log::Record) {} fn flush(&self) {} } let ring = LogRing::with_defaults(); let logger = RingLogger::new(ring.clone(), Box::new(Discard), || true); logger.log( &log::Record::builder() .args(format_args!("naga debug spam")) .level(Level::Debug) .target("naga::front") .build(), ); logger.log( &log::Record::builder() .args(format_args!("naga warning")) .level(Level::Warn) .target("wgpu_core::device") .build(), ); let held: Vec = ring.snapshot().into_iter().map(|l| l.message).collect(); assert_eq!( held, ["naga warning"], "Info-and-above always rings; foreign Debug never does" ); } #[test] fn ring_accepts_is_own_target_debug_only_while_tracing() { assert!( ring_accepts(Level::Info, "wgpu_core::device", false), "Info+ from anything, tracing off" ); assert!( ring_accepts(Level::Warn, "jni", true), "Info+ from anything, tracing on" ); assert!( !ring_accepts(Level::Debug, "jni", true), "foreign Debug, tracing on: still excluded" ); assert!( !ring_accepts(Level::Debug, "iris::sense", false), "own Debug, tracing off: excluded" ); assert!( ring_accepts(Level::Debug, "iris::sense", true), "own Debug, tracing on: included" ); assert!( ring_accepts(Level::Trace, "client_core::api", true), "own Trace, tracing on: included" ); } #[test] fn is_own_target_matches_the_crate_or_its_modules_only() { assert!(is_own_target("iris")); assert!(is_own_target("iris::sense")); assert!(is_own_target("client_core")); assert!(is_own_target("client_core::log_ring")); assert!(!is_own_target("iris_something_else")); assert!(!is_own_target("naga::front")); assert!(!is_own_target("jni")); } }