client-core: filter the ring's Debug/Trace lines to iris's own targets

Iris's phone report (docs/IRIS_TODO.md, 2026-09-07 night): the ring held
1339 lines and dropped 4050 more, almost all of it naga::front/wgpu_core/
jni logging at Debug unconditionally, because RingLogger accepted every
target at whatever level `log`'s own max was set to. The trace gate added
in 992c472 only covers iris's own debug! call sites, not a dependency's.

ring_accepts() is the one filter, applied in RingLogger::log rather than
per callsite: Info and above always rings, from anywhere (a dependency's
real warning is worth keeping); Debug and Trace ring only from `iris`/
`client_core` targets, and only while tracing is on. Tracing itself is
`iris::diagnostics::trace_enabled`, passed into RingLogger as a plain
`fn() -> bool` rather than called directly, since client-core sits below
iris and must not depend on it -- the same reason `inner` (the platform
logger) is already injected rather than chosen here.

Also adds LogRing::tail_text and COPY_REPORT_TAIL_LINES (150, named and
reasoned at the constant) for the next commit's Copy report trim.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
irisandClaude Fable 5.1 committed 2026-09-07 22:26:17 -04:00
1 parent b87f5a597e
commit 7485d78d50
1 file changed
+220 -12
+220 -12
View File
@@ -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::<Vec<_>>()
.join("\n");
}
let omitted = lines.len() - max_lines;
let tail = lines[lines.len() - max_lines..]
.iter()
.map(LogLine::format)
.collect::<Vec<_>>()
.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<dyn log::Log>,
/// 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<dyn log::Log>) -> Self {
Self { ring, inner }
pub fn new(ring: LogRing, inner: Box<dyn log::Log>, 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) {
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<dyn log::Log>,
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<dyn log::Log>,
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<String> = 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<String> = 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"));
}
}