From db08b466b2dd337f256fe6fafbbccf8960625455 Mon Sep 17 00:00:00 2001 From: Ximon Eighteen <3304436+ximon18@users.noreply.github.com> Date: Wed, 17 Mar 2021 13:42:45 +0100 Subject: [PATCH] FIX: Don't log DEBUG level messages when log_level is set to 'info' (fixes #434). (#435) --- src/daemon/config.rs | 177 +++++++++++++++++++++++++++++++++++++------ 1 file changed, 154 insertions(+), 23 deletions(-) diff --git a/src/daemon/config.rs b/src/daemon/config.rs index 8b392d01..1e249cd3 100644 --- a/src/daemon/config.rs +++ b/src/daemon/config.rs @@ -723,33 +723,16 @@ impl Config { /// Creates and returns a fern logger with log level tweaks fn fern_logger(&self) -> fern::Dispatch { - let framework_level = match self.log_level { - LevelFilter::Off => LevelFilter::Off, - LevelFilter::Error => LevelFilter::Error, - _ => LevelFilter::Warn, // more becomes too noisy - }; - - let krill_framework_level = match self.log_level { - LevelFilter::Off => LevelFilter::Off, - LevelFilter::Error => LevelFilter::Error, - LevelFilter::Warn => LevelFilter::Warn, - _ => LevelFilter::Debug, // more becomes too noisy - }; + // suppress overly noisy logging + let framework_level = self.log_level.min(LevelFilter::Warn); + let krill_framework_level = self.log_level.min(LevelFilter::Debug); // disable Oso logging unless the Oso specific POLAR_LOG environment // variable is set, it's too noisy otherwise let oso_framework_level = if env::var("POLAR_LOG").is_ok() { - match self.log_level { - LevelFilter::Trace => LevelFilter::Trace, - _ => LevelFilter::Debug, // at least debug - } + self.log_level.min(LevelFilter::Trace) } else { - match self.log_level { - LevelFilter::Off => LevelFilter::Off, - LevelFilter::Error => LevelFilter::Error, - LevelFilter::Warn => LevelFilter::Warn, - _ => LevelFilter::Info, // more becomes too noisy - } + self.log_level.min(LevelFilter::Info) }; let show_target = self.log_level == LevelFilter::Trace || self.log_level == LevelFilter::Debug; @@ -928,16 +911,164 @@ impl<'de> Deserialize<'de> for AuthType { mod tests { use super::*; + use std::env; #[test] fn should_parse_default_config_file() { // Config for auth token is required! If there is nothing in the conf // file, then an environment variable must be set. - use std::env; env::set_var(KRILL_ENV_AUTH_TOKEN, "secret"); let c = Config::read_config("./defaults/krill.conf").unwrap(); let expected_socket_addr: SocketAddr = ([127, 0, 0, 1], 3000).into(); assert_eq!(c.socket_addr(), expected_socket_addr); } + + #[test] + fn should_set_correct_log_levels() { + use log::Level as LL; + + fn void_logger_from_krill_config(config_bytes: &[u8]) -> Box { + let c: Config = toml::from_slice(config_bytes).unwrap(); + let void_output = fern::Output::writer(Box::new(io::sink()), ""); + let (_, void_logger) = c.fern_logger().chain(void_output).into_log(); + void_logger + } + + fn for_target_at_level(target: &str, level: LL) -> log::Metadata { + log::Metadata::builder().target(target).level(level).build() + } + + fn should_logging_be_enabled_at_this_krill_config_log_level(log_level: &LL, config_level: &str) -> bool { + let log_level_from_krill_config_level = LL::from_str(config_level).unwrap(); + log_level <= &log_level_from_krill_config_level + } + + // Krill requires an auth token to be defined, give it one in the environment + env::set_var(KRILL_ENV_AUTH_TOKEN, "secret"); + + // Define sets of log targets aka components of Krill that we want to test log settings for, based on the + // rules & exceptions that the actual code under test is supposed to configure the logger with + let krill_components = vec!["krill"]; + let krill_framework_components = vec!["krill::commons::eventsourcing", "krill::commons::util::file"]; + let other_key_components = vec!["hyper", "reqwest", "oso"]; + + let krill_key_components = vec![krill_components, krill_framework_components.clone()] + .into_iter() + .flatten() + .collect::>(); + let all_key_components = vec![krill_key_components.clone(), other_key_components] + .into_iter() + .flatten() + .collect::>(); + + // + // Test that important log levels are enabled for all key components + // + + // for each important Krill config log level + for config_level in &["error", "warn"] { + // build a logger for that config + let log = void_logger_from_krill_config(format!(r#"log_level = "{}""#, config_level).as_bytes()); + + // for all log levels + for log_msg_level in &[LL::Error, LL::Warn, LL::Info, LL::Debug, LL::Trace] { + // determine if logging should be enabled or not + let should_be_enabled = + should_logging_be_enabled_at_this_krill_config_log_level(log_msg_level, config_level); + + // for each Krill component we want to pretend to log as + for component in &all_key_components { + // verify that logging is enabled or not as expected + assert_eq!( + should_be_enabled, + log.enabled(&for_target_at_level(component, *log_msg_level)), + // output an easy to understand test failure description + "Logging at level {} with log_level={} should be {} for component {}", + log_msg_level, + config_level, + if should_be_enabled { "enabled" } else { "disabled" }, + component + ); + } + } + } + + // + // Test that info level and below are only enabled for Krill at the right log levels + // + + // for each Krill config log level we want to test + for config_level in &["info", "debug", "trace"] { + // build a logger for that config + let log = void_logger_from_krill_config(format!(r#"log_level = "{}""#, config_level).as_bytes()); + + // for each level of interest that messages could be logged at + for log_msg_level in &[LL::Info, LL::Debug, LL::Trace] { + // determine if logging should be enabled or not + let should_be_enabled = + should_logging_be_enabled_at_this_krill_config_log_level(log_msg_level, config_level); + + // for each Krill component we want to pretend to log as + for component in &krill_key_components { + // framework components shouldn't log at Trace level + let should_be_enabled = should_be_enabled + && (*log_msg_level < LL::Trace || !krill_framework_components.contains(&component)); + + // verify that logging is enabled or not as expected + assert_eq!( + should_be_enabled, + log.enabled(&for_target_at_level(component, *log_msg_level)), + // output an easy to understand test failure description + "Logging at level {} with log_level={} should be {} for component {}", + log_msg_level, + config_level, + if should_be_enabled { "enabled" } else { "disabled" }, + component + ); + } + } + } + + // + // Test that Oso logging at levels below Info is only enabled if the Oso POLAR_LOG=1 + // environment variable is set + // + let component = "oso"; + for set_polar_log_env_var in &[true, false] { + // setup env vars + if *set_polar_log_env_var { + env::set_var("POLAR_LOG", "1"); + } else { + env::remove_var("POLAR_LOG"); + } + + // for each Krill config log level we want to test + for config_level in &["debug", "trace"] { + // build a logger for that config + let log = void_logger_from_krill_config(format!(r#"log_level = "{}""#, config_level).as_bytes()); + + // for each level of interest that messages could be logged at + for log_msg_level in &[LL::Debug, LL::Trace] { + // determine if logging should be enabled or not + let should_be_enabled = + should_logging_be_enabled_at_this_krill_config_log_level(log_msg_level, config_level) + && *set_polar_log_env_var; + + // verify that logging is enabled or not as expected + assert_eq!( + should_be_enabled, + log.enabled(&for_target_at_level(component, *log_msg_level)), + // output an easy to understand test failure description + r#"Logging at level {} with log_level={} should be {} for component {} and env var POLAR_LOG is {}"#, + log_msg_level, + config_level, + if should_be_enabled { "enabled" } else { "disabled" }, + component, + if *set_polar_log_env_var { "set" } else { "not set" } + ); + } + } + } + } }