[PATCH datacenter-manager/proxmox v2 0/7] log: allow finegrained control log levels

[PATCH datacenter-manager/proxmox v2 0/7] log: allow finegrained control log levels

[Thomas Ellmenreich]

The core of this change is a simple reinterpretation of the logging environment
variables that we are already using. Instead of parsing them as a single level
filter [0], they will now be interpreted as env filters [1]. Since the latter
can still parse all of the non erroring cases of the former, this change is
backwards compatible and will not break with any logging environment variables
that have been set.

Implementation
--------------

As Gabriel Goller proposed in this [2] Bugzilla enhancement, by using
EnvFilters [1], we can have more granular control over the logging happening in
the different Proxmox products. The first two commits do exactly this and can
thus be applied by themselves. The rest of the commits include cleanup, tests,
and some further improvements in rest server code that depended on the log
variable.

proxmox 1/7:
    A simple reordering of the logging layers. This had to be done since
    EnvFilter is currently not clonable and can thus be applied only once.
    Previously, the global filter was being applied unnecessarily often, on all
    layers and then on the tracing_log layer as well.

proxmox 2/7:
    Actual implementation of EnvFilters.

proxmox 3/7:
    Introduction of tests for our EnvFilter, parser, and constructor. This was
    initially created for me to better understand EnvFilters, but then evolved
    into tests to ensure consistent functionality with our 'default_log_level'.

proxmox 4/7:
    Simple clean up of empty structs to unit structs and unnecessarily
    explicit module paths that clutter struct definitions.

proxmox 5/7:
    Change the REST server default behaviour for setting its debug flag.
    Instead of defaulting to false, read the current log level and set it
    accordingly.

datacenter-manager 6/7:
    The REST server now reads the current log level to set its debug flag, so
    we can remove the code doing the same thing from the datacenter-manager side.

datacenter-manager 7/7:
    Replaced the PROXMOX_DEBUG environment variable by PDM_LOG, which is more
    in line with the other products. For both levels of api.

Different Log Options
---------------------

Combining the different options of the EnvFilter as well as our own default
log level, we have the following cases for logging:

1. Env contains 'simple':
    Meaning that the environment variable contains a simple 'info'... This
    means that that level is taken as the expected one.

2. Env contains 'simple', and 'module':
    Means that the env variable contains a simple log level as well as zero or
    more module specific log levels. As expected the simple level is applied
    as a default and then for the specified modules the defined levels apply.

3. Env only contains 'module':
    If the env only contains a module (or multiple), that is interpreted by
    tracing as disabling the default logging and only enabling logging for the
    module/s

4. Env is empty:
    No logs are printed at all, everything is hidden.

5. Env is not set:
    This is the only time the default comes into play, by being set as the
    default log level.

6. Env is gibberish:
    An error is printed to stderr and the default log level is used.

Notes for the Maintainer
------------------------

* To only apply the EnvFilter functionality the first two patches are the bare
  minimum, they restructure the filtering and then implement env filtering.

* Patches 3 and 4 add tests and some cleanup respectivly. Neither adds any
  functionality and they can be applied indipendently.

* Patches 5 and 6 should be applied together. No hard errors will appear if
  they are not applied together but Patch 6 epxects the REST server to set
  its own debug flag.

* Patch 7 could maybe be delayed to after the next release as it is a breaking
  change.

Future Work
-----------

Since the REST server now sets its own debug flag according to the log level,
other calls to the AcceptBuilder::debug() function can potentially be removed.
This is the case for proxmox_debug that currently does exactly what the REST
server will soon do by default.

Changelog
---------

- PATCH v1 -> v2 (thanks @Gabriel, @Lukas)
    * Also renamed the PROXMOX_DEBUG log variable into PDM_LOG for the
      privileged api, instead of only for the normal api.

    * I had previously removed the filter passed to the LogTracer, since
      LogTracer does not directly accept EnvFilter and the filter cannot
      be cloned. Now I get the max level in the EnvFilter and apply that as
      a LogTracer filter.

    * The REST server now checks the log level itself, so I removed the code
      setting the debug flag in proxmox-datacenter-manager.

    * Renamed the global_log_level to global_log_filter, as that is more
      fitting for a EnvFilter

- RFC v2 -> PATCH v1 (thanks @Lukas)
    * Split the 'proxmox 1/4' commit into two commits. Instead of mixing the
      global filter mix with the cleanup, they are now two different commits.
      To make sure that the core patches can be applied independently, the
      cleanup commit was moved to 'proxmox 3/6'.

    * Fixed some clippy warnings relating to documentation indenting.

    * Added tests that also directly call 'tracing' instead of just calling
      'log', just to confirm that both work and not just 'log'.

    * Introduced a new patch at the end, renaming the PROXMOX_DEBUG
      environment variable to PDM_LOG, as is default for all other products.

- RFC v1 -> v2
    * Removed patch 'v1 proxmox 4/5', which introduced a LoggerConfig returned
      by the Logger::init function. Deemed it unnecessary since I replaced the
      usage for it in patch 'v1 datacenter-manager 5/5' with a simple 'enabled!'
      and the idea of using it in the solution for [3] was abandoned.

    * Cleaned up this cover letter


[0]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.LevelFilter.html
[1]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html
[2]: https://bugzilla.proxmox.com/show_bug.cgi?id=6081
[3]: https://bugzilla.proxmox.com/show_bug.cgi?id=4646


proxmox:

Thomas Ellmenreich (5):
  log: replace per layer filtering with one global filter
  fix #6081: log: replace simple level filter with env filter
  log: add tests to the logger
  log: clean up of logger components
  rest-server: enable debug based on log level

 proxmox-log/Cargo.toml                |   2 +-
 proxmox-log/src/builder.rs            | 407 +++++++++++++++++++++++---
 proxmox-log/src/lib.rs                |  16 -
 proxmox-log/src/pve_task_formatter.rs |   2 +-
 proxmox-rest-server/src/connection.rs |   2 +-
 5 files changed, 370 insertions(+), 59 deletions(-)


proxmox-datacenter-manager:

Thomas Ellmenreich (2):
  api: remove manual setting of REST server debug flag
  api: rename PROXMOX_DEBUG log variable to PDM_LOG

 server/src/bin/proxmox-datacenter-api/main.rs     | 15 +++++++++------
 .../src/bin/proxmox-datacenter-privileged-api.rs  |  9 ++++++++-
 2 files changed, 17 insertions(+), 7 deletions(-)


Summary over all repositories:
  7 files changed, 387 insertions(+), 66 deletions(-)

-- 
Generated by murpp 0.12.0

[PATCH proxmox v2 1/7] log: replace per layer filtering with one global filter

[Thomas Ellmenreich]

Instead of filtering with the global filter on every layer, provide one
global filter once, as described in [0]

This is also in preparation for filters that either have to be cloned or
cannot be cloned at all, like EnvFilters* [1].

* EnvFilter can be cloned from tracing_subscriber version 0.3.20 onwards.

[0]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/layer/index.html#global-filtering
[1]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html

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

diff --git a/proxmox-log/src/builder.rs b/proxmox-log/src/builder.rs
index 6fcf1cc9..bbac7797 100644
--- a/proxmox-log/src/builder.rs
+++ b/proxmox-log/src/builder.rs
@@ -1,7 +1,8 @@
 use tracing::Level;
 use tracing::Metadata;
 use tracing::level_filters::LevelFilter;
-use tracing_log::{AsLog, LogTracer};
+use tracing_log::AsLog;
+use tracing_log::LogTracer;
 use tracing_subscriber::Layer;
 use tracing_subscriber::layer::Context;
 use tracing_subscriber::layer::Filter;
@@ -76,11 +77,7 @@ impl Logger {
     ///
     /// If the journal cannot be opened, print to stderr instead.
     pub fn journald(mut self) -> Logger {
-        self.layer.push(
-            journald_or_stderr_layer()
-                .with_filter(self.global_log_level)
-                .boxed(),
-        );
+        self.layer.push(journald_or_stderr_layer().boxed());
         self
     }
 
@@ -90,12 +87,8 @@ impl Logger {
     /// no LogContext exists – which means we are not in a PBS workertask – or the level of the
     /// log message is 'ERROR'.
     pub fn journald_on_no_workertask(mut self) -> Logger {
-        self.layer.push(
-            journald_or_stderr_layer()
-                .with_filter(NoWorkerTask)
-                .with_filter(self.global_log_level)
-                .boxed(),
-        );
+        self.layer
+            .push(journald_or_stderr_layer().with_filter(NoWorkerTask).boxed());
         self
     }
 
@@ -103,8 +96,7 @@ impl Logger {
     ///
     /// Check if a LogContext exists and if it does, print to the corresponding task log file.
     pub fn tasklog_pbs(mut self) -> Logger {
-        self.layer
-            .push(TasklogLayer {}.with_filter(self.global_log_level).boxed());
+        self.layer.push(TasklogLayer {}.boxed());
         self
     }
 
@@ -112,11 +104,7 @@ impl Logger {
     ///
     /// Prints all the events to stderr with the compact format (no level, no timestamp).
     pub fn stderr(mut self) -> Logger {
-        self.layer.push(
-            plain_stderr_layer()
-                .with_filter(self.global_log_level)
-                .boxed(),
-        );
+        self.layer.push(plain_stderr_layer().boxed());
         self
     }
 
@@ -126,12 +114,8 @@ impl Logger {
     /// triggered if no workertask could be found (no LogContext exists) or the event level is
     /// `ERROR`.
     pub fn stderr_on_no_workertask(mut self) -> Logger {
-        self.layer.push(
-            plain_stderr_layer()
-                .with_filter(NoWorkerTask)
-                .with_filter(self.global_log_level)
-                .boxed(),
-        );
+        self.layer
+            .push(plain_stderr_layer().with_filter(NoWorkerTask).boxed());
         self
     }
 
@@ -143,7 +127,6 @@ impl Logger {
         let layer = tracing_subscriber::fmt::layer()
             .event_format(PveTaskFormatter {})
             .with_writer(std::io::stderr)
-            .with_filter(self.global_log_level)
             .boxed();
         self.layer.push(layer);
         self
@@ -153,7 +136,10 @@ 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);
+        let registry = tracing_subscriber::registry()
+            .with(self.layer)
+            .with(self.global_log_level);
+
         tracing::subscriber::set_global_default(registry)?;
 
         LogTracer::init_with_filter(self.global_log_level.as_log())?;
-- 
2.47.3

[PATCH proxmox v2 2/7] fix #6081: log: replace simple level filter with env filter

[Thomas Ellmenreich]

Instead of parsing the contents of the environment variable passed to the
Logger as a simple LevelFilter, parse it as an EnvFilter [0]. This is
backwards compatible, as a simple LevelFilter [1] string is parsable as
an EnvFilter.

The LogTracer only accepts a simple level as a filter, so pass it the
EnvFilter's max level hint. This will not avoid the construction of all
eventually discarded logs, but should avoid most of them.

[0]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html
[1]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.LevelFilter.html

Suggested-by: Gabriel Goller <g.goller@proxmox.com>
Fixes: https://bugzilla.proxmox.com/show_bug.cgi?id=6081
Signed-off-by: Thomas Ellmenreich <t.ellmenreich@proxmox.com>
---
 proxmox-log/Cargo.toml     |  2 +-
 proxmox-log/src/builder.rs | 50 ++++++++++++++++++++++++++++++--------
 proxmox-log/src/lib.rs     | 16 ------------
 3 files changed, 41 insertions(+), 27 deletions(-)

diff --git a/proxmox-log/Cargo.toml b/proxmox-log/Cargo.toml
index 25c36fc4..4abe1b11 100644
--- a/proxmox-log/Cargo.toml
+++ b/proxmox-log/Cargo.toml
@@ -16,7 +16,7 @@ anyhow.workspace = true
 nix.workspace = true
 tracing.workspace = true
 tracing-journald.workspace = true
-tracing-subscriber.workspace = true
+tracing-subscriber = { workspace = true, features = ["env-filter"] }
 tracing-log = { workspace = true, features = ["std"] }
 tokio = { workspace = true, features = ["rt-multi-thread"] }
 
diff --git a/proxmox-log/src/builder.rs b/proxmox-log/src/builder.rs
index bbac7797..f21983e3 100644
--- a/proxmox-log/src/builder.rs
+++ b/proxmox-log/src/builder.rs
@@ -3,14 +3,15 @@ use tracing::Metadata;
 use tracing::level_filters::LevelFilter;
 use tracing_log::AsLog;
 use tracing_log::LogTracer;
+use tracing_subscriber::EnvFilter;
 use tracing_subscriber::Layer;
 use tracing_subscriber::layer::Context;
 use tracing_subscriber::layer::Filter;
 use tracing_subscriber::layer::SubscriberExt;
 
 use crate::{
-    LogContext, get_env_variable, 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`.
@@ -55,20 +56,21 @@ impl<S> Filter<S> for NoWorkerTask {
 /// # func().expect("failed to init logger");
 /// ```
 pub struct Logger {
-    global_log_level: LevelFilter,
+    global_log_filter: EnvFilter,
     layer: Vec<
         Box<dyn tracing_subscriber::Layer<tracing_subscriber::Registry> + Send + Sync + 'static>,
     >,
 }
 
 impl Logger {
-    /// Create a new LogBuilder with no layers and a default loglevel retrieved from an env
-    /// variable. If the env variable cannot be retrieved or the content is not parsable, fallback
-    /// to the default_log_level passed.
+    /// Create a new Logger with no layers and a log filter retrieved from an env
+    /// variable. If the env variable cannot be retrieved or the content is not
+    /// parsable, fall back to the default_log_level passed.
     pub fn from_env(env_var: &str, default_log_level: LevelFilter) -> Logger {
-        let log_level = get_env_variable(env_var, default_log_level);
+        let var_content = std::env::var(env_var).ok();
+        let global_log_filter = Self::apply_default_log_level(var_content, default_log_level);
         Logger {
-            global_log_level: log_level,
+            global_log_filter,
             layer: vec![],
         }
     }
@@ -136,13 +138,41 @@ impl Logger {
     ///
     /// Also configures the `LogTracer` which will convert all `log` events to tracing events.
     pub fn init(self) -> Result<(), anyhow::Error> {
+        let max_level = self.global_log_filter.max_level_hint();
         let registry = tracing_subscriber::registry()
             .with(self.layer)
-            .with(self.global_log_level);
+            .with(self.global_log_filter);
 
         tracing::subscriber::set_global_default(registry)?;
 
-        LogTracer::init_with_filter(self.global_log_level.as_log())?;
+        match max_level {
+            Some(max_level) => LogTracer::init_with_filter(max_level.as_log()),
+            None => LogTracer::init(),
+        }?;
+
         Ok(())
     }
+
+    /// If present, tries to parse the `env_filter_str` as an [`EnvFilter`],
+    /// otherwise falls back to the provided default log level.
+    ///
+    /// The provided default log level is an application default defined by us.
+    /// The user can define their own default as part of the [`EnvFilter`].
+    ///
+    /// * `env_filter_str` - Log settings in string format, what is usually
+    ///   written into a log variable. This supports the [`EnvFilter`] format.
+    /// * `default_log_level` - Default log level used by the [`Logger`] in
+    ///   case the log settings are not set.
+    fn apply_default_log_level(
+        env_filter_str: Option<String>,
+        default_log_level: LevelFilter,
+    ) -> EnvFilter {
+        if let Some(env_filter_str) = env_filter_str {
+            match EnvFilter::try_new(env_filter_str.as_str()) {
+                Ok(filter) => return filter,
+                Err(e) => eprintln!("unable to parse the log env variable {env_filter_str}: {e:#}"),
+            }
+        }
+        EnvFilter::default().add_directive(default_log_level.into())
+    }
 }
diff --git a/proxmox-log/src/lib.rs b/proxmox-log/src/lib.rs
index 2d321f20..32c10e27 100644
--- a/proxmox-log/src/lib.rs
+++ b/proxmox-log/src/lib.rs
@@ -1,7 +1,6 @@
 #![cfg_attr(docsrs, feature(doc_cfg, doc_auto_cfg))]
 #![deny(unsafe_op_in_unsafe_fn)]
 
-use std::env;
 use std::future::Future;
 use std::sync::{Arc, Mutex};
 
@@ -147,21 +146,6 @@ where
         .with_writer(std::io::stderr)
 }
 
-fn get_env_variable(env_var: &str, default_log_level: LevelFilter) -> LevelFilter {
-    let mut log_level = default_log_level;
-    if let Ok(v) = env::var(env_var) {
-        match v.parse::<LevelFilter>() {
-            Ok(l) => {
-                log_level = l;
-            }
-            Err(e) => {
-                eprintln!("env variable {env_var} found, but parsing failed: {e:?}");
-            }
-        }
-    }
-    log_level
-}
-
 /// Initialize tracing logger that prints to journald or stderr depending on if we are in a pbs
 /// task.
 ///
-- 
2.47.3

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

[Thomas Ellmenreich]

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 | 318 ++++++++++++++++++++++++++++++++++++-
 1 file changed, 315 insertions(+), 3 deletions(-)

diff --git a/proxmox-log/src/builder.rs b/proxmox-log/src/builder.rs
index f21983e3..fb8e7d70 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::AsLog;
 use tracing_log::LogTracer;
@@ -139,9 +140,7 @@ impl Logger {
     /// Also configures the `LogTracer` which will convert all `log` events to tracing events.
     pub fn init(self) -> Result<(), anyhow::Error> {
         let max_level = self.global_log_filter.max_level_hint();
-        let registry = tracing_subscriber::registry()
-            .with(self.layer)
-            .with(self.global_log_filter);
+        let registry = self.create_subscriber();
 
         tracing::subscriber::set_global_default(registry)?;
 
@@ -153,6 +152,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_filter)
+    }
+
     /// If present, tries to parse the `env_filter_str` as an [`EnvFilter`],
     /// otherwise falls back to the provided default log level.
     ///
@@ -176,3 +184,307 @@ impl Logger {
         EnvFilter::default().add_directive(default_log_level.into())
     }
 }
+
+#[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 tracing_info(message: &'static str) {
+                tracing::info!("{message}");
+            }
+        }
+        pub fn info(message: &'static str) {
+            tracing_log::log::info!("{message}");
+        }
+        pub fn tracing_info(message: &'static str) {
+            tracing::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
+        assert_logs!(events, ["log2", "log3"]);
+    }
+
+    #[test]
+    fn tracing_logs_are_also_properly_registered_and_filtered() {
+        // Arrange
+        let (events, _guard) = setup_logging(
+            Some("ERROR,proxmox_log::builder::tests::test_module::nested_module=INFO"),
+            LevelFilter::INFO,
+        );
+
+        // Act
+        tracing::info!("log1");
+        tracing::error!("log2");
+        test_module::tracing_info("log3");
+        test_module::nested_module::tracing_info("log4");
+
+        // Assert
+        assert_logs!(events, ["log2", "log4"]);
+    }
+
+    /// 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_filter: 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

[PATCH proxmox v2 4/7] log: clean up of logger components

[Thomas Ellmenreich]

Simplify the logger code. The cleanups performed were:
- Remove some explicit module paths in favor of imports
- Simplify an empty struct by converting it to a unit struct.
- Instead of creating a unit struct as an empty struct,
  instantiated it as a unit struct.

Signed-off-by: Thomas Ellmenreich <t.ellmenreich@proxmox.com>
---
 proxmox-log/src/builder.rs            | 9 ++++-----
 proxmox-log/src/pve_task_formatter.rs | 2 +-
 2 files changed, 5 insertions(+), 6 deletions(-)

diff --git a/proxmox-log/src/builder.rs b/proxmox-log/src/builder.rs
index fb8e7d70..e52379d0 100644
--- a/proxmox-log/src/builder.rs
+++ b/proxmox-log/src/builder.rs
@@ -6,6 +6,7 @@ use tracing_log::AsLog;
 use tracing_log::LogTracer;
 use tracing_subscriber::EnvFilter;
 use tracing_subscriber::Layer;
+use tracing_subscriber::Registry;
 use tracing_subscriber::layer::Context;
 use tracing_subscriber::layer::Filter;
 use tracing_subscriber::layer::SubscriberExt;
@@ -58,9 +59,7 @@ impl<S> Filter<S> for NoWorkerTask {
 /// ```
 pub struct Logger {
     global_log_filter: EnvFilter,
-    layer: Vec<
-        Box<dyn tracing_subscriber::Layer<tracing_subscriber::Registry> + Send + Sync + 'static>,
-    >,
+    layer: Vec<Box<dyn Layer<Registry> + Send + Sync + 'static>>,
 }
 
 impl Logger {
@@ -99,7 +98,7 @@ impl Logger {
     ///
     /// Check if a LogContext exists and if it does, print to the corresponding task log file.
     pub fn tasklog_pbs(mut self) -> Logger {
-        self.layer.push(TasklogLayer {}.boxed());
+        self.layer.push(TasklogLayer.boxed());
         self
     }
 
@@ -128,7 +127,7 @@ impl Logger {
     /// e.g.: `DEBUG: event message`.
     pub fn stderr_pve(mut self) -> Logger {
         let layer = tracing_subscriber::fmt::layer()
-            .event_format(PveTaskFormatter {})
+            .event_format(PveTaskFormatter)
             .with_writer(std::io::stderr)
             .boxed();
         self.layer.push(layer);
diff --git a/proxmox-log/src/pve_task_formatter.rs b/proxmox-log/src/pve_task_formatter.rs
index e9866a4b..12bc33c8 100644
--- a/proxmox-log/src/pve_task_formatter.rs
+++ b/proxmox-log/src/pve_task_formatter.rs
@@ -8,7 +8,7 @@ use tracing_subscriber::registry::LookupSpan;
 /// This custom formatter outputs logs as they are visible in the PVE task log.
 ///
 /// e.g.: "DEBUG: sample message"
-pub struct PveTaskFormatter {}
+pub struct PveTaskFormatter;
 
 impl<C, N> FormatEvent<C, N> for PveTaskFormatter
 where
-- 
2.47.3

[PATCH proxmox v2 5/7] rest-server: enable debug based on log level

[Thomas Ellmenreich]

To set the debug flag of the REST server, a call to AcceptBuilder::debug()
was necessary. Callers would then usually just inspect the current
log level and set the debug flag accordingly. So, instead of
defaulting to false for the debug flag, set it according to
the debug level.

This has the advantage that the REST server's debug flag can also
be set by only changing the log level of the relevant module,
like so:

    proxmox_rest_server::connection=debug

Users of the REST server can still call debug and retain their previous
implementation, this only changes the default.

Signed-off-by: Thomas Ellmenreich <t.ellmenreich@proxmox.com>
---
 proxmox-rest-server/src/connection.rs | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/proxmox-rest-server/src/connection.rs b/proxmox-rest-server/src/connection.rs
index 153a44b0..dfcec7f1 100644
--- a/proxmox-rest-server/src/connection.rs
+++ b/proxmox-rest-server/src/connection.rs
@@ -193,7 +193,7 @@ pub struct AcceptBuilder {
 impl Default for AcceptBuilder {
     fn default() -> Self {
         Self {
-            debug: false,
+            debug: proxmox_log::enabled!(proxmox_log::Level::DEBUG),
             tcp_keepalive_time: 120,
             max_pending_accepts: 1024,
 
-- 
2.47.3

[PATCH datacenter-manager v2 6/7] api: remove manual setting of REST server debug flag

[Thomas Ellmenreich]

Previously the REST server would be set to debug if the PROXMOX_DEBUG
environment variable was set. Now the server itself checks the enabled
log level and enables the debug flag accordingly.

This means that users will now have to set the PROXMOX_DEBUG variable to
debug for the REST server to enable its debug flag. Additionally,
setting the debug log level for proxmox_rest_server::connection
specifically will now also trigger the debug flag to be set, allowing
for greater control.

Signed-off-by: Thomas Ellmenreich <t.ellmenreich@proxmox.com>
---
 server/src/bin/proxmox-datacenter-api/main.rs | 8 +++-----
 1 file changed, 3 insertions(+), 5 deletions(-)

diff --git a/server/src/bin/proxmox-datacenter-api/main.rs b/server/src/bin/proxmox-datacenter-api/main.rs
index eac1585b..1c107b1f 100644
--- a/server/src/bin/proxmox-datacenter-api/main.rs
+++ b/server/src/bin/proxmox-datacenter-api/main.rs
@@ -47,8 +47,6 @@ fn main() -> Result<(), Error> {
 
     server::env::sanitize_environment_vars();
 
-    let debug = std::env::var("PROXMOX_DEBUG").is_ok();
-
     proxmox_log::Logger::from_env("PROXMOX_DEBUG", LevelFilter::INFO)
         .journald_on_no_workertask()
         .tasklog_pbs()
@@ -70,7 +68,7 @@ fn main() -> Result<(), Error> {
     proxmox_product_config::init(pdm_config::api_user()?, pdm_config::priv_user()?);
     let app = server::context::init()?;
 
-    proxmox_async::runtime::main(run(app, debug))
+    proxmox_async::runtime::main(run(app))
 }
 
 async fn get_index_future(env: RestEnvironment, parts: Parts) -> Response<proxmox_http::Body> {
@@ -145,7 +143,7 @@ async fn get_index_future(env: RestEnvironment, parts: Parts) -> Response<proxmo
     resp
 }
 
-async fn run(app: PdmApplication, debug: bool) -> Result<(), Error> {
+async fn run(app: PdmApplication) -> Result<(), Error> {
     auth::init(false);
 
     proxmox_acme_api::init(configdir!("/acme"), false)?;
@@ -229,7 +227,7 @@ async fn run(app: PdmApplication, debug: bool) -> Result<(), Error> {
         }
     })?;
 
-    let connections = proxmox_rest_server::connection::AcceptBuilder::new().debug(debug);
+    let connections = proxmox_rest_server::connection::AcceptBuilder::new();
     let server = proxmox_daemon::server::create_daemon(
         PDM_LISTEN_ADDR,
         move |listener| {
-- 
2.47.3

[PATCH datacenter-manager v2 7/7] api: rename PROXMOX_DEBUG log variable to PDM_LOG

[Thomas Ellmenreich]

Update the variable used to set the log level for the privileged and
unprivileged datacenter-api. The old 'PROXMOX_DEBUG' variable is replaced by
'PDM_LOG' to match the pattern used by other products.

In the case that PROXMOX_DEBUG is still set, a warning will be emitted,
notifying the user that the environment variable is no longer in use.

Suggested-by: Lukas Wagner <l.wagner@proxmox.com>
Signed-off-by: Thomas Ellmenreich <t.ellmenreich@proxmox.com>
---
 server/src/bin/proxmox-datacenter-api/main.rs       | 7 ++++++-
 server/src/bin/proxmox-datacenter-privileged-api.rs | 9 ++++++++-
 2 files changed, 14 insertions(+), 2 deletions(-)

diff --git a/server/src/bin/proxmox-datacenter-api/main.rs b/server/src/bin/proxmox-datacenter-api/main.rs
index 1c107b1f..9d04ba91 100644
--- a/server/src/bin/proxmox-datacenter-api/main.rs
+++ b/server/src/bin/proxmox-datacenter-api/main.rs
@@ -47,11 +47,16 @@ fn main() -> Result<(), Error> {
 
     server::env::sanitize_environment_vars();
 
-    proxmox_log::Logger::from_env("PROXMOX_DEBUG", LevelFilter::INFO)
+    proxmox_log::Logger::from_env("PDM_LOG", LevelFilter::INFO)
         .journald_on_no_workertask()
         .tasklog_pbs()
         .init()?;
 
+    // TODO: remove after a few versions
+    if std::env::var("PROXMOX_DEBUG").is_ok() {
+        proxmox_log::warn!("PROXMOX_DEBUG is deprecated, please use PDM_LOG instead");
+    }
+
     if std::env::args().nth(1).is_some() {
         bail!("unexpected command line parameters");
     }
diff --git a/server/src/bin/proxmox-datacenter-privileged-api.rs b/server/src/bin/proxmox-datacenter-privileged-api.rs
index 616d9e14..3ead7eb9 100644
--- a/server/src/bin/proxmox-datacenter-privileged-api.rs
+++ b/server/src/bin/proxmox-datacenter-privileged-api.rs
@@ -27,11 +27,18 @@ fn main() -> Result<(), Error> {
 
     server::env::sanitize_environment_vars();
 
-    proxmox_log::Logger::from_env("PROXMOX_DEBUG", LevelFilter::INFO)
+    proxmox_log::Logger::from_env("PDM_LOG", LevelFilter::INFO)
         .journald_on_no_workertask()
         .tasklog_pbs()
         .init()?;
 
+    // TODO: remove after a few versions
+    if std::env::var("PROXMOX_DEBUG").is_ok() {
+        proxmox_log::warn!(
+            "to set the log level, please use the PDM_LOG variable, as it has replaced PROXMOX_DEBUG"
+        );
+    }
+
     proxmox_product_config::init(pdm_config::api_user()?, pdm_config::priv_user()?);
 
     create_directories()?;
-- 
2.47.3