diff --git a/moli/Cargo.toml b/moli/Cargo.toml index 5733c02996..19b2560bca 100644 --- a/moli/Cargo.toml +++ b/moli/Cargo.toml @@ -33,7 +33,7 @@ regex = "1.12.3" serde_json = "1.0.145" tokio = { version = "1.51.0", features = ["macros", "net", "rt-multi-thread", "signal", "sync"] } tracing = "0.1.41" -tracing-subscriber = { version = "0.3.19", features = ["env-filter", "fmt"] } +tracing-subscriber = { version = "0.3.19", features = ["fmt"] } url = "2.5.7" # Keep the existing jemalloc fallback only where rusty_v8 does not publish a @@ -43,6 +43,7 @@ tikv-jemalloc-sys = { version = "0.7.1", optional = true, default-features = fal tikv-jemallocator = { version = "0.7.0", optional = true, default-features = false, features = ["override_allocator_on_supported_platforms"] } [dev-dependencies] +tracing-subscriber = { version = "0.3.19", features = ["env-filter", "fmt"] } futures-util = "0.3.31" lopdf = { version = "0.45.0", default-features = false } libc = "0.2" diff --git a/moli/src/telemetry.rs b/moli/src/telemetry.rs index 626b89d53a..b308ac8fb9 100644 --- a/moli/src/telemetry.rs +++ b/moli/src/telemetry.rs @@ -1,25 +1,34 @@ -use tracing_subscriber::{EnvFilter, filter::LevelFilter}; +use tracing_subscriber::{ + filter::{LevelFilter, Targets}, + layer::SubscriberExt, + util::SubscriberInitExt, +}; const DEFAULT_LOG_LEVEL: LevelFilter = LevelFilter::INFO; const FIRST_PARTY_TARGET_PREFIX: &str = "moli"; -fn first_party_filter(log_level: &str) -> EnvFilter { +fn first_party_filter(log_level: &str) -> Targets { let level = log_level .parse::() .unwrap_or(DEFAULT_LOG_LEVEL); - EnvFilter::new(format!("off,{FIRST_PARTY_TARGET_PREFIX}={level}")) + Targets::new() + .with_default(LevelFilter::OFF) + .with_target(FIRST_PARTY_TARGET_PREFIX, level) } pub fn init(log_filter: &str) { - // Rust crate targets use underscores, and EnvFilter target directives match - // prefixes, so this includes every moli workspace crate but no dependency. + // Rust crate targets use underscores, and Targets matches prefixes, so + // this includes every moli workspace crate but no dependency. let filter = first_party_filter(log_filter); - let _ = tracing_subscriber::fmt() - .with_env_filter(filter) - .with_target(false) - .with_writer(std::io::stderr) - .log_internal_errors(false) + let _ = tracing_subscriber::registry() + .with(filter) + .with( + tracing_subscriber::fmt::layer() + .with_target(false) + .with_writer(std::io::stderr) + .log_internal_errors(false), + ) .try_init(); } @@ -31,7 +40,7 @@ mod tests { }; use parking_lot::Mutex; - use tracing_subscriber::fmt::MakeWriter; + use tracing_subscriber::{fmt::MakeWriter, layer::SubscriberExt}; use super::first_party_filter; @@ -68,13 +77,15 @@ mod tests { #[test] fn first_party_filter_excludes_dependency_and_lower_level_logs() { let writer = SharedWriter::default(); - let subscriber = tracing_subscriber::fmt() - .without_time() - .with_ansi(false) - .with_target(true) - .with_writer(writer.clone()) - .with_env_filter(first_party_filter("info")) - .finish(); + let subscriber = tracing_subscriber::registry() + .with(first_party_filter("info")) + .with( + tracing_subscriber::fmt::layer() + .without_time() + .with_ansi(false) + .with_target(true) + .with_writer(writer.clone()), + ); tracing::subscriber::with_default(subscriber, || { tracing::info!(target: "moli_parser", "first-party-info"); @@ -91,13 +102,15 @@ mod tests { #[test] fn non_level_filter_falls_back_to_first_party_info() { let writer = SharedWriter::default(); - let subscriber = tracing_subscriber::fmt() - .without_time() - .with_ansi(false) - .with_target(true) - .with_writer(writer.clone()) - .with_env_filter(first_party_filter("info,dependency=trace")) - .finish(); + let subscriber = tracing_subscriber::registry() + .with(first_party_filter("info,dependency=trace")) + .with( + tracing_subscriber::fmt::layer() + .without_time() + .with_ansi(false) + .with_target(true) + .with_writer(writer.clone()), + ); tracing::subscriber::with_default(subscriber, || { tracing::info!(target: "moli", "fallback-info"); @@ -109,6 +122,89 @@ mod tests { assert!(!output.contains("dependency-warning")); } + fn render_filter(filter: F) -> String + where + F: tracing_subscriber::Layer + Send + Sync + 'static, + { + use tracing_subscriber::fmt::format::FmtSpan; + + let writer = SharedWriter::default(); + let subscriber = tracing_subscriber::registry().with(filter).with( + tracing_subscriber::fmt::layer() + .without_time() + .with_ansi(false) + .with_target(true) + .with_span_events(FmtSpan::NEW | FmtSpan::ENTER | FmtSpan::EXIT) + .with_writer(writer.clone()), + ); + tracing::subscriber::with_default(subscriber, || { + macro_rules! emit_for_target { + ($target:literal) => {{ + let parent = tracing::info_span!(target: $target, "filter_parent", value = 1); + let _entered = parent.enter(); + parent.record("value", 2); + tracing::error!(target: $target, "error-probe"); + tracing::warn!(target: $target, "warn-probe"); + tracing::info!(target: $target, "info-probe"); + tracing::debug!(target: $target, "debug-probe"); + tracing::trace!(target: $target, "trace-probe"); + tracing::info!(target: "dependency", "dependency-inside-parent"); + }}; + } + + emit_for_target!("moli"); + emit_for_target!("moli_parser"); + emit_for_target!("moli::nested"); + emit_for_target!("molibogus"); + emit_for_target!("dependency"); + emit_for_target!("dependency::moli"); + let parent = tracing::info_span!(target: "dependency", "dependency_parent"); + let _entered = parent.enter(); + tracing::info!(target: "moli", "first-party-inside-dependency"); + }); + writer.output() + } + + #[test] + fn targets_match_env_filter_for_levels_prefixes_and_spans() { + use tracing_subscriber::{EnvFilter, filter::LevelFilter}; + + use super::{DEFAULT_LOG_LEVEL, FIRST_PARTY_TARGET_PREFIX}; + + for log_level in [ + "off", + "error", + "warn", + "info", + "debug", + "trace", + "INFO", + "0", + "1", + "2", + "3", + "4", + "5", + "", + "invalid", + "info,dependency=trace", + ] { + let level = log_level + .parse::() + .unwrap_or(DEFAULT_LOG_LEVEL); + let previous = EnvFilter::new(format!("off,{FIRST_PARTY_TARGET_PREFIX}={level}")); + let expected = render_filter(previous); + let actual = render_filter(first_party_filter(log_level)); + assert_eq!(actual, expected, "log level {log_level:?}"); + if level == LevelFilter::OFF { + assert!(actual.is_empty()); + } else { + assert!(actual.contains("error-probe")); + } + assert!(!actual.contains("dependency-inside-parent")); + } + } + #[test] fn broken_diagnostic_writer_does_not_panic() { const CHILD: &str = "MOLI_TEST_BROKEN_DIAGNOSTIC_SINK";