From 24a42fad0ecd1de9c3a3890d06b7abaa77a523d4 Mon Sep 17 00:00:00 2001 From: Leynos Date: Mon, 23 Jun 2025 23:57:20 +0100 Subject: [PATCH 1/5] Add logger fixture for push policy tests --- Cargo.lock | 26 +++++++ Cargo.toml | 1 + docs/rust-testing-with-rstest-fixtures.md | 20 ++++- tests/push_policies.rs | 89 +++++++++++++++++++++++ 4 files changed, 135 insertions(+), 1 deletion(-) create mode 100644 tests/push_policies.rs diff --git a/Cargo.lock b/Cargo.lock index 3cd970da..e1801382 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -197,6 +197,12 @@ version = "0.3.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a8d1add55171497b4705a648c6b583acafb01d58050a51727785f0b2c8e0a2b2" +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "libc" version = "0.2.173" @@ -208,6 +214,19 @@ name = "log" version = "0.4.27" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "13dc2df351e3202783a1fe0d44375f7295ffb4049267b0f3018346dc122a1d94" +dependencies = [ + "value-bag", +] + +[[package]] +name = "logtest" +version = "2.0.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "eb3e43a8657c1d64516dcc9db8ca03826a4aceaf89d5ce1b37b59f6ff0e43026" +dependencies = [ + "lazy_static", + "log", +] [[package]] name = "memchr" @@ -458,6 +477,12 @@ version = "0.0.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6d49784317cd0d1ee7ec5c716dd598ec5b4483ea832a2dced265471cc0f690ae" +[[package]] +name = "value-bag" +version = "1.11.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "943ce29a8a743eb10d6082545d861b24f9d1b160b7d741e0f2cdf726bec909c5" + [[package]] name = "virtue" version = "0.0.18" @@ -561,6 +586,7 @@ dependencies = [ "bytes", "futures", "log", + "logtest", "rstest", "serde", "tokio", diff --git a/Cargo.toml b/Cargo.toml index fec8fb8d..5da53c66 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,6 +15,7 @@ log = "0.4" [dev-dependencies] rstest = "0.18.2" wireframe_testing = { path = "./wireframe_testing" } +logtest = "2" [lints.clippy] pedantic = "warn" diff --git a/docs/rust-testing-with-rstest-fixtures.md b/docs/rust-testing-with-rstest-fixtures.md index 3570f825..f05d9fde 100644 --- a/docs/rust-testing-with-rstest-fixtures.md +++ b/docs/rust-testing-with-rstest-fixtures.md @@ -1237,7 +1237,25 @@ proper initialization. `rstest-log` likely provides attributes or wrappers to ensure that logging is correctly set up before each `rstest`-generated test case runs, making it easier to get consistent log output from tests. -### B. `test-with`: Conditional Testing with `rstest` +### B. `logtest`: Verifying Log Output + +`logtest` provides a lightweight logger that records emitted log records during +tests. This makes it trivial to assert on log messages without interfering with +other tests. Add it under `[dev-dependencies]` and start a `Logger` before +running the code under test: + +```rust +use logtest::Logger; + +let mut logger = Logger::start(); +my_async_fn().await; +assert!(logger.pop().is_some()); +``` + +This crate complements `rstest` nicely when verifying that warnings or errors +are logged under specific conditions. + +### C. `test-with`: Conditional Testing with `rstest` The `test-with` crate allows for conditional execution of tests based on various runtime conditions, such as the presence of environment variables, the existence diff --git a/tests/push_policies.rs b/tests/push_policies.rs new file mode 100644 index 00000000..29b7f0f1 --- /dev/null +++ b/tests/push_policies.rs @@ -0,0 +1,89 @@ +//! Tests for push queue policy behaviour. + +use std::sync::{Mutex, Once}; + +use logtest::Logger; +use rstest::{fixture, rstest}; +use wireframe::push::{PushPolicy, PushPriority, PushQueues}; + +/// Handle to the global logger with exclusive access. +struct LoggerHandle { + _guard: std::sync::MutexGuard<'static, ()>, + logger: Logger, +} + +impl LoggerHandle { + fn new() -> Self { + static INIT: Once = Once::new(); + static LOCK: Mutex<()> = Mutex::new(()); + + let guard = LOCK.lock().expect("lock logger"); + INIT.call_once(|| { + Logger::start(); + }); + + let mut logger = Logger; + while logger.pop().is_some() {} + + Self { + _guard: guard, + logger, + } + } +} + +impl std::ops::Deref for LoggerHandle { + type Target = Logger; + + fn deref(&self) -> &Self::Target { &self.logger } +} + +impl std::ops::DerefMut for LoggerHandle { + fn deref_mut(&mut self) -> &mut Self::Target { &mut self.logger } +} + +#[fixture] +fn rt() -> tokio::runtime::Runtime { + tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("runtime") +} +#[allow(unused_braces)] +#[fixture] +fn logger() -> LoggerHandle { LoggerHandle::new() } + +#[rstest] +fn drop_if_full_discards_frame(rt: tokio::runtime::Runtime, mut logger: LoggerHandle) { + rt.block_on(async { + let (mut queues, handle) = PushQueues::bounded(1, 1); + handle.push_high_priority(1u8).await.unwrap(); + handle + .try_push(2u8, PushPriority::High, PushPolicy::DropIfFull) + .unwrap(); + let (_, val) = queues.recv().await.unwrap(); + assert_eq!(val, 1); + assert!(queues.high_priority_rx.try_recv().is_err()); + }); + + assert!(logger.pop().is_none()); +} + +#[rstest] +fn warn_and_drop_if_full_logs_warning(rt: tokio::runtime::Runtime, mut logger: LoggerHandle) { + rt.block_on(async { + let (mut queues, handle) = PushQueues::bounded(1, 1); + handle.push_low_priority(3u8).await.unwrap(); + handle + .try_push(4u8, PushPriority::Low, PushPolicy::WarnAndDropIfFull) + .unwrap(); + let (_, val) = queues.recv().await.unwrap(); + assert_eq!(val, 3); + assert!(queues.low_priority_rx.try_recv().is_err()); + }); + + let record = logger.pop().expect("expected warning"); + assert_eq!(record.level(), log::Level::Warn); + assert!(record.args().contains("push queue full")); + assert!(logger.pop().is_none()); +} From 68b8462716a17a7e4a62b23c75425f818b71cd87 Mon Sep 17 00:00:00 2001 From: Leynos Date: Tue, 24 Jun 2025 02:37:00 +0100 Subject: [PATCH 2/5] Refine push policy tests --- Cargo.toml | 2 +- docs/rust-testing-with-rstest-fixtures.md | 10 ++- tests/push_policies.rs | 76 +++++++++-------------- 3 files changed, 38 insertions(+), 50 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 5da53c66..cd992d89 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,7 +15,7 @@ log = "0.4" [dev-dependencies] rstest = "0.18.2" wireframe_testing = { path = "./wireframe_testing" } -logtest = "2" +logtest = "^2.0" [lints.clippy] pedantic = "warn" diff --git a/docs/rust-testing-with-rstest-fixtures.md b/docs/rust-testing-with-rstest-fixtures.md index f05d9fde..5a3417b0 100644 --- a/docs/rust-testing-with-rstest-fixtures.md +++ b/docs/rust-testing-with-rstest-fixtures.md @@ -1241,8 +1241,14 @@ runs, making it easier to get consistent log output from tests. `logtest` provides a lightweight logger that records emitted log records during tests. This makes it trivial to assert on log messages without interfering with -other tests. Add it under `[dev-dependencies]` and start a `Logger` before -running the code under test: +other tests. Add it under `[dev-dependencies]` using an explicit version range: + +```toml +[dev-dependencies] +logtest = "^2.0" +``` + +Start a `Logger` before running the code under test: ```rust use logtest::Logger; diff --git a/tests/push_policies.rs b/tests/push_policies.rs index 29b7f0f1..20b6d445 100644 --- a/tests/push_policies.rs +++ b/tests/push_policies.rs @@ -1,6 +1,6 @@ //! Tests for push queue policy behaviour. -use std::sync::{Mutex, Once}; +use std::sync::{Mutex, OnceLock}; use logtest::Logger; use rstest::{fixture, rstest}; @@ -8,79 +8,61 @@ use wireframe::push::{PushPolicy, PushPriority, PushQueues}; /// Handle to the global logger with exclusive access. struct LoggerHandle { - _guard: std::sync::MutexGuard<'static, ()>, - logger: Logger, + guard: std::sync::MutexGuard<'static, Logger>, } impl LoggerHandle { fn new() -> Self { - static INIT: Once = Once::new(); - static LOCK: Mutex<()> = Mutex::new(()); + static LOGGER: OnceLock> = OnceLock::new(); - let guard = LOCK.lock().expect("lock logger"); - INIT.call_once(|| { - Logger::start(); - }); + let logger = LOGGER.get_or_init(|| Mutex::new(Logger::start())); + let mut guard = logger.lock().expect("lock logger"); + while guard.pop().is_some() {} - let mut logger = Logger; - while logger.pop().is_some() {} - - Self { - _guard: guard, - logger, - } + Self { guard } } } impl std::ops::Deref for LoggerHandle { type Target = Logger; - fn deref(&self) -> &Self::Target { &self.logger } + fn deref(&self) -> &Self::Target { &self.guard } } impl std::ops::DerefMut for LoggerHandle { - fn deref_mut(&mut self) -> &mut Self::Target { &mut self.logger } + fn deref_mut(&mut self) -> &mut Self::Target { &mut self.guard } } -#[fixture] -fn rt() -> tokio::runtime::Runtime { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("runtime") -} #[allow(unused_braces)] #[fixture] fn logger() -> LoggerHandle { LoggerHandle::new() } #[rstest] -fn drop_if_full_discards_frame(rt: tokio::runtime::Runtime, mut logger: LoggerHandle) { - rt.block_on(async { - let (mut queues, handle) = PushQueues::bounded(1, 1); - handle.push_high_priority(1u8).await.unwrap(); - handle - .try_push(2u8, PushPriority::High, PushPolicy::DropIfFull) - .unwrap(); - let (_, val) = queues.recv().await.unwrap(); - assert_eq!(val, 1); - assert!(queues.high_priority_rx.try_recv().is_err()); - }); +#[tokio::test] +async fn drop_if_full_discards_frame(mut logger: LoggerHandle) { + let (mut queues, handle) = PushQueues::bounded(1, 1); + handle.push_high_priority(1u8).await.unwrap(); + handle + .try_push(2u8, PushPriority::High, PushPolicy::DropIfFull) + .unwrap(); + let (_, val) = queues.recv().await.unwrap(); + assert_eq!(val, 1); + assert!(queues.high_priority_rx.try_recv().is_err()); assert!(logger.pop().is_none()); } #[rstest] -fn warn_and_drop_if_full_logs_warning(rt: tokio::runtime::Runtime, mut logger: LoggerHandle) { - rt.block_on(async { - let (mut queues, handle) = PushQueues::bounded(1, 1); - handle.push_low_priority(3u8).await.unwrap(); - handle - .try_push(4u8, PushPriority::Low, PushPolicy::WarnAndDropIfFull) - .unwrap(); - let (_, val) = queues.recv().await.unwrap(); - assert_eq!(val, 3); - assert!(queues.low_priority_rx.try_recv().is_err()); - }); +#[tokio::test] +async fn warn_and_drop_if_full_logs_warning(mut logger: LoggerHandle) { + let (mut queues, handle) = PushQueues::bounded(1, 1); + handle.push_low_priority(3u8).await.unwrap(); + handle + .try_push(4u8, PushPriority::Low, PushPolicy::WarnAndDropIfFull) + .unwrap(); + let (_, val) = queues.recv().await.unwrap(); + assert_eq!(val, 3); + assert!(queues.low_priority_rx.try_recv().is_err()); let record = logger.pop().expect("expected warning"); assert_eq!(record.level(), log::Level::Warn); From 406fab4d1eefb5018749982fe6c94c8e9500307b Mon Sep 17 00:00:00 2001 From: Leynos Date: Thu, 26 Jun 2025 01:08:36 +0100 Subject: [PATCH 3/5] Clarify logger lock failure --- tests/push_policies.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/push_policies.rs b/tests/push_policies.rs index 20b6d445..301748ed 100644 --- a/tests/push_policies.rs +++ b/tests/push_policies.rs @@ -16,7 +16,9 @@ impl LoggerHandle { static LOGGER: OnceLock> = OnceLock::new(); let logger = LOGGER.get_or_init(|| Mutex::new(Logger::start())); - let mut guard = logger.lock().expect("lock logger"); + let mut guard = logger + .lock() + .expect("failed to acquire global logger lock when starting capture"); while guard.pop().is_some() {} Self { guard } From ecdecf5fc623e21cf4db175ee523e4a9cec95480 Mon Sep 17 00:00:00 2001 From: Leynos Date: Thu, 26 Jun 2025 01:22:28 +0100 Subject: [PATCH 4/5] Add push policy tests --- tests/push_policies.rs | 74 +++++++++++++++++++++++++++--------------- 1 file changed, 47 insertions(+), 27 deletions(-) diff --git a/tests/push_policies.rs b/tests/push_policies.rs index 301748ed..ccc407e3 100644 --- a/tests/push_policies.rs +++ b/tests/push_policies.rs @@ -4,6 +4,8 @@ use std::sync::{Mutex, OnceLock}; use logtest::Logger; use rstest::{fixture, rstest}; +use tokio::runtime::Runtime; +use tokio::time::{timeout, Duration}; use wireframe::push::{PushPolicy, PushPriority, PushQueues}; /// Handle to the global logger with exclusive access. @@ -16,10 +18,9 @@ impl LoggerHandle { static LOGGER: OnceLock> = OnceLock::new(); let logger = LOGGER.get_or_init(|| Mutex::new(Logger::start())); - let mut guard = logger + let guard = logger .lock() .expect("failed to acquire global logger lock when starting capture"); - while guard.pop().is_some() {} Self { guard } } @@ -39,35 +40,54 @@ impl std::ops::DerefMut for LoggerHandle { #[fixture] fn logger() -> LoggerHandle { LoggerHandle::new() } +#[allow(unused_braces)] +#[fixture] +fn rt() -> Runtime { + tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("failed to build test runtime") +} + #[rstest] -#[tokio::test] -async fn drop_if_full_discards_frame(mut logger: LoggerHandle) { - let (mut queues, handle) = PushQueues::bounded(1, 1); - handle.push_high_priority(1u8).await.unwrap(); - handle - .try_push(2u8, PushPriority::High, PushPolicy::DropIfFull) - .unwrap(); - let (_, val) = queues.recv().await.unwrap(); - assert_eq!(val, 1); - assert!(queues.high_priority_rx.try_recv().is_err()); +fn drop_if_full_discards_frame(rt: Runtime, mut logger: LoggerHandle) { + rt.block_on(async { + let (mut queues, handle) = PushQueues::bounded(1, 1); + handle.push_high_priority(1u8).await.unwrap(); + handle + .try_push(2u8, PushPriority::High, PushPolicy::DropIfFull) + .unwrap(); + let (_, val) = queues.recv().await.unwrap(); + assert_eq!(val, 1); + assert!( + timeout(Duration::from_millis(20), queues.recv()) + .await + .is_err() + ); - assert!(logger.pop().is_none()); + assert!(logger.pop().is_none()); + }); } #[rstest] -#[tokio::test] -async fn warn_and_drop_if_full_logs_warning(mut logger: LoggerHandle) { - let (mut queues, handle) = PushQueues::bounded(1, 1); - handle.push_low_priority(3u8).await.unwrap(); - handle - .try_push(4u8, PushPriority::Low, PushPolicy::WarnAndDropIfFull) - .unwrap(); - let (_, val) = queues.recv().await.unwrap(); - assert_eq!(val, 3); - assert!(queues.low_priority_rx.try_recv().is_err()); +fn warn_and_drop_if_full_logs_warning(rt: Runtime, mut logger: LoggerHandle) { + rt.block_on(async { + let (mut queues, handle) = PushQueues::bounded(1, 1); + handle.push_low_priority(3u8).await.unwrap(); + handle + .try_push(4u8, PushPriority::Low, PushPolicy::WarnAndDropIfFull) + .unwrap(); + let (_, val) = queues.recv().await.unwrap(); + assert_eq!(val, 3); + assert!( + timeout(Duration::from_millis(20), queues.recv()) + .await + .is_err() + ); - let record = logger.pop().expect("expected warning"); - assert_eq!(record.level(), log::Level::Warn); - assert!(record.args().contains("push queue full")); - assert!(logger.pop().is_none()); + let record = logger.pop().expect("expected warning"); + assert_eq!(record.level(), log::Level::Warn); + assert!(record.args().contains("push queue full")); + assert!(logger.pop().is_none()); + }); } From 7ea9d9a2e076bf5093acc68075fb0b77a411ec44 Mon Sep 17 00:00:00 2001 From: Leynos Date: Thu, 26 Jun 2025 02:00:49 +0100 Subject: [PATCH 5/5] Improve logger lock error message --- tests/push_policies.rs | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/tests/push_policies.rs b/tests/push_policies.rs index ccc407e3..ac938f12 100644 --- a/tests/push_policies.rs +++ b/tests/push_policies.rs @@ -4,8 +4,10 @@ use std::sync::{Mutex, OnceLock}; use logtest::Logger; use rstest::{fixture, rstest}; -use tokio::runtime::Runtime; -use tokio::time::{timeout, Duration}; +use tokio::{ + runtime::Runtime, + time::{Duration, timeout}, +}; use wireframe::push::{PushPolicy, PushPriority, PushQueues}; /// Handle to the global logger with exclusive access. @@ -20,7 +22,7 @@ impl LoggerHandle { let logger = LOGGER.get_or_init(|| Mutex::new(Logger::start())); let guard = logger .lock() - .expect("failed to acquire global logger lock when starting capture"); + .expect("failed to acquire global logger lock; a previous test may still hold it"); Self { guard } }