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:
1 parent
b87f5a597e
commit
7485d78d50
1 file changed
+220
-12
+220
-12
@@ -11,7 +11,7 @@
|
|||||||
//!
|
//!
|
||||||
//! Two consumers, both reading the same ring rather than each keeping
|
//! Two consumers, both reading the same ring rather than each keeping
|
||||||
//! their own: the bench app's `Copy report`/`Diagnostics` (which reads
|
//! 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
|
//! log out of the process -- on Android, the `DevLogProvider` Dev Updater
|
||||||
//! queries, which reads [`LogRing::since`] and [`LogRing::newest_seq`].
|
//! queries, which reads [`LogRing::since`] and [`LogRing::newest_seq`].
|
||||||
//! That is why reading does not consume: a line already handed over must
|
//! 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_LINES: usize = 2000;
|
||||||
pub const DEFAULT_MAX_BYTES: usize = 256 * 1024;
|
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
|
/// 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
|
/// 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
|
/// came after -- and a gap in the sequence is exactly the lines the bound
|
||||||
@@ -240,6 +249,35 @@ impl LogRing {
|
|||||||
.join("\n")
|
.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
|
/// 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
|
/// 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
|
/// 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
|
/// A `log` backend that records into a [`LogRing`] **and** forwards to the
|
||||||
/// logger the platform already installs, so nothing that reads the
|
/// logger the platform already installs, so nothing that reads the
|
||||||
/// platform's log (`logcat`, a terminal) changes.
|
/// platform's log (`logcat`, a terminal) changes.
|
||||||
@@ -281,25 +350,40 @@ impl LogRing {
|
|||||||
pub struct RingLogger {
|
pub struct RingLogger {
|
||||||
ring: LogRing,
|
ring: LogRing,
|
||||||
inner: Box<dyn log::Log>,
|
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 {
|
impl RingLogger {
|
||||||
pub fn new(ring: LogRing, inner: Box<dyn log::Log>) -> Self {
|
pub fn new(ring: LogRing, inner: Box<dyn log::Log>, trace_enabled: fn() -> bool) -> Self {
|
||||||
Self { ring, inner }
|
Self {
|
||||||
|
ring,
|
||||||
|
inner,
|
||||||
|
trace_enabled,
|
||||||
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
impl log::Log for RingLogger {
|
impl log::Log for RingLogger {
|
||||||
/// True for anything `log`'s own max level lets through: the ring
|
/// True for anything `log`'s own max level lets through: the ring
|
||||||
/// wants everything, even where the platform logger would filter it
|
/// wants everything the *inner* logger might also want, even where the
|
||||||
/// out. The filter is applied per-logger in [`Self::log`] instead.
|
/// 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 {
|
fn enabled(&self, _metadata: &log::Metadata) -> bool {
|
||||||
true
|
true
|
||||||
}
|
}
|
||||||
|
|
||||||
fn log(&self, record: &log::Record) {
|
fn log(&self, record: &log::Record) {
|
||||||
|
if ring_accepts(record.level(), record.target(), (self.trace_enabled)()) {
|
||||||
self.ring
|
self.ring
|
||||||
.push(record.level(), record.target(), record.args().to_string());
|
.push(record.level(), record.target(), record.args().to_string());
|
||||||
|
}
|
||||||
if self.inner.enabled(record.metadata()) {
|
if self.inner.enabled(record.metadata()) {
|
||||||
self.inner.log(record);
|
self.inner.log(record);
|
||||||
}
|
}
|
||||||
@@ -320,8 +404,9 @@ pub fn install(
|
|||||||
ring: LogRing,
|
ring: LogRing,
|
||||||
inner: Box<dyn log::Log>,
|
inner: Box<dyn log::Log>,
|
||||||
max_level: log::LevelFilter,
|
max_level: log::LevelFilter,
|
||||||
|
trace_enabled: fn() -> bool,
|
||||||
) -> Result<(), log::SetLoggerError> {
|
) -> 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);
|
log::set_max_level(max_level);
|
||||||
Ok(())
|
Ok(())
|
||||||
}
|
}
|
||||||
@@ -349,12 +434,16 @@ pub fn process_ring() -> &'static LogRing {
|
|||||||
/// Installs [`process_ring`] as the recording half of the process logger,
|
/// Installs [`process_ring`] as the recording half of the process logger,
|
||||||
/// forwarding to `inner` (the platform's own logger, already configured).
|
/// forwarding to `inner` (the platform's own logger, already configured).
|
||||||
/// The platform half of AGENTS.md's sharing rule is `inner`; everything
|
/// 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(
|
pub fn install_process_logger(
|
||||||
inner: Box<dyn log::Log>,
|
inner: Box<dyn log::Log>,
|
||||||
max_level: log::LevelFilter,
|
max_level: log::LevelFilter,
|
||||||
|
trace_enabled: fn() -> bool,
|
||||||
) -> Result<(), log::SetLoggerError> {
|
) -> Result<(), log::SetLoggerError> {
|
||||||
install(process_ring().clone(), inner, max_level)
|
install(process_ring().clone(), inner, max_level, trace_enabled)
|
||||||
}
|
}
|
||||||
|
|
||||||
#[cfg(test)]
|
#[cfg(test)]
|
||||||
@@ -471,6 +560,33 @@ mod tests {
|
|||||||
assert_eq!(ring.to_text().lines().count(), 2);
|
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]
|
#[test]
|
||||||
fn an_empty_ring_says_so_rather_than_reporting_a_time() {
|
fn an_empty_ring_says_so_rather_than_reporting_a_time() {
|
||||||
let ring = LogRing::with_defaults();
|
let ring = LogRing::with_defaults();
|
||||||
@@ -522,19 +638,26 @@ mod tests {
|
|||||||
|
|
||||||
let seen = Arc::new(Mutex::new(Vec::new()));
|
let seen = Arc::new(Mutex::new(Vec::new()));
|
||||||
let ring = LogRing::with_defaults();
|
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(
|
logger.log(
|
||||||
&log::Record::builder()
|
&log::Record::builder()
|
||||||
.args(format_args!("kept"))
|
.args(format_args!("kept"))
|
||||||
.level(Level::Info)
|
.level(Level::Info)
|
||||||
.target("t")
|
.target("iris::test")
|
||||||
.build(),
|
.build(),
|
||||||
);
|
);
|
||||||
logger.log(
|
logger.log(
|
||||||
&log::Record::builder()
|
&log::Record::builder()
|
||||||
.args(format_args!("filtered"))
|
.args(format_args!("filtered"))
|
||||||
.level(Level::Debug)
|
.level(Level::Debug)
|
||||||
.target("t")
|
.target("iris::test")
|
||||||
.build(),
|
.build(),
|
||||||
);
|
);
|
||||||
|
|
||||||
@@ -544,6 +667,91 @@ mod tests {
|
|||||||
"the inner logger's own filter still applies"
|
"the inner logger's own filter still applies"
|
||||||
);
|
);
|
||||||
let held: Vec<String> = ring.snapshot().into_iter().map(|l| l.message).collect();
|
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"));
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
Reference in new issue
Block a user