[PATCH proxmox 3/5] log: add tests to the logger

[Thomas Ellmenreich <t.ellmenreich@proxmox.com>]

Add tests to ensure consistent functionality when setting the logging
environment variable, as well as global filtering of logs.

Although the EnvFilter itself is not something we should be testing, we are
adding some additional machinery, on top of the extensive functionality
provided by tracing/tracing_subscriber, which does need testing.

Signed-off-by: Thomas Ellmenreich <t.ellmenreich@proxmox.com>
---
 proxmox-log/src/builder.rs | 296 ++++++++++++++++++++++++++++++++++++-
 1 file changed, 291 insertions(+), 5 deletions(-)

diff --git a/proxmox-log/src/builder.rs b/proxmox-log/src/builder.rs
index 9b545603..05da3643 100644
--- a/proxmox-log/src/builder.rs
+++ b/proxmox-log/src/builder.rs
@@ -1,5 +1,6 @@
 use tracing::Level;
 use tracing::Metadata;
+use tracing::Subscriber;
 use tracing::level_filters::LevelFilter;
 use tracing_log::LogTracer;
 use tracing_subscriber::EnvFilter;
@@ -10,8 +11,8 @@ use tracing_subscriber::layer::Filter;
 use tracing_subscriber::layer::SubscriberExt;
 
 use crate::{
-    LogContext, journald_or_stderr_layer, plain_stderr_layer,
-    pve_task_formatter::PveTaskFormatter, tasklog_layer::TasklogLayer,
+    LogContext, journald_or_stderr_layer, plain_stderr_layer, pve_task_formatter::PveTaskFormatter,
+    tasklog_layer::TasklogLayer,
 };
 ///
 /// Filter yielding `true` *outside* of worker tasks, *unless* the level is `ERROR`.
@@ -136,9 +137,7 @@ impl Logger {
     ///
     /// Also configures the `LogTracer` which will convert all `log` events to tracing events.
     pub fn init(self) -> Result<(), anyhow::Error> {
-        let registry = tracing_subscriber::registry()
-            .with(self.layer)
-            .with(self.global_log_level);
+        let registry = self.create_subscriber();
 
         tracing::subscriber::set_global_default(registry)?;
 
@@ -146,6 +145,15 @@ impl Logger {
         Ok(())
     }
 
+    /// Creates the subscriber to be used for the Logger
+    ///
+    /// Placed in its own method to allow easier testing of the subscriber
+    fn create_subscriber(self) -> impl Subscriber {
+        tracing_subscriber::registry()
+            .with(self.layer)
+            .with(self.global_log_level)
+    }
+
     /// If present, tries to parse the `env_filter_str` as a [`EnvFilter`],
     /// otherwiese falls back to the provided default log level.
     ///
@@ -170,3 +178,281 @@ impl Logger {
     }
 }
 
+#[cfg(test)]
+mod tests {
+    use std::sync::{Arc, Mutex};
+
+    use tracing::level_filters::LevelFilter;
+    use tracing_log::log;
+    use tracing_subscriber::{Layer, util::SubscriberInitExt};
+
+    use crate::Logger;
+
+    /// Modules created for testing purposes. Specifically, to test filtering
+    /// of logs in different modules.
+    mod test_module {
+        pub mod nested_module {
+            pub fn info(message: &'static str) {
+                tracing_log::log::info!("{message}");
+            }
+        }
+        pub fn info(message: &'static str) {
+            tracing_log::log::info!("{message}");
+        }
+    }
+
+    macro_rules! assert_logs {
+        ($events:expr, [$($expected:expr),* $(,)?]) => {{
+            let events = $events.lock().unwrap();
+
+            assert_eq!(events.as_slice(), [$($expected),*]);
+        }};
+    }
+
+    #[test]
+    fn logger_builder_correctly_applies_filter() {
+        // Arrange
+        let (events, builder) = create_logger(Some("WARN"), LevelFilter::INFO);
+        let _guard = builder.create_subscriber().set_default();
+
+        // Act
+        log::info!("log1");
+        log::warn!("log2");
+
+        // Assert
+        assert_logs!(events, ["log2"]);
+    }
+
+    #[test]
+    fn simple_log_is_registered() {
+        // Arrange
+        let (events, _guard) = setup_logging(None, LevelFilter::TRACE);
+
+        // Act
+        log::info!("log1");
+
+        // Assert
+        assert_logs!(events, ["log1"]);
+    }
+
+    #[test]
+    fn env_filter_is_backwards_compatible() {
+        // Arrange
+        let (events, _guard) = setup_logging(Some("ERROR"), LevelFilter::INFO);
+
+        // Act
+        test_module::info("log1");
+        test_module::nested_module::info("log2");
+        log::error!("log3");
+
+        // Assert
+        assert_logs!(events, ["log3"]);
+    }
+
+    #[test]
+    fn only_module_filter_disables_other_logging() {
+        // Arrange
+        let (events, _guard) = setup_logging(
+            Some("proxmox_log::builder::tests::test_module=INFO"),
+            LevelFilter::INFO,
+        );
+
+        // Act
+        test_module::info("log1");
+        test_module::nested_module::info("log2");
+        log::info!("log3");
+
+        // Assert
+        assert_logs!(events, ["log1", "log2"]);
+    }
+
+    #[test]
+    fn nested_module_filter_correctly_removes_logs_from_nested_module() {
+        // Arrange
+        let (events, _guard) = setup_logging(
+            Some(
+                "proxmox_log::builder::tests::test_module=INFO,proxmox_log::builder::tests::test_module::nested_module=ERROR",
+            ),
+            LevelFilter::INFO,
+        );
+
+        // Act
+        test_module::info("log1");
+        test_module::nested_module::info("log2");
+
+        // Assert
+        assert_logs!(events, ["log1",]);
+    }
+
+    #[test]
+    fn empty_variable_turns_off_all_logging() {
+        // Arrange
+        let (events, _guard) = setup_logging(Some(""), LevelFilter::TRACE);
+
+        // Act
+        log::trace!("log1");
+        log::debug!("log2");
+        log::info!("log3");
+        log::warn!("log4");
+        log::error!("log5");
+
+        // Assert
+        let list = events.lock().unwrap();
+        assert!(list.is_empty());
+    }
+
+    #[test]
+    fn gibberish_filter_allows_use_of_fallback() {
+        // Arrange
+        let (events, _guard) = setup_logging(
+            Some("SNERROR,::_interesting*Üpath::we;HAVE=QUARNING"),
+            LevelFilter::ERROR,
+        );
+
+        // Act
+        log::info!("log1");
+        log::error!("log2");
+
+        // Assert
+        assert_logs!(events, ["log2"]);
+    }
+
+    #[test]
+    fn setting_default_in_variable_is_adopted_as_default() {
+        // Arrange
+        let (events, _guard) = setup_logging(
+            Some("ERROR,proxmox_log::builder::tests::test_module::nested_module=INFO"),
+            LevelFilter::INFO,
+        );
+
+        // Act
+        test_module::info("log1");
+        test_module::nested_module::info("log2");
+        log::error!("log3");
+
+        assert_logs!(events, ["log2", "log3"]);
+    }
+
+    /// Creates a [`Logger`] with a [`crate::builder::tests::TestLayer`]
+    /// inserted so that any logs received can be monitored through the
+    /// returned Vec of strings.
+    /// * `var_filter` - The log settings that would usually be written into
+    ///                  a environment variable and then extracted by the [`Logger`]
+    /// * `default_log_level` - Default log level used by the [`Logger`] in
+    ///                         case the log settings are empty.
+    fn create_logger(
+        var_filter: Option<&'static str>,
+        default_log_level: LevelFilter,
+    ) -> (Arc<Mutex<Vec<String>>>, Logger) {
+        let (events, test_layer) = TestLayer::no_filter();
+        (
+            events,
+            Logger {
+                global_log_level: Logger::apply_default_log_level(
+                    var_filter.map(str::to_string),
+                    default_log_level,
+                ),
+                layer: vec![test_layer.boxed()],
+            },
+        )
+    }
+
+    /// Sets up logging in a way that allows the filter to act, and then
+    /// records every log that is let through in a Vec of strings. Returns
+    /// said Vec of strings as well as a guard that allows tracing to capture
+    /// logs while it's not dropped.
+    /// * `var_filter` - The log settings that would usually be written into
+    ///                  a environment variable and then extracted by the [`Logger`]
+    /// * `default_log_level` - Default log level used by the [`Logger`] in
+    ///                         case the log settings are empty.
+    fn setup_logging(
+        var_filter: Option<&'static str>,
+        default_log_level: LevelFilter,
+    ) -> (Arc<Mutex<Vec<String>>>, tracing::subscriber::DefaultGuard) {
+        use tracing_subscriber::layer::SubscriberExt;
+
+        let filter =
+            Logger::apply_default_log_level(var_filter.map(str::to_string), default_log_level);
+
+        let (events, filter) = TestLayer::new(filter);
+        let guard = tracing_subscriber::Registry::default()
+            .with(filter)
+            .set_default();
+        (events, guard)
+    }
+
+    pub(crate) struct TestLayer {
+        events: Arc<Mutex<Vec<String>>>,
+        filter: Option<tracing_subscriber::EnvFilter>,
+    }
+
+    impl TestLayer {
+        pub(crate) fn no_filter() -> (Arc<Mutex<Vec<String>>>, Self) {
+            let events = Arc::new(Mutex::new(vec![]));
+            (
+                Arc::clone(&events),
+                Self {
+                    events,
+                    filter: None,
+                },
+            )
+        }
+
+        pub(crate) fn new(
+            filter: tracing_subscriber::EnvFilter,
+        ) -> (Arc<Mutex<Vec<String>>>, Self) {
+            let events = Arc::new(Mutex::new(vec![]));
+            (
+                Arc::clone(&events),
+                Self {
+                    events,
+                    filter: Some(filter),
+                },
+            )
+        }
+    }
+
+    impl<S> tracing_subscriber::Layer<S> for TestLayer
+    where
+        S: tracing::Subscriber,
+    {
+        /// adds events to the Vec of Strings
+        fn on_event(
+            &self,
+            event: &tracing::Event<'_>,
+            _: tracing_subscriber::layer::Context<'_, S>,
+        ) {
+            struct Visitor(Option<String>);
+
+            impl tracing::field::Visit for Visitor {
+                fn record_debug(
+                    &mut self,
+                    field: &tracing::field::Field,
+                    value: &dyn std::fmt::Debug,
+                ) {
+                    if field.name() == "message" {
+                        self.0 = Some(format!("{value:?}"));
+                    }
+                }
+            }
+
+            let mut visitor = Visitor(None);
+            event.record(&mut visitor);
+            let message = visitor.0.unwrap_or_default();
+
+            self.events.lock().unwrap().push(message);
+        }
+
+        /// applies the filter to the logs
+        fn enabled(
+            &self,
+            metadata: &tracing::Metadata<'_>,
+            ctx: tracing_subscriber::layer::Context<'_, S>,
+        ) -> bool {
+            self.filter
+                .as_ref()
+                .map(|filter| filter.enabled(metadata, ctx))
+                .unwrap_or(true)
+        }
+    }
+}
-- 
2.47.3