Mirrors/chatmail-core
1
0
Fork 0
mirror of https://github.com/chatmail/core.git synced 2026-09-22 13:01:21 +03:00
Code Issues Packages Projects Releases Wiki Activity

test: Assert log warnings and errors (#8457)

Browse Source 
Adds `assert_warn`, `assert_error` and `assert_warns_or_errors`
methods to `TestContext`, that let us assert that
a certain warning or error is logged during the test.
Also asserts test logs should not contain any other
errors or warnings.

Adjusts tests accordingly.

Signed-off-by: Jagoda Ślązak <jslazak@jslazak.com>
This commit is contained in:
Jagoda Estera Ślązak
2026-08-10 15:36:09 +02:00
committed by GitHub
parent 97932fda07
commit fd8c56894a
36 changed files with 554 additions and 219 deletions
Download Patch File Download Diff File Expand all files Collapse all files

257
src/test_utils.rs
View File

@@ -1,9 +1,10 @@
//! Utilities to help writing tests.
//!
//! This private module is only compiled for test runs.
use std::collections::{BTreeMap, BTreeSet, HashSet};
use std::env::current_dir;
use std::fmt::Write;
use std::fmt::{Debug, Write};
use std::ops::{Deref, DerefMut};
use std::panic;
use std::path::Path;
@@ -36,7 +37,6 @@ use crate::contact::{
use crate::context::Context;
use crate::events::{Event, EventEmitter, EventType, Events};
use crate::key::{self, DcKey, self_fingerprint};
use crate::log::warn;
use crate::login_param::EnteredLoginParam;
use crate::message::{Message, MessageState, MsgId};
use crate::mimeparser::{MimeMessage, SystemMessage};
@@ -68,19 +68,13 @@ static CONTEXT_NAMES: LazyLock<std::sync::RwLock<BTreeMap<u32, String>>> =
LazyLock::new(|| std::sync::RwLock::new(BTreeMap::new()));
/// Manage multiple [`TestContext`]s in one place.
///
/// The main advantage is that the log records of the contexts will appear in the order they
/// occurred rather than grouped by context like would happen when you use separate
/// [`TestContext`]s without managing your own [`LogSink`].
pub struct TestContextManager {
log_sink: LogSink,
used_names: BTreeSet<String>,
}
impl TestContextManager {
pub fn new() -> Self {
Self {
log_sink: LogSink::new(),
used_names: BTreeSet::new(),
}
}
@@ -89,7 +83,6 @@ impl TestContextManager {
TestContext::builder()
.configure_alice()
.with_id_offset(1000)
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
@@ -98,7 +91,6 @@ impl TestContextManager {
TestContext::builder()
.configure_bob()
.with_id_offset(2000)
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
@@ -107,7 +99,6 @@ impl TestContextManager {
TestContext::builder()
.configure_charlie()
.with_id_offset(3000)
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
@@ -116,7 +107,6 @@ impl TestContextManager {
TestContext::builder()
.configure_dom()
.with_id_offset(4000)
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
@@ -126,7 +116,6 @@ impl TestContextManager {
TestContext::builder()
.configure_elena()
.with_id_offset(5000)
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
@@ -135,7 +124,6 @@ impl TestContextManager {
TestContext::builder()
.configure_fiona()
.with_id_offset(6000)
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
@@ -146,7 +134,6 @@ impl TestContextManager {
.with_key_pair(pqc_keypair())
.with_address("pqc@example.org".to_string())
.with_id_offset(7000)
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
@@ -154,21 +141,15 @@ impl TestContextManager {
/// Creates a new unconfigured test account.
pub async fn unconfigured(&mut self) -> TestContext {
TestContext::builder()
.with_log_sink(self.log_sink.clone())
.build(Some(&mut self.used_names))
.await
}
/// Writes info events to the log that mark a section, e.g.:
/// Prints a section to stdout, e.g.:
///
/// ========== `msg` goes here ==========
pub fn section(&self, msg: &str) {
self.log_sink
.sender
.try_send(LogEvent::Section(msg.to_string()))
.expect(
"The events channel should be unbounded and not closed, so try_send() shouldn't fail",
);
println!("\n========== {msg} ==========");
}
/// - Let one TestContext send a message
@@ -330,18 +311,6 @@ pub struct TestContextBuilder {
/// Email address.
address: Option<String>,
/// Log sink if set.
///
/// If log sink is not set,
/// a new one will be created and stored
/// inside the test context when it is built.
/// If log sink is provided by the caller,
/// it will be subscribed to the test context,
/// but not stored inside of it,
/// so the caller should store the LogSink elsewhere to
/// prevent it from being dropped immediately.
log_sink: Option<LogSink>,
/// Offset for chat-,message-,contact ids.
///
/// This makes tests fail where ids from different accounts were mixed up.
@@ -412,17 +381,6 @@ impl TestContextBuilder {
self
}
/// Attaches a [`LogSink`] to this [`TestContext`].
///
/// This is useful when using multiple [`TestContext`] instances in one test: it allows
/// using a single [`LogSink`] for both contexts. This shows the log messages in
/// sequence as they occurred rather than all messages from each context in a single
/// block.
pub fn with_log_sink(mut self, sink: LogSink) -> Self {
self.log_sink = Some(sink);
self
}
/// Adds an offset for chat-, message-, contact IDs.
///
/// This makes it harder to accidentally mix up IDs from different accounts.
@@ -449,7 +407,7 @@ impl TestContextBuilder {
used_names.insert(unused_name.clone());
}
let test_context = TestContext::new_internal(Some(unused_name), self.log_sink).await;
let test_context = TestContext::new_internal(Some(unused_name)).await;
test_context.configure_addr(&addr).await;
key::store_self_keypair(&test_context, &key_pair)
.await
@@ -472,7 +430,7 @@ impl TestContextBuilder {
test_context
} else {
TestContext::new_internal(None, self.log_sink).await
TestContext::new_internal(None).await
}
}
}
@@ -487,15 +445,7 @@ pub struct TestContext {
pub evtracker: EventTracker,
/// Reference to implicit [`LogSink`] so it is dropped together with the context.
///
/// Only used if no explicit `log_sender` is passed into [`TestContext::new_internal`]
/// (which is assumed to be the sending end of a [`LogSink`]).
///
/// This is a convenience in case only a single [`TestContext`] is used to avoid dealing
/// with [`LogSink`]. Never read, since the only purpose is to
/// control when Drop is invoked.
_log_sink: Option<LogSink>,
log_sink: LogSink,
}
impl TestContext {
@@ -512,7 +462,7 @@ impl TestContext {
///
/// [Context]: crate::context::Context
pub async fn new() -> Self {
Self::new_internal(None, None).await
Self::new_internal(None).await
}
/// Creates a new configured [`TestContext`].
@@ -563,11 +513,7 @@ impl TestContext {
///
/// `name` is used to identify this context in e.g. log output. This is useful mostly
/// when you have multiple [`TestContext`]s in a test.
///
/// `log_sender` is assumed to be the sender for a [`LogSink`]. If not supplied a new
/// [`LogSink`] will be created so that events are logged to this test when the
/// [`TestContext`] is dropped.
async fn new_internal(name: Option<String>, log_sink: Option<LogSink>) -> Self {
async fn new_internal(name: Option<String>) -> Self {
let dir = tempdir().unwrap();
let dbfile = dir.path().join("db.sqlite");
let id = rand::random();
@@ -581,16 +527,8 @@ impl TestContext {
.await
.expect("failed to create context");
let _log_sink = if let Some(log_sink) = log_sink {
// Subscribe existing LogSink and don't store reference to it.
log_sink.subscribe(ctx.get_event_emitter());
None
} else {
// Create new LogSink and store it inside the `TestContext`.
let log_sink = LogSink::new();
log_sink.subscribe(ctx.get_event_emitter());
Some(log_sink)
};
let log_sink = LogSink::new();
log_sink.subscribe(ctx.get_event_emitter());
ctx.set_config(Config::SkipStartMessages, Some("1"))
.await
@@ -602,7 +540,7 @@ impl TestContext {
ctx,
dir,
evtracker: EventTracker::new(evtracker_receiver),
_log_sink,
log_sink,
}
}
@@ -895,8 +833,8 @@ ORDER BY id"
.expect("add_or_lookup");
match modified {
Modifier::None => (),
Modifier::Modified => warn!(&self.ctx, "Contact {} modified by TestContext", &addr),
Modifier::Created => warn!(&self.ctx, "Contact {} created by TestContext", &addr),
Modifier::Modified => info!(&self.ctx, "Contact {} modified by TestContext", &addr),
Modifier::Created => info!(&self.ctx, "Contact {} created by TestContext", &addr),
}
contact_id
}
@@ -1233,6 +1171,33 @@ ORDER BY id"
self.set_config_bool(Config::ForceEncryption, false).await?;
Ok(())
}
/// Asserts a warning containing `pat` should be logged.
///
/// Delegates to [`InnerLogSink::assert_warn`].
pub async fn assert_warn(&self, pat: &str) {
self.log_sink.assert_warn(pat).await
}
/// Asserts an error containing `pat` should be logged.
///
/// Delegates to [`InnerLogSink::assert_error`].
pub async fn assert_error(&self, pat: &str) {
self.log_sink.assert_error(pat).await
}
/// Asserts that a list of errors and/or warnings has been logged,
/// at least one time each and in any order.
///
/// # Important
///
/// Order of `pats` matters: if a log can be matched by multiple patterns,
/// the first one takes precedence.
///
/// Delegates to [`InnerLogSink::assert_warns_or_errors`].
pub async fn assert_warns_or_errors(&self, pats: &[&str]) {
self.log_sink.assert_warns_or_errors(pats).await
}
}
pub async fn encrypt_raw_message(
@@ -1343,25 +1308,9 @@ impl Drop for TestContext {
}
}
pub enum LogEvent {
/// Logged event.
Event(Event),
/// Test output section.
Section(String),
}
/// A receiver of [`Event`]s which will log the events to the captured test stdout.
///
/// Tests redirect the stdout of the test thread and capture this, showing the captured
/// stdout if the test fails. This means printing log messages must be done on the thread
/// of the test itself and not from a spawned task.
///
/// This sink achieves this by printing the events, in the order received, at the time it is
/// dropped. Thus to use you must only make sure this sink is dropped in the test itself.
///
/// To use this create an instance using [`LogSink::new`] and then use the
/// [`TestContextBuilder::with_log_sink`] or use [`TestContextManager`].
/// Panics on [`drop`][`Drop::drop`], if an unexpected warning or error was received.
#[derive(Debug, Clone, Default)]
pub struct LogSink(Arc<InnerLogSink>);
@@ -1382,15 +1331,14 @@ impl Deref for LogSink {
#[derive(Debug)]
pub struct InnerLogSink {
events: Receiver<LogEvent>,
/// Log events receiver.
events: Receiver<Event>,
/// Sender side of the log receiver.
///
/// It is cloned when log sink is subscribed
/// to new event emitter
/// and can be used directly from the test to
/// add "sections" to the log.
sender: Sender<LogEvent>,
/// to new event emitter.
sender: Sender<Event>,
}
impl Default for InnerLogSink {
@@ -1409,16 +1357,118 @@ impl InnerLogSink {
let sender = self.sender.clone();
task::spawn(async move {
while let Some(event) = event_emitter.recv().await {
sender.try_send(LogEvent::Event(event.clone())).ok();
print_event(&event);
sender.try_send(event).ok();
}
});
}
async fn assert(&self, is_error: bool, pat: &str) {
while let Ok(Ok(event)) =
tokio::time::timeout(Duration::from_secs(1), self.events.recv()).await
{
if Self::assert_inner(event, is_error, pat) {
return;
}
}
if is_error {
panic!("Expected an error log.")
} else {
panic!("Expected a warning log.")
}
}
fn assert_inner(log_event: Event, is_error: bool, pat: &str) -> bool {
if let Some(log) = match is_error {
false => log_event.typ.get_warn(),
true => log_event.typ.get_error(),
} {
assert!(log.contains(pat), "'{log}' does not contain '{pat}'.");
true
} else {
if is_error {
assert!(
!log_event.is_warn(),
"Expected a warning log, but found an error log instead.",
);
} else {
assert!(
!log_event.is_error(),
"Expected an error log, but found a warning log instead.",
);
}
false
}
}
/// Asserts that a list of errors and/or warnings has been logged,
/// at least one time each and in any order.
///
/// # Important
///
/// Order of `pats` matters: if a log can be matched by multiple patterns,
/// the first one takes precedence.
pub async fn assert_warns_or_errors(&self, pats: &[&str]) {
let mut hits = BTreeSet::new();
'events: while let Ok(Ok(event)) =
tokio::time::timeout(Duration::from_secs(1), self.events.recv()).await
{
let Some(log) = event.typ.get_warn().or_else(|| event.typ.get_error()) else {
continue 'events;
};
for pat in pats {
if log.contains(*pat) {
hits.insert(*pat);
continue 'events;
}
}
panic!("Unexpected log event: {event:?}.")
}
let mut panic = false;
for pat in pats {
if !hits.contains(*pat) {
eprintln!("Expected at least one error or warning log matching: '{pat}'");
panic = true;
}
}
if panic {
panic!("One or more log assertions weren't met.")
}
}
/// Asserts that a warning containing `pat` should be logged.
pub async fn assert_warn(&self, pat: &str) {
self.assert(false, pat).await
}
/// Asserts that an error containing `pat` should be logged.
pub async fn assert_error(&self, pat: &str) {
self.assert(true, pat).await
}
}
/// Similar to [`assert!`], but doesn't panic if the thread is already panicking.
///
/// [`assert!`]: assert
macro_rules! soft_assert {
($cond:expr, $($arg:tt)+) => {
if std::thread::panicking() {
if !$cond {
eprintln!($($arg)+)
}
} else {
assert!($cond, $($arg)+);
}
};
}
impl Drop for InnerLogSink {
fn drop(&mut self) {
while let Ok(event) = self.events.try_recv() {
print_logevent(&event);
soft_assert!(!event.is_warn(), "Logged an unexpected warning: {event:?}");
soft_assert!(!event.is_error(), "Logged an unexpected error: {event:?}");
}
if std::env::var("DELTACHAT_SAVE_TMP_DB").is_err() {
eprintln!(
@@ -1659,13 +1709,6 @@ pub(crate) async fn get_chat_msg(
Message::load_from_db(&t.ctx, msg_id).await.unwrap()
}
fn print_logevent(logevent: &LogEvent) {
match logevent {
LogEvent::Event(event) => print_event(event),
LogEvent::Section(msg) => println!("\n========== {msg} =========="),
}
}
/// Saves the other account's public key as verified
pub(crate) async fn mark_as_verified(this: &TestContext, other: &TestContext) {
let contact_id = this.add_or_lookup_contact_id(other).await;