From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from gate001.proxmox.com (gate001.proxmox.com [IPv6:2a0f:8001:1:32::40]) by lore.proxmox.com (Postfix) with ESMTPS id 0AEBE1FF09C for ; Mon, 21 Sep 2026 11:53:23 +0200 (CEST) Received: from gate001.proxmox.com (localhost.localdomain [127.0.0.1]) by gate001.proxmox.com (Proxmox) with ESMTP id 78EF121595; Mon, 21 Sep 2026 11:53:19 +0200 (CEST) From: Thomas Ellmenreich To: pdm-devel@lists.proxmox.com Subject: [PATCH proxmox 3/5] log: add tests to the logger Date: Mon, 21 Sep 2026 11:51:56 +0200 Message-ID: <20260921095210.229315-5-t.ellmenreich@proxmox.com> X-Mailer: git-send-email 2.47.3 In-Reply-To: <20260921095210.229315-2-t.ellmenreich@proxmox.com> References: <20260921095210.229315-2-t.ellmenreich@proxmox.com> MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-Bm-Milter-Handled: 55990f41-d878-4baa-be0a-ee34c49e34d2 X-Bm-Transport-Timestamp: 1789984393429 X-SPAM-LEVEL: Spam detection results: 0 AWL 0.578 Adjusted score from AWL reputation of From: address DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment (newer systems) RCVD_IN_DNSWL_MED -2.3 Sender listed at https://www.dnswl.org/, medium trust SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_PASS -0.001 SPF: sender matches SPF record Message-ID-Hash: ZZ4NHCG3ZMRHII2WFZZ54WJ6KZWQC3YG X-Message-ID-Hash: ZZ4NHCG3ZMRHII2WFZZ54WJ6KZWQC3YG X-MailFrom: t.ellmenreich@proxmox.com X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; loop; banned-address; emergency; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: Thomas Ellmenreich X-Mailman-Version: 3.3.10 Precedence: list List-Id: Proxmox Datacenter Manager development discussion List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: 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 --- 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>>, 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>>, 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>>, + filter: Option, + } + + impl TestLayer { + pub(crate) fn no_filter() -> (Arc>>, Self) { + let events = Arc::new(Mutex::new(vec![])); + ( + Arc::clone(&events), + Self { + events, + filter: None, + }, + ) + } + + pub(crate) fn new( + filter: tracing_subscriber::EnvFilter, + ) -> (Arc>>, Self) { + let events = Arc::new(Mutex::new(vec![])); + ( + Arc::clone(&events), + Self { + events, + filter: Some(filter), + }, + ) + } + } + + impl tracing_subscriber::Layer 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); + + 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