From d9fab8a09b5fc7b7899b19821b8ebb0bc8412927 Mon Sep 17 00:00:00 2001 From: avifenesh Date: Mon, 10 Jul 2023 08:45:23 +0000 Subject: [PATCH] changed logger logic for enable reseting --- .github/workflows/rust.yml | 4 + babushka-core/tests/utilities/mod.rs | 2 +- logger_core/Cargo.toml | 6 +- logger_core/src/lib.rs | 169 +++++++++++++++++---------- logger_core/tests/test_logger.rs | 97 +++++++++++++++ 5 files changed, 216 insertions(+), 62 deletions(-) create mode 100644 logger_core/tests/test_logger.rs diff --git a/.github/workflows/rust.yml b/.github/workflows/rust.yml index a2c3e2b385..75454750f5 100644 --- a/.github/workflows/rust.yml +++ b/.github/workflows/rust.yml @@ -55,6 +55,10 @@ jobs: working-directory: ./babushka-core run: cargo test -- --nocapture --test-threads=1 # TODO remove the concurrency limit after we fix test flakyness. + - name: Run logger tests + working-directory: ./logger_core + run: cargo test -- --nocapture --test-threads=1 + - name: Check features working-directory: ./babushka-core run: | diff --git a/babushka-core/tests/utilities/mod.rs b/babushka-core/tests/utilities/mod.rs index 81abe7a938..e1712b3495 100644 --- a/babushka-core/tests/utilities/mod.rs +++ b/babushka-core/tests/utilities/mod.rs @@ -560,5 +560,5 @@ pub async fn setup_test_basics(use_tls: bool) -> TestBasics { #[cfg(test)] #[ctor::ctor] fn init() { - logger_core::init_console(logger_core::Level::Debug); + logger_core::init(Some(logger_core::Level::Debug), None); } diff --git a/logger_core/Cargo.toml b/logger_core/Cargo.toml index 18ed2f9c83..bb93d724aa 100644 --- a/logger_core/Cargo.toml +++ b/logger_core/Cargo.toml @@ -6,9 +6,13 @@ license = "Apache-2.0" [lib] +[dev-dependencies] +rand = "0.8.5" +test-env-helpers = "0.2.2" [dependencies] tracing = "0.1" tracing-appender = "0.2.2" once_cell = "1.16.0" -tracing-subscriber = "0.3.16" +file-rotate = "0.7.1" +tracing-subscriber = "0.3.17" diff --git a/logger_core/src/lib.rs b/logger_core/src/lib.rs index 53cc86f638..72ff4a072a 100644 --- a/logger_core/src/lib.rs +++ b/logger_core/src/lib.rs @@ -1,14 +1,49 @@ +use once_cell::sync::OnceCell; use std::sync::RwLock; use tracing::{self, event}; -use tracing_appender::{ - non_blocking, - non_blocking::WorkerGuard, - rolling::{RollingFileAppender, Rotation}, +use tracing_appender::rolling::{RollingFileAppender, Rotation}; +use tracing_subscriber::{ + filter::Filtered, + fmt::{ + format::{DefaultFields, Format}, + Layer, + }, + layer::Layered, + Registry, }; -use tracing_subscriber::{self, filter::LevelFilter}; -// Guard is in charge of making sure that the logs been collected when program stop -pub static GUARD: RwLock> = RwLock::new(None); +use tracing_subscriber::{ + self, + filter::{self, LevelFilter}, + prelude::*, + reload::{self, Handle}, +}; +// Layer-Filter pair determines whether a log will be collected +type InnerFiltered = Filtered, LevelFilter, Registry>; +// A Reloadable pair of layer-filter +type InnerLayered = Layered, Registry>; +// A reloadable layer of subscriber to a rolling file +type FileReload = Handle< + Filtered< + Layer, + LevelFilter, + InnerLayered, + >, + InnerLayered, +>; + +pub struct Reloads { + console_reload: RwLock>, + file_reload: RwLock, +} + +pub struct InitiateOnce { + init_once: OnceCell, +} + +pub static INITIATE_ONCE: InitiateOnce = InitiateOnce { + init_once: OnceCell::new(), +}; #[derive(Debug)] pub enum Level { @@ -19,7 +54,7 @@ pub enum Level { Trace = 4, } impl Level { - fn to_filter(&self) -> LevelFilter { + fn to_filter(&self) -> filter::LevelFilter { match self { Level::Trace => LevelFilter::TRACE, Level::Debug => LevelFilter::DEBUG, @@ -30,59 +65,74 @@ impl Level { } } -fn tracing_format( -) -> tracing_subscriber::fmt::format::Format { - tracing_subscriber::fmt::format() - .with_source_location(false) - .with_target(false) - .compact() -} - -// Initialize a logger that writes the received logs to a file under the babushka-logs folder. -// The file name will be prefixed with the current timestamp, and will be replaced every hour. -// This logger doesn't block the calling thread, and will save only logs of the given level or above. -pub fn init_file(minimal_level: Level, file_name: &str) -> Level { - let file_appender = RollingFileAppender::new(Rotation::HOURLY, "babushka-logs", file_name); - let (non_blocking, _guard) = non_blocking(file_appender); - let mut guard = GUARD.write().unwrap(); - *guard = Some(_guard); - let level_filter = minimal_level.to_filter(); - let _ = tracing::subscriber::set_global_default( - tracing_subscriber::fmt() - .event_format(tracing_format()) - .with_max_level(level_filter) - .with_writer(non_blocking) - .finish(), - ); - minimal_level -} - -// Initialize the global logger so that it will write the received logs to a file under the babushka-logs folder. -// The file name will be prefixed with the current timestamp, and will be replaced every hour. -// The logger doesn't block the calling thread, and will save only logs of the given level or above. -pub fn init_console(minimal_level: Level) -> Level { - let level_filter = minimal_level.to_filter(); - let (non_blocking, _guard) = tracing_appender::non_blocking(std::io::stdout()); - let mut guard = GUARD.write().unwrap(); - *guard = Some(_guard); - let _ = tracing::subscriber::set_global_default( - tracing_subscriber::fmt() - .event_format(tracing_format()) - .with_writer(non_blocking) - .with_max_level(level_filter) - .finish(), - ); - minimal_level -} - -// Initialize the global logger so that it will write the received logs to the console. +// Initialize the global logger to error level on the first call only +// In any of the calls to the function, including the first - resetting the existence loggers to the new setting +// provided by using the global reloadable handle // The logger will save only logs of the given level or above. pub fn init(minimal_level: Option, file_name: Option<&str>) -> Level { let level = minimal_level.unwrap_or(Level::Warn); + let level_filter = level.to_filter(); + let reloads = INITIATE_ONCE.init_once.get_or_init(|| { + let stdout_fmt = tracing_subscriber::fmt::layer() + .with_ansi(true) + .with_filter(LevelFilter::OFF); + + let (stdout_layer, stdout_reload) = reload::Layer::new(stdout_fmt); + + let file_appender = RollingFileAppender::new( + Rotation::HOURLY, + "babushka-logs", + file_name.unwrap_or("output.log"), + ); + let file_fmt = tracing_subscriber::fmt::layer() + .with_writer(file_appender) + .with_filter(LevelFilter::OFF); + let (file_layer, file_reload) = reload::Layer::new(file_fmt); + tracing_subscriber::registry() + .with(stdout_layer) + .with(file_layer) + .init(); + + let reloads: Reloads = Reloads { + console_reload: RwLock::new(stdout_reload), + file_reload: RwLock::new(file_reload), + }; + reloads + }); + match file_name { - None => init_console(level), - Some(file) => init_file(level, file), - } + None => { + let _ = reloads + .console_reload + .write() + .expect("error reloading stdout") + .modify(|layer| (*layer.filter_mut() = level_filter)); + let _ = reloads + .file_reload + .write() + .expect("error reloading file appender") + .modify(|layer| { + *layer.filter_mut() = LevelFilter::OFF; + }); + } + Some(file) => { + let file_appender = RollingFileAppender::new(Rotation::HOURLY, "babushka-logs", file); + let _ = reloads + .file_reload + .write() + .expect("error reloading file appender") + .modify(|layer| { + *layer.filter_mut() = level_filter; + *layer.inner_mut().writer_mut() = file_appender; + }); + let _ = reloads + .console_reload + .write() + .expect("error reloading stdout") + .modify(|layer| (*layer.filter_mut() = LevelFilter::OFF)); + } + }; + level } macro_rules! create_log { @@ -91,10 +141,9 @@ macro_rules! create_log { log_identifier: Identifier, message: Message, ) { - if GUARD.read().unwrap().is_none() { - init(None, None); + if INITIATE_ONCE.init_once.get().is_none() { + init(Some(Level::Warn), None); }; - let message_ref = message.as_ref(); let identifier_ref = log_identifier.as_ref(); event!( diff --git a/logger_core/tests/test_logger.rs b/logger_core/tests/test_logger.rs new file mode 100644 index 0000000000..e0b4c9ae9a --- /dev/null +++ b/logger_core/tests/test_logger.rs @@ -0,0 +1,97 @@ +use test_env_helpers::*; + +#[cfg(test)] +#[after_all] +#[cfg(test)] +mod tests { + use logger_core::{init, log_debug, log_trace}; + use rand::{distributions::Alphanumeric, Rng}; + use std::fs::{read_dir, read_to_string, remove_dir_all}; + const FILE_DIRECTORY: &str = "babushka-logs"; + + fn generate_random_string(length: usize) -> String { + rand::thread_rng() + .sample_iter(&Alphanumeric) + .take(length) + .map(char::from) + .collect() + } + + fn get_file_contents(file_name: &str) -> String { + let files = read_dir(FILE_DIRECTORY).unwrap(); + let file = files + .into_iter() + .find(|path| { + path.as_ref() + .unwrap() + .path() + .file_name() + .unwrap() + .to_str() + .unwrap() + .starts_with(file_name) + }) + .unwrap(); + read_to_string(file.unwrap().path()).unwrap() + } + + #[test] + fn log_to_console_works_after_multiple_inits_diff_log_level() { + let identifier = generate_random_string(10); + init(Some(logger_core::Level::Trace), None); + init(Some(logger_core::Level::Debug), None); + // you should see in the console something like '2023-07-07T06:57:54.446236Z DEBUG logger_core: e49NaJ5J41 - foo' + log_debug(identifier.clone(), "foo"); + // make sure that something like '2023-07-07T06:57:54.446236Z DEBUG logger_core: e49NaJ5J41 - boo' does not appear + log_trace(identifier, "boo"); + } + + #[test] + fn log_to_file_works_after_multiple_inits() { + let identifier = generate_random_string(10); + init(Some(logger_core::Level::Trace), Some(identifier.as_str())); + init(Some(logger_core::Level::Debug), Some(identifier.as_str())); + log_debug(identifier.clone(), "foo"); + let contents = get_file_contents(identifier.as_str()); + assert!( + contents.contains(identifier.as_str()), + "Contens: {}", + contents + ); + assert!(contents.contains("foo"), "Contens: {}", contents); + } + + #[test] + fn log_to_file_works_after_console_init() { + let identifier = generate_random_string(10); + init(Some(logger_core::Level::Trace), None); + init(Some(logger_core::Level::Trace), Some(identifier.as_str())); + let identifier = generate_random_string(10); + init(Some(logger_core::Level::Debug), Some(identifier.as_str())); + log_debug(identifier.clone(), "foo"); + log_trace(identifier.clone(), "boo"); + let contents = get_file_contents(identifier.as_str()); + assert!( + contents.contains(identifier.as_str()), + "Contens: {}", + contents + ); + assert!(contents.contains("foo"), "Contens: {}", contents); + assert_eq!(contents.contains("boo"), false); + } + + #[test] + fn log_to_file_disabled_when_console_init() { + let identifier = generate_random_string(10); + init(Some(logger_core::Level::Trace), Some(identifier.as_str())); + init(Some(logger_core::Level::Trace), None); + // you should see in the console something like '2023-07-07T06:57:54.446236Z TRACE logger_core: e49NaJ5J41 - foo' + log_trace(identifier.clone(), "foo"); + let contents = get_file_contents(identifier.as_str()); + assert!(contents.is_empty()); + } + + fn after_all() { + remove_dir_all(FILE_DIRECTORY).expect("Cannot remove log directory") + } +}