fix(tests): tweak a flaky test to make it more stable + logs (#4968)

Tentative fix for
#4832

Tweaked a bit the timings and added more logging in the UTD manager to
see what is happening exactly in case it is still flaky.

Signed-off-by: Damir Jelić <poljar@termina.org.uk>
Co-authored-by: Damir Jelić <poljar@termina.org.uk>
Co-authored-by: Benjamin Bouvier <benjamin@bouvier.cc>

Author: 3 people

crates/matrix-sdk-ui/src/timeline/tests/encryption.rs

@@ -194,8 +194,9 @@ async fn test_false_positive_late_decryption_regression() {
 
     let hook = Arc::new(DummyUtdHook::default());
     let client = test_client_builder(None).build().await.unwrap();
-    let utd_hook =
-        Arc::new(UtdHookManager::new(hook.clone(), client).with_max_delay(Duration::from_secs(1)));
+    let utd_hook = Arc::new(
+        UtdHookManager::new(hook.clone(), client).with_max_delay(Duration::from_millis(500)),
+    );
 
     let timeline = TestTimelineBuilder::new().unable_to_decrypt_hook(utd_hook.clone()).build();
 
@@ -229,6 +230,11 @@ async fn test_false_positive_late_decryption_regression() {
     let own_user_id = user_id!("@example:morheus.localhost");
     let olm_machine = OlmMachine::new(own_user_id, "SomeDeviceId".into()).await;
 
+    sleep(Duration::from_millis(200)).await;
+
+    // Simulate a retry decryption.
+    // Due to the regression this was marking the event as successfully decrypted on
+    // retry
     timeline
         .controller
         .retry_event_decryption_test(

crates/matrix-sdk-ui/src/unable_to_decrypt_hook.rs

@@ -36,7 +36,7 @@ use ruma::{
     EventId, MilliSecondsSinceUnixEpoch, OwnedEventId, OwnedServerName, UserId,
 };
 use tokio::sync::{Mutex as AsyncMutex, MutexGuard};
-use tracing::error;
+use tracing::{error, trace};
 
 /// A generic interface which methods get called whenever we observe a
 /// unable-to-decrypt (UTD) event.
@@ -234,6 +234,7 @@ impl UtdHookManager {
         event_timestamp: MilliSecondsSinceUnixEpoch,
         sender_user_id: &UserId,
     ) {
+        trace!(%event_id, "UtdHookManager: Observed UTD");
         // Hold the lock on `reported_utds` throughout, to avoid races with other
         // threads.
         let mut reported_utds_lock = self.reported_utds.lock().await;
@@ -331,6 +332,7 @@ impl UtdHookManager {
     /// Note: if this is called for an event that was never marked as a UTD
     /// before, it has no effect.
     pub(crate) async fn on_late_decrypt(&self, event_id: &EventId) {
+        trace!(%event_id, "UtdHookManager: On late decrypt");
         // Hold the lock on `reported_utds` throughout, to avoid races with other
         // threads.
         let mut reported_utds_lock = self.reported_utds.lock().await;
@@ -339,6 +341,7 @@ impl UtdHookManager {
         // a pending UTD. If so, remove the event from the pending list —
         // doing so will cause the reporting task to no-op if it runs.
         let Some(pending_utd_report) = self.pending_delayed.lock().unwrap().remove(event_id) else {
+            trace!(%event_id, "UtdHookManager: received a late decrypt report for an unknown utd");
             return;
         };