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:🅰️:b` modules, but `crate::a=trace` will not enable trace
messages in module `crate:🅰️: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
This commit is contained in:
Ben Kunkle 2025-04-21 11:43:24 -04:00 committed by GitHub
parent f8ac6eef75
commit d13cd007a2
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
4 changed files with 211 additions and 118 deletions

View file

@ -18,12 +18,12 @@ pub fn parse(filter: &str) -> Result<EnvFilter> {
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;
};

View file

@ -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<env_config::EnvFilter> = OnceLock::new();
static SCOPE_MAP: RwLock<Option<GlobalScopeMap>> = RwLock::new(None);
struct GlobalScopeMap {
map: ScopeMap,
hash: u64,
}
static SCOPE_MAP: RwLock<Option<ScopeMap>> = 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<String, String>) -> u64 {
let mut hasher = DefaultHasher::new();
let mut items = map.iter().collect::<Vec<_>>();
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<String, String>) {
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<log::Level> {
fn level_filter_from_str(level_str: &String) -> Option<log::LevelFilter> {
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<ScopeAlloc> {
return Some(scope);
}
#[derive(PartialEq, Eq)]
pub struct ScopeMap {
entries: Vec<ScopeMapEntry>,
modules: Vec<(String, log::LevelFilter)>,
root_count: usize,
}
#[derive(PartialEq, Eq)]
pub struct ScopeMapEntry {
scope: String,
enabled: Option<log::Level>,
enabled: Option<log::LevelFilter>,
descendants: std::ops::Range<usize>,
}
@ -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<S>(&self, scope: &[S; SCOPE_DEPTH_MAX], level: log::Level) -> EnabledStatus
pub fn is_enabled<S>(
&self,
scope: &[S; SCOPE_DEPTH_MAX],
module_path: Option<&str>,
level: log::Level,
) -> EnabledStatus
where
S: AsRef<str>,
{
@ -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<String, String> = 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,
);
}

View file

@ -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");

View file

@ -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_"
);
}
}