From cbb1667a0c8ff7722e2653c7e0f91055f57e975e Mon Sep 17 00:00:00 2001 From: Hocuri Date: Wed, 4 Dec 2024 16:46:03 +0100 Subject: [PATCH 1/2] test: Notifiy more prominently & in more tests about false positives when running with `cargo test` This: - Moves the note about the false positive to the end of the test output, where it is more likely to be noticed - Also notes in test_modify_chat_disordered() and test_setup_contact_*(), in addition to the existing note in test_was_seen_recently() --- src/chat.rs | 4 +++- src/contact.rs | 17 ++++------------- src/securejoin.rs | 4 +++- src/test_utils.rs | 18 ++++++++++++++++++ 4 files changed, 28 insertions(+), 15 deletions(-) diff --git a/src/chat.rs b/src/chat.rs index e57372c931..91877e6787 100644 --- a/src/chat.rs +++ b/src/chat.rs @@ -4724,7 +4724,7 @@ mod tests { use crate::headerdef::HeaderDef; use crate::message::delete_msgs; use crate::receive_imf::receive_imf; - use crate::test_utils::{sync, TestContext, TestContextManager}; + use crate::test_utils::{sync, TestContext, TestContextManager, TimeShiftFalsePositiveNote}; use strum::IntoEnumIterator; use tokio::fs; @@ -5268,6 +5268,8 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn test_modify_chat_disordered() -> Result<()> { + let _n = TimeShiftFalsePositiveNote; + // Alice creates a group with Bob, Claire and Daisy and then removes Claire and Daisy // (sleep() is needed as otherwise smeared time from Alice looks to Bob like messages from the future which are all set to "now" then) let alice = TestContext::new_alice().await; diff --git a/src/contact.rs b/src/contact.rs index bf5c71746f..6ce4ecfa9f 100644 --- a/src/contact.rs +++ b/src/contact.rs @@ -1984,7 +1984,7 @@ mod tests { use crate::chat::{get_chat_contacts, send_text_msg, Chat}; use crate::chatlist::Chatlist; use crate::receive_imf::receive_imf; - use crate::test_utils::{self, TestContext, TestContextManager}; + use crate::test_utils::{self, TestContext, TestContextManager, TimeShiftFalsePositiveNote}; #[test] fn test_contact_id_values() { @@ -2915,6 +2915,8 @@ Hi."#; #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn test_was_seen_recently() -> Result<()> { + let _n = TimeShiftFalsePositiveNote; + let mut tcm = TestContextManager::new(); let alice = tcm.alice().await; let bob = tcm.bob().await; @@ -2930,18 +2932,7 @@ Hi."#; bob.recv_msg(&sent_msg).await; let contact = Contact::get_by_id(&bob, *contacts.first().unwrap()).await?; - let green = nu_ansi_term::Color::Green.normal(); - assert!( - contact.was_seen_recently(), - "{}", - green.paint( - "\nNOTE: This test failure is probably a false-positive, caused by tests running in parallel. -The issue is that `SystemTime::shift()` (a utility function for tests) changes the time for all threads doing tests, and not only for the running test. -Until the false-positive is fixed: -- Use `cargo test -- --test-threads 1` instead of `cargo test` -- Or use `cargo nextest run` (install with `cargo install cargo-nextest --locked`)\n" - ) - ); + assert!(contact.was_seen_recently()); let self_contact = Contact::get_by_id(&bob, ContactId::SELF).await?; assert!(!self_contact.was_seen_recently()); diff --git a/src/securejoin.rs b/src/securejoin.rs index f9ebd00d98..5779178f2b 100644 --- a/src/securejoin.rs +++ b/src/securejoin.rs @@ -751,7 +751,7 @@ mod tests { use crate::imex::{imex, ImexMode}; use crate::receive_imf::receive_imf; use crate::stock_str::{self, chat_protection_enabled}; - use crate::test_utils::get_chat_msg; + use crate::test_utils::{get_chat_msg, TimeShiftFalsePositiveNote}; use crate::test_utils::{TestContext, TestContextManager}; use crate::tools::SystemTime; use std::collections::HashSet; @@ -798,6 +798,8 @@ mod tests { } async fn test_setup_contact_ex(case: SetupContactCase) { + let _n = TimeShiftFalsePositiveNote; + let mut tcm = TestContextManager::new(); let alice = tcm.alice().await; let alice_addr = &alice.get_config(Config::Addr).await.unwrap().unwrap(); diff --git a/src/test_utils.rs b/src/test_utils.rs index 0eddb76204..0c9a452ab1 100644 --- a/src/test_utils.rs +++ b/src/test_utils.rs @@ -1351,6 +1351,24 @@ async fn write_msg(context: &Context, prefix: &str, msg: &Message, buf: &mut Str .unwrap(); } +/// When dropped after a test failure, +/// prints a note about a possible false-possible caused by SystemTime::shift(). +pub(crate) struct TimeShiftFalsePositiveNote; +impl Drop for TimeShiftFalsePositiveNote { + fn drop(&mut self) { + if std::thread::panicking() { + let green = nu_ansi_term::Color::Green.normal(); + println!("{}", green.paint( + "\nNOTE: This test failure is probably a false-positive, caused by tests running in parallel. +The issue is that `SystemTime::shift()` (a utility function for tests) changes the time for all threads doing tests, and not only for the running test. +Until the false-positive is fixed: +- Use `cargo test -- --test-threads 1` instead of `cargo test` +- Or use `cargo nextest run` (install with `cargo install cargo-nextest --locked`)\n") + ); + } + } +} + #[cfg(test)] mod tests { use super::*; From 635ca00fb3779c5cc6acafcdf2be3d6bfee000e3 Mon Sep 17 00:00:00 2001 From: Hocuri Date: Wed, 4 Dec 2024 16:50:23 +0100 Subject: [PATCH 2/2] Reword "probably" -> "may be" because it's used in more places now --- src/test_utils.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/test_utils.rs b/src/test_utils.rs index 0c9a452ab1..e680d2025a 100644 --- a/src/test_utils.rs +++ b/src/test_utils.rs @@ -1359,7 +1359,7 @@ impl Drop for TimeShiftFalsePositiveNote { if std::thread::panicking() { let green = nu_ansi_term::Color::Green.normal(); println!("{}", green.paint( - "\nNOTE: This test failure is probably a false-positive, caused by tests running in parallel. + "\nNOTE: This test failure may be a false-positive, caused by tests running in parallel. The issue is that `SystemTime::shift()` (a utility function for tests) changes the time for all threads doing tests, and not only for the running test. Until the false-positive is fixed: - Use `cargo test -- --test-threads 1` instead of `cargo test`