WIP: test: Assert log warnings and errors

src/calls/calls_tests.rs

@@ -679,6 +679,10 @@ async fn test_end_text_call() -> Result<()> {
         .unwrap();
     assert_eq!(received2.msg_ids.len(), 1);
     assert_eq!(received2.chat_id, DC_CHAT_ID_TRASH);
+    alice
+        .log_sink
+        .assert_warn("does not refer to a call message")
+        .await;
 
     Ok(())
 }

src/chat/chat_tests.rs

@@ -309,6 +309,9 @@ async fn test_add_contact_to_chat_ex_add_self() {
         .await
         .unwrap();
     assert_eq!(added, false);
+    t.log_sink
+        .assert_warn("Invalid attempt to add self e-mail address to group")
+        .await;
 }
 
 /// Test adding and removing members in a group chat.
@@ -2714,7 +2717,7 @@ async fn test_resend_doesnt_resort_msg() -> Result<()> {
     let mut tcm = TestContextManager::new();
     let alice = &tcm.alice().await;
     let bob = &tcm.bob().await;
-    let alice_grp = create_group(alice, "").await?;
+    let alice_grp = create_group(alice, "group").await?;
     let sent1 = alice.send_text(alice_grp, "hi").await;
     let sent1_ts = Message::load_from_db(alice, sent1.sender_msg_id)
         .await?
@@ -2878,6 +2881,10 @@ async fn test_broadcast_members_cant_see_each_other() -> Result<()> {
         let parsed_by_bob = bob.parse_msg(&vc_pubkey).await;
         assert!(parsed_by_bob.decryption_error.is_some());
 
+        bob.log_sink
+            .assert_warn("Could not find symmetric secret for session key")
+            .await;
+
         charlie.recv_msg_trash(&vc_pubkey).await;
     }
 
@@ -2915,6 +2922,9 @@ async fn test_broadcast_members_cant_see_each_other() -> Result<()> {
 
         let parsed_by_bob = bob.parse_msg(&member_added).await;
         assert!(parsed_by_bob.decryption_error.is_some());
+        bob.log_sink
+            .assert_warn("decryption failed: decrypt_the_ring: missing key")
+            .await;
 
         let rcvd = charlie.recv_msg(&member_added).await;
         assert_eq!(rcvd.param.get_cmd(), SystemMessage::MemberAddedToGroup);
@@ -2947,6 +2957,9 @@ async fn test_broadcast_members_cant_see_each_other() -> Result<()> {
 
         let parsed_by_bob = bob.parse_msg(&member_removed).await;
         assert!(parsed_by_bob.decryption_error.is_some());
+        bob.log_sink
+            .assert_warn("decryption failed: decrypt_the_ring: missing key")
+            .await;
 
         let rcvd = charlie.recv_msg(&member_removed).await;
         assert_eq!(rcvd.param.get_cmd(), SystemMessage::MemberRemovedFromGroup);
@@ -3099,6 +3112,9 @@ async fn test_broadcast_resend_to_new_member() -> Result<()> {
                 .is_some()
         );
         bob.recv_msg_trash(&resent_msg).await;
+        bob.log_sink.assert_warn("missing key").await;
+        bob.log_sink.assert_warn("missing key").await;
+        bob.log_sink.assert_warn("unencrypted message").await;
     }
     assert!(alice.pop_sent_msg_opt().await.is_none());
     Ok(())
@@ -3117,6 +3133,7 @@ async fn test_broadcast_resend_failed_msg_to_new_member() -> Result<()> {
     let alice_msg_id = alice.send_text(alice_bc_id, "text").await.sender_msg_id;
     let mut msg = Message::load_from_db(alice, alice_msg_id).await?;
     message::set_msg_failed(alice, &mut msg, "error").await?;
+    alice.log_sink.assert_warn("error").await;
     let fiona_bc_id = tcm.exec_securejoin_qr(fiona, alice, &qr).await;
     let resent_msg = alice.pop_sent_msg().await;
     let fiona_msg = fiona.recv_msg(&resent_msg).await;
@@ -3208,6 +3225,7 @@ async fn test_broadcast_recipients_sync1() -> Result<()> {
     sync(alice1, alice2).await;
     let a2_chatlist = Chatlist::try_load(alice2, 0, Some("Channel"), None).await?;
     assert!(a2_chatlist.is_empty());
+    alice2.log_sink.assert_warn("No chat for grpid").await;
 
     // Alice1 adds Charlie to the broadcast channel,
     // and now, Alice2 receives the messages
@@ -3223,6 +3241,7 @@ async fn test_broadcast_recipients_sync1() -> Result<()> {
     let request_with_auth = charlie.pop_sent_msg().await;
     alice1.recv_msg_trash(&request_with_auth).await;
     alice2.recv_msg_trash(&request_with_auth).await;
+    alice2.log_sink.assert_warn("unknown grpid").await;
 
     let member_added = alice1.pop_sent_msg().await;
     let a2_charlie_added = alice2.recv_msg(&member_added).await;
@@ -3549,6 +3568,7 @@ async fn test_chat_description(
 
         tcm.section("Check Alice's second device");
         alice2.recv_msg(&sent).await;
+
         let alice2_chat_id = get_chat_id_by_grpid(
             alice2,
             &Chat::load_from_db(alice, alice_chat_id).await?.grpid,
@@ -3935,6 +3955,8 @@ async fn test_leave_broadcast_multidevice() -> Result<()> {
 
     tcm.section("Bob's second device also receives these messages");
     bob1.recv_msg_trash(&vc_pubkey).await;
+    bob1.log_sink.assert_warn("decryption failed").await;
+    bob1.log_sink.assert_warn("unencrypted message").await;
     bob1.recv_msg_trash(&request_with_auth).await;
     bob1.recv_msg(&member_added).await;
 
@@ -4024,6 +4046,7 @@ async fn test_only_broadcast_owner_can_send_1() -> Result<()> {
         "Bob receives an answer, but shows it in a single chat because of a fingerprint mismatch",
     );
     let rcvd = bob.recv_msg(&member_added).await;
+    bob.log_sink.assert_warn("wrong sender").await;
     assert_eq!(rcvd.text, "Member bob@example.net was added.");
 
     let bob_alice_chat_id = bob.get_chat(alice).await.id;
@@ -4088,6 +4111,9 @@ async fn test_only_broadcast_owner_can_send_2() -> Result<()> {
     tcm.section("Alice sends a message, which is trashed");
     let sent = alice.send_text(alice_broadcast_id, "Hi").await;
     bob.recv_msg_trash(&sent).await;
+    bob.log_sink
+        .assert_warn("This sender is not allowed to encrypt with this secret key")
+        .await;
     let EventType::Warning(warning) = bob
         .evtracker
         .get_matching(|ev| matches!(ev, EventType::Warning(_)))
@@ -4201,6 +4227,14 @@ async fn test_encrypt_decrypt_broadcast() -> Result<()> {
 
     tcm.section("If Bob doesn't know the secret, he can't decrypt the message");
     bob_without_secret.recv_msg_trash(&sent).await;
+    bob_without_secret
+        .log_sink
+        .assert_warn("Could not find symmetric secret for session key")
+        .await;
+    bob_without_secret
+        .log_sink
+        .assert_warn("unencrypted message")
+        .await;
 
     Ok(())
 }
@@ -4316,7 +4350,9 @@ async fn test_out_failed_on_all_keys_missing() -> Result<()> {
     let bob = &tcm.bob().await;
     let fiona = &tcm.fiona().await;
 
-    let bob_chat_id = bob.create_group_with_members("", &[alice, fiona]).await;
+    let bob_chat_id = bob
+        .create_group_with_members("group", &[alice, fiona])
+        .await;
     bob.send_text(bob_chat_id, "Gossiping Fiona's key").await;
     alice
         .recv_msg(&bob.send_text(bob_chat_id, "No key gossip").await)
@@ -4328,6 +4364,8 @@ async fn test_out_failed_on_all_keys_missing() -> Result<()> {
     let mut msg = Message::new_text("Hi".to_string());
     send_msg(alice, alice_chat_id, &mut msg).await.ok();
     assert_eq!(msg.id.get_state(alice).await?, MessageState::OutFailed);
+    alice.log_sink.assert_warn("Missing key").await;
+    alice.log_sink.assert_warn("cannot encrypt").await;
     Ok(())
 }
 
@@ -4948,6 +4986,10 @@ async fn test_sync_broadcast_and_send_message() -> Result<()> {
     let bob_broadcast_id = tcm
         .exec_securejoin_qr_multi_device(bob, &[alice1, alice2], &qr)
         .await;
+    bob.log_sink
+        .assert_warn("Could not find symmetric secret for session key")
+        .await;
+    bob.log_sink.assert_warn("unencrypted message").await;
 
     let a2b_contact_id = alice2.add_or_lookup_contact_no_key(bob).await.id;
     assert_eq!(
@@ -5119,7 +5161,7 @@ async fn test_blocked_bob_cant_join_chat() -> Result<()> {
     let alice2_bob_id = alice2.add_or_lookup_contact_id(bob).await;
     Contact::block(alice2, alice2_bob_id).await?;
 
-    let alice1_chat_id = create_group(alice1, "").await?;
+    let alice1_chat_id = create_group(alice1, "group").await?;
     sync(alice1, alice2).await;
     let alice1_chat = Chat::load_from_db(alice1, alice1_chat_id).await?;
     let (alice2_chat_id, _blocked) = get_chat_id_by_grpid(alice2, &alice1_chat.grpid)
@@ -5130,6 +5172,8 @@ async fn test_blocked_bob_cant_join_chat() -> Result<()> {
 
     tcm.exec_securejoin_qr_multi_device(bob, &[alice1, alice2], &qr)
         .await;
+    alice2.log_sink.assert_warn("blocked").await;
+    alice2.log_sink.assert_warn("blocked").await;
     let alice1_bob_id = alice1.add_or_lookup_contact_id(bob).await;
     assert_eq!(get_chat_contacts(alice1, alice1_chat_id).await?.len(), 2);
     // "vg-member-added" from alice1 adds bob for alice2 to provide membership consistency on
@@ -5144,6 +5188,7 @@ async fn test_blocked_bob_cant_join_chat() -> Result<()> {
     remove_contact_from_chat(alice1, alice1_chat_id, alice1_bob_id).await?;
     bob.recv_msg(&alice1.pop_sent_msg().await).await;
     tcm.exec_securejoin_qr(bob, alice1, &qr).await;
+    alice1.log_sink.assert_warn("blocked").await;
     let members = get_chat_contacts(alice1, alice1_chat_id).await?;
     assert_eq!(members.len(), 1);
     assert!(members.contains(&ContactId::SELF));
@@ -5174,6 +5219,9 @@ async fn test_blocked_bob_cant_create_single_chat_via_securejoin() -> Result<()>
     assert_eq!(get_chat_cnt(alice2).await?, chat_cnt);
     tcm.exec_securejoin_qr_multi_device(bob, &[alice1, alice2], &qr)
         .await;
+    for _ in 0..3 {
+        alice2.log_sink.assert_warn("blocked").await;
+    }
     assert_eq!(get_chat_cnt(alice1).await?, chat_cnt + 1);
     assert_eq!(get_chat_cnt(alice2).await?, chat_cnt);
     Ok(())
@@ -5269,6 +5317,7 @@ async fn test_nonimage_with_png_ext() -> Result<()> {
             msg.get_filename().unwrap().contains("screenshot"),
             vt == Viewtype::File
         );
+        alice.log_sink.assert_error("Unknown format").await;
         let msg_bob = bob.recv_msg(&sent_msg).await;
         assert_eq!(msg_bob.viewtype, Viewtype::File);
         assert_eq!(msg_bob.get_filemime().unwrap(), "application/octet-stream");
@@ -5592,6 +5641,7 @@ async fn test_non_member_cannot_modify_member_list() -> Result<()> {
     remove_contact_from_chat(bob, bob_chat_id, bob_alice_contact_id).await?;
     let bob_sent_add_msg = bob.pop_sent_msg().await;
     alice.recv_msg_trash(&bob_sent_add_msg).await;
+    alice.log_sink.assert_warn("no contact id").await;
     assert_eq!(get_chat_contacts(alice, alice_chat_id).await?.len(), 1);
     Ok(())
 }
@@ -5968,6 +6018,9 @@ async fn test_receive_edit_request_after_removal() -> Result<()> {
 
     bob.recv_msg_trash(&sent2).await;
     assert_eq!(bob_chat_id.get_msg_cnt(bob).await?, E2EE_INFO_MSGS);
+    bob.log_sink
+        .assert_warn("Edit message: Database entry does not exist")
+        .await;
 
     Ok(())
 }
@@ -6061,6 +6114,7 @@ async fn test_send_delete_request() -> Result<()> {
     let bob2 = &tcm.bob().await;
     bob2.recv_msg_opt(&sent2).await;
     assert!(bob2.recv_msg_opt(&sent1).await.is_none());
+    bob2.log_sink.assert_warn("not found").await;
 
     // Alice has another device, and there is also nothing at the end
     let alice2 = &tcm.alice().await;
@@ -6352,6 +6406,10 @@ async fn test_create_unencrypted_group_chat() -> Result<()> {
     assert!(res.is_err());
 
     add_contact_to_chat(alice, chat_id, charlie_address_contact_id).await?;
+    alice
+        .log_sink
+        .assert_warn("No good message identifying the chat found")
+        .await;
 
     let chat = Chat::load_from_db(alice, chat_id).await?;
     assert!(!chat.is_encrypted(alice).await?);
@@ -6368,6 +6426,7 @@ async fn test_create_group_invalid_name() -> Result<()> {
     let chat_id = create_group(alice, " ").await?;
     let chat = Chat::load_from_db(alice, chat_id).await?;
     assert_eq!(chat.get_name(), "…");
+    alice.log_sink.assert_error("Invalid chat name").await;
     Ok(())
 }
 
@@ -6391,6 +6450,7 @@ async fn test_no_avatar_in_adhoc_chats() -> Result<()> {
     .await?
     .unwrap()
     .chat_id;
+    alice.log_sink.assert_warn("unencrypted message").await;
 
     // Test that setting avatar in ad hoc group is not possible.
     let file = alice.dir.path().join("avatar.png");

src/configure.rs

@@ -748,7 +748,7 @@ mod tests {
     use crate::config::Config;
     use crate::login_param::EnteredImapLoginParam;
     use crate::sql::update_transport_last_rcvd_timestamp;
-    use crate::test_utils::TestContext;
+    use crate::test_utils::{LogAssertType, TestContext};
     use crate::transport::add_pseudo_transport;
 
     #[tokio::test(flavor = "multi_thread", worker_threads = 2)]
@@ -759,6 +759,15 @@ mod tests {
             .unwrap();
         t.set_config(Config::MailPw, Some("123456")).await.unwrap();
         assert!(t.configure().await.is_err());
+
+        t.log_sink
+            .assert_many(vec![
+                (LogAssertType::Warn, "SMTP failed to connect", 6),
+                (LogAssertType::Warn, "IMAP failed to connect", 6),
+                (LogAssertType::Warn, "DNS resolution", 20),
+                (LogAssertType::Warn, "configure failed", 1),
+            ])
+            .await;
     }
 
     #[tokio::test(flavor = "multi_thread", worker_threads = 2)]

src/contact/contact_tests.rs

@@ -162,7 +162,7 @@ async fn test_search_contacts_from_group() -> Result<()> {
     let bob = &tcm.bob().await;
     let fiona = &tcm.fiona().await;
 
-    let alice_chat_id = chat::create_group(alice, "").await?;
+    let alice_chat_id = chat::create_group(alice, "group").await?;
     let qr = get_securejoin_qr(alice, Some(alice_chat_id)).await?;
     let bob_chat_id = tcm.exec_securejoin_qr(bob, alice, &qr).await;
     tcm.exec_securejoin_qr(fiona, alice, &qr).await;
@@ -224,6 +224,9 @@ async fn test_add_or_lookup() {
         "\nWonderland, Alice <alice@w.de>\n",
     );
     assert_eq!(Contact::add_address_book(&t, book).await.unwrap(), 4);
+    t.log_sink
+        .assert_warn(r#"invalid address "+1234567890""#)
+        .await;
 
     // check first added contact, this modifies authname because it is empty
     let (contact_id, sth_modified) = Contact::add_or_lookup(
@@ -1081,6 +1084,12 @@ async fn test_was_seen_recently_event() -> Result<()> {
             .get_matching(|evt| matches!(evt, EventType::ContactsChanged { .. }))
             .await;
     }
+    // this warning is only printed when `RecentlySeenLoop` is dropped,
+    // so we can't assert it otherwise.
+    drop(recently_seen_loop);
+    bob.log_sink
+        .assert_warn("receiving from an empty and closed channel")
+        .await;
     Ok(())
 }
 

src/context/context_tests.rs

@@ -617,6 +617,12 @@ async fn test_cache_is_cleared_when_io_is_started() -> Result<()> {
     // but it should invalidate the caches:
     alice.start_io().await;
 
+    alice
+        .log_sink
+        .assert_warn("No IMAP connection candidates provided")
+        .await;
+    alice.log_sink.assert_warn("IMAP got rate limited").await;
+
     assert_eq!(
         alice.get_config(Config::Displayname).await?,
         Some("Alice 2".to_string())

src/e2ee.rs

@@ -141,10 +141,9 @@ Sent with my Delta Chat Messenger: https://delta.chat";
 
         let mut msg = Message::new_text("Hello!".to_string());
         assert!(chat::send_msg(alice, chat.id, &mut msg).await.is_err());
-        assert_eq!(
-            msg.error().unwrap(),
-            "\u{26a0}\u{fe0f} Your email provider example.org requires end-to-end encryption which is not setup yet."
-        );
+        let expected_error = "\u{26a0}\u{fe0f} Your email provider example.org requires end-to-end encryption which is not setup yet.";
+        assert_eq!(msg.error().unwrap(), expected_error);
+        alice.log_sink.assert_warn(expected_error).await;
         let info_msg = alice.get_last_msg().await;
         assert_eq!(
             info_msg.get_info_type(),