From d13cd007a263dc9b1388291c8832f0f6430d6f4a Mon Sep 17 00:00:00 2001 From: Ben Kunkle Date: Mon, 21 Apr 2025 11:43:24 -0400 Subject: [PATCH] zlog: Module-level configuration and other improvements (#29161) Various improvements to `zlog` including: - Enable filtering by module (reproducing `env_logger` behavior) both through env and settings. - Note: filtering by module currently does not account for parent module configuration, but does account for crate configuration. i.e. `crate=trace` will enable `TRACE` messages in `crate::a` and `crate::a::b` modules, but `crate::a=trace` will not enable trace messages in module `crate::a::b` - Implementing the `Log` trait for `zlog::Logger` to support gradual transition and evaluate tradeoffs of always going through `log` crate. - Added the ability to turn off logging for a specific filter (module or scope) completely by setting it to `off` (in env: `crate::a=off`, in settings: `"project.foo": "off"`) - Made it so the `zlog::scoped!` macro can be used in constant expressions, so scoped loggers can be declared as global constants Release Notes: - N/A --- crates/zlog/src/env_config.rs | 4 +- crates/zlog/src/filter.rs | 226 ++++++++++++++++++++-------------- crates/zlog/src/sink.rs | 1 + crates/zlog/src/zlog.rs | 98 +++++++++++---- 4 files changed, 211 insertions(+), 118 deletions(-) diff --git a/crates/zlog/src/env_config.rs b/crates/zlog/src/env_config.rs index 481be37d95..9efde5c821 100644 --- a/crates/zlog/src/env_config.rs +++ b/crates/zlog/src/env_config.rs @@ -18,12 +18,12 @@ pub fn parse(filter: &str) -> Result { return Err(anyhow!("Invalid directive: {}", directive)); } let level = parse_level(level.trim())?; - directive_names.push(name.to_string()); + directive_names.push(name.trim().trim_end_matches(".rs").to_string()); directive_levels.push(level); } None => { let Ok(level) = parse_level(directive.trim()) else { - directive_names.push(directive.trim().to_string()); + directive_names.push(directive.trim().trim_end_matches(".rs").to_string()); directive_levels.push(log::LevelFilter::max() /* Enable all levels */); continue; }; diff --git a/crates/zlog/src/filter.rs b/crates/zlog/src/filter.rs index 13bd5f049b..1efeae7bc4 100644 --- a/crates/zlog/src/filter.rs +++ b/crates/zlog/src/filter.rs @@ -1,6 +1,5 @@ use std::{ collections::{HashMap, VecDeque}, - hash::{DefaultHasher, Hasher}, sync::{ OnceLock, RwLock, atomic::{AtomicU8, Ordering}, @@ -13,11 +12,7 @@ use crate::{SCOPE_DEPTH_MAX, SCOPE_STRING_SEP_STR, Scope, ScopeAlloc, env_config use log; static ENV_FILTER: OnceLock = OnceLock::new(); -static SCOPE_MAP: RwLock> = RwLock::new(None); -struct GlobalScopeMap { - map: ScopeMap, - hash: u64, -} +static SCOPE_MAP: RwLock> = RwLock::new(None); const LEVEL_ENABLED_MAX_DEFAULT: log::LevelFilter = log::LevelFilter::Info; /// The maximum log level of verbosity that is enabled by default. @@ -54,7 +49,7 @@ pub fn is_possibly_enabled_level(level: log::Level) -> bool { return level as u8 <= LEVEL_ENABLED_MAX_CONFIG.load(Ordering::Relaxed); } -pub fn is_scope_enabled(scope: &Scope, level: log::Level) -> bool { +pub fn is_scope_enabled(scope: &Scope, module_path: Option<&str>, level: log::Level) -> bool { if level <= unsafe { LEVEL_ENABLED_MAX_STATIC } { // [FAST PATH] // if the message is at or below the minimum printed log level @@ -73,7 +68,7 @@ pub fn is_scope_enabled(scope: &Scope, level: log::Level) -> bool { return err.into_inner(); }); - let Some(GlobalScopeMap { map, .. }) = global_scope_map.as_ref() else { + let Some(map) = global_scope_map.as_ref() else { // on failure, return false because it's not <= LEVEL_ENABLED_MAX_STATIC return false; }; @@ -82,7 +77,7 @@ pub fn is_scope_enabled(scope: &Scope, level: log::Level) -> bool { // if no scopes are enabled, return false because it's not <= LEVEL_ENABLED_MAX_STATIC return false; } - let enabled_status = map.is_enabled(&scope, level); + let enabled_status = map.is_enabled(&scope, module_path, level); return match enabled_status { // if it isn't configured, then it it's disabled because it's not <= LEVEL_ENABLED_MAX_STATIC EnabledStatus::NotConfigured => false, @@ -91,69 +86,46 @@ pub fn is_scope_enabled(scope: &Scope, level: log::Level) -> bool { }; } -fn hash_scope_map_settings(map: &HashMap) -> u64 { - let mut hasher = DefaultHasher::new(); - let mut items = map.iter().collect::>(); - items.sort(); - for (key, value) in items { - Hasher::write(&mut hasher, key.as_bytes()); - Hasher::write(&mut hasher, value.as_bytes()); - } - return hasher.finish(); -} - pub(crate) fn refresh() { refresh_from_settings(&HashMap::default()); } pub fn refresh_from_settings(settings: &HashMap) { - let hash_old = { - SCOPE_MAP - .read() - .unwrap_or_else(|err| { - SCOPE_MAP.clear_poison(); - err.into_inner() - }) - .as_ref() - .map(|scope_map| scope_map.hash) - }; - let hash_new = hash_scope_map_settings(settings); - if hash_old == Some(hash_new) { - return; - } let env_config = ENV_FILTER.get(); let map_new = ScopeMap::new_from_settings_and_env(settings, env_config); let mut level_enabled_max = unsafe { LEVEL_ENABLED_MAX_STATIC }; for entry in &map_new.entries { if let Some(level) = entry.enabled { - level_enabled_max = level_enabled_max.max(level.to_level_filter()); + level_enabled_max = level_enabled_max.max(level); } } LEVEL_ENABLED_MAX_CONFIG.store(level_enabled_max as u8, Ordering::Release); - let mut global_map = SCOPE_MAP.write().unwrap_or_else(|err| { - SCOPE_MAP.clear_poison(); - err.into_inner() - }); - global_map.replace(GlobalScopeMap { - map: map_new, - hash: hash_new, - }); + { + let mut global_map = SCOPE_MAP.write().unwrap_or_else(|err| { + SCOPE_MAP.clear_poison(); + err.into_inner() + }); + global_map.replace(map_new); + } + log::trace!("Log configuration updated"); } -fn level_from_level_str(level_str: &String) -> Option { +fn level_filter_from_str(level_str: &String) -> Option { + use log::LevelFilter::*; let level = match level_str.to_ascii_lowercase().as_str() { - "" => log::Level::Trace, - "trace" => log::Level::Trace, - "debug" => log::Level::Debug, - "info" => log::Level::Info, - "warn" => log::Level::Warn, - "error" => log::Level::Error, - "off" | "disable" | "no" | "none" | "disabled" => { + "" => Trace, + "trace" => Trace, + "debug" => Debug, + "info" => Info, + "warn" => Warn, + "error" => Error, + "off" => Off, + "disable" | "no" | "none" | "disabled" => { crate::warn!( - "Invalid log level \"{level_str}\", set to error to disable non-error logging. Defaulting to error" + "Invalid log level \"{level_str}\", to disable logging set to \"off\". Defaulting to \"off\"." ); - log::Level::Error + Off } _ => { crate::warn!("Invalid log level \"{level_str}\", ignoring"); @@ -190,14 +162,17 @@ fn scope_alloc_from_scope_str(scope_str: &String) -> Option { return Some(scope); } +#[derive(PartialEq, Eq)] pub struct ScopeMap { entries: Vec, + modules: Vec<(String, log::LevelFilter)>, root_count: usize, } +#[derive(PartialEq, Eq)] pub struct ScopeMapEntry { scope: String, - enabled: Option, + enabled: Option, descendants: std::ops::Range, } @@ -216,6 +191,8 @@ impl ScopeMap { let mut items = Vec::with_capacity( items_input_map.len() + env_config.map_or(0, |c| c.directive_names.len()), ); + let mut modules = Vec::with_capacity(4); + if let Some(env_filter) = env_config { // TODO: parse on load instead of every reload items.extend( @@ -223,15 +200,17 @@ impl ScopeMap { .directive_names .iter() .zip(env_filter.directive_levels.iter()) - .filter_map(|(scope, level_filter)| { - if items_input_map.get(scope).is_some() { + .filter_map(|(scope_str, &level_filter)| { + if items_input_map.get(scope_str).is_some() { return None; } - let scope = scope_alloc_from_scope_str(scope)?; - // TODO: use level filters instead of scopes in scope map - let level = level_filter.to_level()?; + if scope_str.contains("::") { + modules.push((scope_str.clone(), level_filter)); + return None; + } + let scope = scope_alloc_from_scope_str(scope_str)?; - Some((scope, level)) + Some((scope, level_filter)) }), ); } @@ -239,16 +218,22 @@ impl ScopeMap { items_input_map .into_iter() .filter_map(|(scope_str, level_str)| { + if scope_str.contains("::") { + modules.push((scope_str.clone(), level_str.parse().ok()?)); + return None; + } + let level_filter = level_filter_from_str(&level_str)?; let scope = scope_alloc_from_scope_str(&scope_str)?; - let level = level_from_level_str(&level_str)?; - return Some((scope, level)); + return Some((scope, level_filter)); }), ); items.sort_by(|a, b| a.0.cmp(&b.0)); + modules.sort_by(|(a_name, _), (b_name, _)| a_name.cmp(b_name)); let mut this = Self { entries: Vec::with_capacity(items.len() * SCOPE_DEPTH_MAX), + modules, root_count: 0, }; @@ -329,10 +314,15 @@ impl ScopeMap { } pub fn is_empty(&self) -> bool { - self.entries.is_empty() + self.entries.is_empty() && self.modules.is_empty() } - pub fn is_enabled(&self, scope: &[S; SCOPE_DEPTH_MAX], level: log::Level) -> EnabledStatus + pub fn is_enabled( + &self, + scope: &[S; SCOPE_DEPTH_MAX], + module_path: Option<&str>, + level: log::Level, + ) -> EnabledStatus where S: AsRef, { @@ -346,7 +336,6 @@ impl ScopeMap { { for entry in cur_range { if entry.scope == scope[depth].as_ref() { - // note: enabled = entry.enabled.or(enabled); cur_range = &self.entries[entry.descendants.clone()]; depth += 1; @@ -356,13 +345,23 @@ impl ScopeMap { break 'search; } - return enabled.map_or(EnabledStatus::NotConfigured, |level_enabled| { - if level <= level_enabled { - EnabledStatus::Enabled - } else { - EnabledStatus::Disabled + if enabled.is_none() && !self.modules.is_empty() && module_path.is_some() { + let module_path = module_path.unwrap(); + for (module, filter) in &self.modules { + if module == module_path { + enabled.replace(*filter); + break; + } } - }); + } + + if let Some(enabled_filter) = enabled { + if level <= enabled_filter { + return EnabledStatus::Enabled; + } + return EnabledStatus::Disabled; + } + return EnabledStatus::NotConfigured; } } @@ -444,63 +443,108 @@ mod tests { ]); use log::Level; assert_eq!( - map.is_enabled(&scope_from_scope_str("a.b.c.d"), Level::Trace), + map.is_enabled(&scope_from_scope_str("a.b.c.d"), None, Level::Trace), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("a.b.c.d"), Level::Debug), + map.is_enabled(&scope_from_scope_str("a.b.c.d"), None, Level::Debug), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Debug), + map.is_enabled(&scope_from_scope_str("e.f.g.h"), None, Level::Debug), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Info), + map.is_enabled(&scope_from_scope_str("e.f.g.h"), None, Level::Info), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Trace), + map.is_enabled(&scope_from_scope_str("e.f.g.h"), None, Level::Trace), EnabledStatus::Disabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Info), + map.is_enabled(&scope_from_scope_str("i.j.k.l"), None, Level::Info), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Warn), + map.is_enabled(&scope_from_scope_str("i.j.k.l"), None, Level::Warn), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Debug), + map.is_enabled(&scope_from_scope_str("i.j.k.l"), None, Level::Debug), EnabledStatus::Disabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Warn), + map.is_enabled(&scope_from_scope_str("m.n.o.p"), None, Level::Warn), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Error), + map.is_enabled(&scope_from_scope_str("m.n.o.p"), None, Level::Error), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Info), + map.is_enabled(&scope_from_scope_str("m.n.o.p"), None, Level::Info), EnabledStatus::Disabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("q.r.s.t"), Level::Error), + map.is_enabled(&scope_from_scope_str("q.r.s.t"), None, Level::Error), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_from_scope_str("q.r.s.t"), Level::Warn), + map.is_enabled(&scope_from_scope_str("q.r.s.t"), None, Level::Warn), EnabledStatus::Disabled ); } + #[test] + fn test_is_enabled_module() { + let mut map = scope_map_from_keys(&[("a", "trace")]); + map.modules = [("a::b::c", "trace"), ("a::b::d", "debug")] + .map(|(k, v)| (k.to_string(), v.parse().unwrap())) + .to_vec(); + use log::Level; + assert_eq!( + map.is_enabled( + &scope_from_scope_str("__unused__"), + Some("a::b::c"), + Level::Trace + ), + EnabledStatus::Enabled + ); + assert_eq!( + map.is_enabled( + &scope_from_scope_str("__unused__"), + Some("a::b::d"), + Level::Debug + ), + EnabledStatus::Enabled + ); + assert_eq!( + map.is_enabled( + &scope_from_scope_str("__unused__"), + Some("a::b::d"), + Level::Trace, + ), + EnabledStatus::Disabled + ); + assert_eq!( + map.is_enabled( + &scope_from_scope_str("__unused__"), + Some("a::e"), + Level::Info + ), + EnabledStatus::NotConfigured + ); + assert_eq!( + map.is_enabled(&scope_from_scope_str("a"), Some("a::b::d"), Level::Trace), + EnabledStatus::Enabled, + ); + } + fn scope_map_from_keys_and_env(kv: &[(&str, &str)], env: &env_config::EnvFilter) -> ScopeMap { let hash_map: HashMap = kv .iter() @@ -516,15 +560,15 @@ mod tests { assert_eq!(map.root_count, 2); assert_eq!(map.entries.len(), 3); assert_eq!( - map.is_enabled(&scope_new(&["a"]), log::Level::Debug), + map.is_enabled(&scope_new(&["a"]), None, log::Level::Debug), EnabledStatus::NotConfigured ); assert_eq!( - map.is_enabled(&scope_new(&["a", "b"]), log::Level::Debug), + map.is_enabled(&scope_new(&["a", "b"]), None, log::Level::Debug), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_new(&["a", "b", "c"]), log::Level::Trace), + map.is_enabled(&scope_new(&["a", "b", "c"]), None, log::Level::Trace), EnabledStatus::Disabled ); @@ -548,20 +592,20 @@ mod tests { assert_eq!(map.entries[4].scope, "q"); assert_eq!(map.entries[5].scope, "u"); assert_eq!( - map.is_enabled(&scope_new(&["a", "b", "c", "d"]), log::Level::Trace), + map.is_enabled(&scope_new(&["a", "b", "c", "d"]), None, log::Level::Trace), EnabledStatus::Enabled ); assert_eq!( - map.is_enabled(&scope_new(&["a", "b", "c"]), log::Level::Trace), + map.is_enabled(&scope_new(&["a", "b", "c"]), None, log::Level::Trace), EnabledStatus::Disabled ); assert_eq!( - map.is_enabled(&scope_new(&["u", "v"]), log::Level::Warn), + map.is_enabled(&scope_new(&["u", "v"]), None, log::Level::Warn), EnabledStatus::Disabled ); // settings override env assert_eq!( - map.is_enabled(&scope_new(&["e", "f", "g", "h"]), log::Level::Trace), + map.is_enabled(&scope_new(&["e", "f", "g", "h"]), None, log::Level::Trace), EnabledStatus::Disabled, ); } diff --git a/crates/zlog/src/sink.rs b/crates/zlog/src/sink.rs index 96a3b5750a..edf2398a0e 100644 --- a/crates/zlog/src/sink.rs +++ b/crates/zlog/src/sink.rs @@ -257,6 +257,7 @@ mod tests { assert_eq!(size.load(Ordering::Relaxed), 0); } + /// Regression test, ensuring that if log level values change we are made aware #[test] fn test_log_level_names() { assert_eq!(LEVEL_OUTPUT_STRINGS[log::Level::Error as usize], "ERROR"); diff --git a/crates/zlog/src/zlog.rs b/crates/zlog/src/zlog.rs index 6c34f164d8..aed051e106 100644 --- a/crates/zlog/src/zlog.rs +++ b/crates/zlog/src/zlog.rs @@ -43,28 +43,28 @@ impl log::Log for Zlog { if !self.enabled(record.metadata()) { return; } - let scope = match record.module_path_static() { + let (crate_name_scope, module_scope) = match record.module_path_static() { Some(module_path) => { - // TODO: better module name -> scope translation let crate_name = private::extract_crate_name_from_module_path(module_path); - private::scope_new(&[crate_name]) + let crate_name_scope = private::scope_new(&[crate_name]); + let module_scope = private::scope_new(&[module_path]); + (crate_name_scope, module_scope) } // TODO: when do we hit this - None => private::scope_new(&["*unknown*"]), + None => (private::scope_new(&[]), private::scope_new(&["*unknown*"])), }; let level = record.metadata().level(); - if !filter::is_scope_enabled(&scope, level) { + if !filter::is_scope_enabled(&crate_name_scope, record.module_path(), level) { return; } sink::submit(sink::Record { - scope, + scope: module_scope, level, message: record.args(), }); } fn flush(&self) { - // todo: necessary? sink::flush(); } } @@ -74,7 +74,7 @@ macro_rules! log { ($logger:expr, $level:expr, $($arg:tt)+) => { let level = $level; let logger = $logger; - let enabled = $crate::filter::is_scope_enabled(&logger.scope, level); + let enabled = $crate::filter::is_scope_enabled(&logger.scope, Some(module_path!()), level); if enabled { $crate::sink::submit($crate::sink::Record { scope: logger.scope, @@ -143,7 +143,7 @@ macro_rules! error { /// However, this is a feature not a bug, as it allows for a more accurate /// understanding of how long the action actually took to complete, including /// interruptions, which can help explain why something may have timed out, -/// why it took longer to complete than it would had the await points resolved +/// why it took longer to complete than it would have had the await points resolved /// immediately, etc. #[macro_export] macro_rules! time { @@ -168,15 +168,7 @@ macro_rules! scoped { if index >= scope.len() { #[cfg(debug_assertions)] { - panic!("Scope overflow trying to add scope {}", name); - } - #[cfg(not(debug_assertions))] - { - $crate::warn!( - parent => - "Scope overflow trying to add scope {}... ignoring scope", - name - ); + unreachable!("Scope overflow trying to add scope... ignoring scope"); } } scope[index] = name; @@ -208,17 +200,31 @@ macro_rules! crate_name { pub mod private { use super::*; - pub fn extract_crate_name_from_module_path(module_path: &'static str) -> &'static str { - return module_path - .split_once("::") - .map(|(crate_name, _)| crate_name) - .unwrap_or(module_path); + pub const fn extract_crate_name_from_module_path(module_path: &'static str) -> &'static str { + let mut i = 0; + let mod_path_bytes = module_path.as_bytes(); + let mut index = mod_path_bytes.len(); + while i + 1 < mod_path_bytes.len() { + if mod_path_bytes[i] == b':' && mod_path_bytes[i + 1] == b':' { + index = i; + break; + } + i += 1; + } + let Some((crate_name, _)) = module_path.split_at_checked(index) else { + return module_path; + }; + return crate_name; } - pub fn scope_new(scopes: &[&'static str]) -> Scope { + pub const fn scope_new(scopes: &[&'static str]) -> Scope { assert!(scopes.len() <= SCOPE_DEPTH_MAX); let mut scope = [""; SCOPE_DEPTH_MAX]; - scope[0..scopes.len()].copy_from_slice(scopes); + let mut i = 0; + while i < scopes.len() { + scope[i] = scopes[i]; + i += 1; + } scope } @@ -244,6 +250,31 @@ pub struct Logger { pub scope: Scope, } +impl log::Log for Logger { + fn enabled(&self, metadata: &log::Metadata) -> bool { + filter::is_possibly_enabled_level(metadata.level()) + } + + fn log(&self, record: &log::Record) { + if !self.enabled(record.metadata()) { + return; + } + let level = record.metadata().level(); + if !filter::is_scope_enabled(&self.scope, record.module_path(), level) { + return; + } + sink::submit(sink::Record { + scope: self.scope, + level, + message: record.args(), + }); + } + + fn flush(&self) { + sink::flush(); + } +} + pub struct Timer { pub logger: Logger, pub start_time: std::time::Instant, @@ -269,6 +300,7 @@ impl Timer { done: false, }; } + pub fn warn_if_gt(mut self, warn_limit: std::time::Duration) -> Self { self.warn_if_longer_than = Some(warn_limit); return self; @@ -313,5 +345,21 @@ mod tests { #[test] fn test_crate_name() { assert_eq!(crate_name!(), "zlog"); + assert_eq!( + private::extract_crate_name_from_module_path("my_speedy_⚡️_crate::some_module"), + "my_speedy_⚡️_crate" + ); + assert_eq!( + private::extract_crate_name_from_module_path("my_speedy_crate_⚡️::some_module"), + "my_speedy_crate_⚡️" + ); + assert_eq!( + private::extract_crate_name_from_module_path("my_speedy_crate_:⚡️:some_module"), + "my_speedy_crate_:⚡️:some_module" + ); + assert_eq!( + private::extract_crate_name_from_module_path("my_speedy_crate_::⚡️some_module"), + "my_speedy_crate_" + ); } }