changed logger logic for enable reseting

.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: |

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);
 }

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"

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<Option<WorkerGuard>> = 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<Layer<Registry>, LevelFilter, Registry>;
+// A Reloadable pair of layer-filter
+type InnerLayered = Layered<reload::Layer<InnerFiltered, Registry>, Registry>;
+// A reloadable layer of subscriber to a rolling file
+type FileReload = Handle<
+    Filtered<
+        Layer<InnerLayered, DefaultFields, Format, RollingFileAppender>,
+        LevelFilter,
+        InnerLayered,
+    >,
+    InnerLayered,
+>;
+
+pub struct Reloads {
+    console_reload: RwLock<reload::Handle<InnerFiltered, Registry>>,
+    file_reload: RwLock<FileReload>,
+}
+
+pub struct InitiateOnce {
+    init_once: OnceCell<Reloads>,
+}
+
+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::Compact> {
-    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<Level>, 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!(

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")
+    }
+}