diff --git a/client-core/src/log_ring.rs b/client-core/src/log_ring.rs index 144dc30..51ae7fb 100644 --- a/client-core/src/log_ring.rs +++ b/client-core/src/log_ring.rs @@ -11,7 +11,7 @@ //! //! 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 +//! [`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 @@ -32,6 +32,15 @@ use std::time::{SystemTime, UNIX_EPOCH}; 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 @@ -240,6 +249,35 @@ impl LogRing { .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 @@ -270,6 +308,37 @@ impl LogRing { } } +/// 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. @@ -281,25 +350,40 @@ impl LogRing { 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) -> Self { - Self { ring, inner } + 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, even where the platform logger would filter it - /// out. The filter is applied per-logger in [`Self::log`] instead. + /// 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) { - self.ring - .push(record.level(), record.target(), record.args().to_string()); + 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); } @@ -320,8 +404,9 @@ 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)))?; + log::set_boxed_logger(Box::new(RingLogger::new(ring, inner, trace_enabled)))?; log::set_max_level(max_level); Ok(()) } @@ -349,12 +434,16 @@ pub fn process_ring() -> &'static LogRing { /// 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. +/// 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) + install(process_ring().clone(), inner, max_level, trace_enabled) } #[cfg(test)] @@ -471,6 +560,33 @@ mod tests { 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(); @@ -522,19 +638,26 @@ mod tests { 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))); + // 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("t") + .target("iris::test") .build(), ); logger.log( &log::Record::builder() .args(format_args!("filtered")) .level(Level::Debug) - .target("t") + .target("iris::test") .build(), ); @@ -544,6 +667,91 @@ mod tests { "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"], "the ring keeps both"); + 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")); } }