From b45b1e8f5b33fed85b55ca24eb615d999a325042 Mon Sep 17 00:00:00 2001
From: Kegan Dougal <7190048+kegsay@users.noreply.github.com>
Date: Fri, 22 Mar 2024 10:56:39 +0000
Subject: [PATCH] Waiter: change up the interface to improve dev UX

This does two things:
 - Replace `.Wait` with `.Waitf` forcing test authors to give descriptive
   reasons why they are waiting. This stops awkward error messages that
   just say "timed out after 5s". It's worth noting that in both cases there
   is a file:line_number so you can work out context.
 - Add `.TryWait` which returns an error instead of fatally failing the test.
   This will be used in multiprocess to enable cross-process waiting, by using
   this weaker form in the external process, then waiting for the next poll before
   failing the test.
---
 internal/api/client.go                        |  7 +++-
 internal/api/js/js.go                         | 17 ++++++---
 internal/api/rust/rust.go                     | 21 +++++++----
 internal/tests/client_test.go                 | 10 +++---
 tests/device_keys_test.go                     |  2 +-
 tests/federation_connectivity_test.go         | 14 ++++----
 .../test.go                                   |  2 +-
 tests/key_backup_test.go                      |  4 +--
 tests/membership_acls_test.go                 | 24 ++++++-------
 tests/one_time_keys_test.go                   | 12 +++----
 tests/room_keys_test.go                       | 36 +++++++++----------
 tests/to_device_test.go                       |  4 +--
 12 files changed, 88 insertions(+), 65 deletions(-)

diff --git a/internal/api/client.go b/internal/api/client.go
index 87e6399..3d6e052 100644
--- a/internal/api/client.go
+++ b/internal/api/client.go
@@ -206,7 +206,12 @@ type Event struct {
 }
 
 type Waiter interface {
-	Wait(t ct.TestLike, s time.Duration)
+	// Wait for something to happen, up until the timeout s. If nothing happens,
+	// fail the test with the formatted string provided.
+	Waitf(t ct.TestLike, s time.Duration, format string, args ...any)
+	// Wait for something to happen, up until the timeout s. If nothing happens,
+	// return an error with the formatted string provided.
+	TryWaitf(t ct.TestLike, s time.Duration, format string, args ...any) error
 }
 
 func CheckEventHasBody(body string) func(e Event) bool {
diff --git a/internal/api/js/js.go b/internal/api/js/js.go
index 3b98831..3e89fd4 100644
--- a/internal/api/js/js.go
+++ b/internal/api/js/js.go
@@ -473,7 +473,15 @@ type jsTimelineWaiter struct {
 	client  *JSClient
 }
 
-func (w *jsTimelineWaiter) Wait(t ct.TestLike, s time.Duration) {
+func (w *jsTimelineWaiter) Waitf(t ct.TestLike, s time.Duration, format string, args ...any) {
+	t.Helper()
+	err := w.TryWaitf(t, s, format, args...)
+	if err != nil {
+		ct.Fatalf(t, err.Error())
+	}
+}
+
+func (w *jsTimelineWaiter) TryWaitf(t ct.TestLike, s time.Duration, format string, args ...any) error {
 	t.Helper()
 	updates := make(chan bool, 3)
 	cancel := w.client.listenForUpdates(func(roomID string, ev api.Event) {
@@ -494,17 +502,18 @@ func (w *jsTimelineWaiter) Wait(t ct.TestLike, s time.Duration) {
 		});`, w.roomID, CONSOLE_LOG_CONTROL_STRING,
 	))
 
+	msg := fmt.Sprintf(format, args...)
 	start := time.Now()
 	for {
 		timeLeft := s - time.Since(start)
 		if timeLeft <= 0 {
-			ct.Fatalf(t, "%s (js): Wait[%s]: timed out", w.client.userID, w.roomID)
+			return fmt.Errorf("%s (js): Wait[%s]: timed out: %s", w.client.userID, w.roomID, msg)
 		}
 		select {
 		case <-time.After(timeLeft):
-			ct.Fatalf(t, "%s (js): Wait[%s]: timed out", w.client.userID, w.roomID)
+			return fmt.Errorf("%s (js): Wait[%s]: timed out: %s", w.client.userID, w.roomID, msg)
 		case <-updates:
-			return
+			return nil // event exists
 		}
 	}
 }
diff --git a/internal/api/rust/rust.go b/internal/api/rust/rust.go
index 14eea26..8e1d4ac 100644
--- a/internal/api/rust/rust.go
+++ b/internal/api/rust/rust.go
@@ -604,7 +604,15 @@ type timelineWaiter struct {
 	client  *RustClient
 }
 
-func (w *timelineWaiter) Wait(t ct.TestLike, s time.Duration) {
+func (w *timelineWaiter) Waitf(t ct.TestLike, s time.Duration, format string, args ...any) {
+	t.Helper()
+	err := w.TryWaitf(t, s, format, args...)
+	if err != nil {
+		ct.Fatalf(t, err.Error())
+	}
+}
+
+func (w *timelineWaiter) TryWaitf(t ct.TestLike, s time.Duration, format string, args ...any) error {
 	t.Helper()
 
 	checkForEvent := func() bool {
@@ -629,7 +637,7 @@ func (w *timelineWaiter) Wait(t ct.TestLike, s time.Duration) {
 	}
 
 	if checkForEvent() {
-		return
+		return nil // event exists
 	}
 
 	updates := make(chan bool, 3)
@@ -653,21 +661,22 @@ func (w *timelineWaiter) Wait(t ct.TestLike, s time.Duration) {
 
 	// check again in case it was added after the previous checkForEvent but before AddListener
 	if checkForEvent() {
-		return
+		return nil // event exists
 	}
 
+	msg := fmt.Sprintf(format, args...)
 	// either no timeline or doesn't exist yet, start blocking
 	start := time.Now()
 	for {
 		timeLeft := s - time.Since(start)
 		if timeLeft <= 0 {
-			ct.Fatalf(t, "%s (rust): Wait[%s]: timed out", w.client.userID, w.roomID)
+			return fmt.Errorf("%s (rust): Wait[%s]: timed out: %s", w.client.userID, w.roomID, msg)
 		}
 		select {
 		case <-time.After(timeLeft):
-			ct.Fatalf(t, "%s (rust): Wait[%s]: timed out", w.client.userID, w.roomID)
+			return fmt.Errorf("%s (rust): Wait[%s]: timed out %s", w.client.userID, w.roomID, msg)
 		case <-updates:
-			return
+			return nil // event exists
 		}
 	}
 }
diff --git a/internal/tests/client_test.go b/internal/tests/client_test.go
index 15566e8..aa33053 100644
--- a/internal/tests/client_test.go
+++ b/internal/tests/client_test.go
@@ -92,13 +92,13 @@ func TestReceiveTimeline(t *testing.T) {
 		stopSyncing := client.MustStartSyncing(t)
 		defer stopSyncing()
 		// wait until we see the latest event
-		client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventIDs[len(eventIDs)-1])).Wait(t, 5*time.Second)
+		client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventIDs[len(eventIDs)-1])).Waitf(t, 5*time.Second, "client did not see latest event")
 		// ensure we have backpaginated if we need to. It is valid for a client to only sync the latest
 		// event in the room, so we have to backpaginate here.
 		client.MustBackpaginate(t, roomID, len(eventIDs))
 		// ensure we see all the events
 		for _, eventID := range eventIDs {
-			client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventID)).Wait(t, 5*time.Second)
+			client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventID)).Waitf(t, 5*time.Second, "client did not see event %s", eventID)
 		}
 		// check event content is correct
 		for i, eventID := range eventIDs {
@@ -123,7 +123,7 @@ func TestReceiveTimeline(t *testing.T) {
 		// ensure we see all the events
 		for i, eventID := range eventIDs {
 			t.Logf("waiting for event %d : %s", i, eventID)
-			client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventID)).Wait(t, 5*time.Second)
+			client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventID)).Waitf(t, 5*time.Second, "client did not see event %s", eventID)
 		}
 		// now send another live event and ensure we see it. This ensure we can still wait for events after having
 		// previously waited for events.
@@ -135,7 +135,7 @@ func TestReceiveTimeline(t *testing.T) {
 				"body":    "Final",
 			},
 		})
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "client did not see final message")
 
 		// check event content is correct
 		for i, eventID := range eventIDs {
@@ -165,7 +165,7 @@ func TestCanWaitUntilEventInRoomBeforeRoomIsKnown(t *testing.T) {
 		completed := helpers.NewWaiter()
 		waiter := client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventID))
 		go func() {
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "client did not seee event %s", eventID)
 			completed.Finish()
 		}()
 		t.Logf("waiting for event %s", eventID)
diff --git a/tests/device_keys_test.go b/tests/device_keys_test.go
index caf4ebf..f223c26 100644
--- a/tests/device_keys_test.go
+++ b/tests/device_keys_test.go
@@ -54,7 +54,7 @@ func TestFailedDeviceKeyDownloadRetries(t *testing.T) {
 					t,
 					roomID,
 					api.CheckEventHasBody("checking whether we can send a message"),
-				).Wait(t, 5*time.Second)
+				).Waitf(t, 5*time.Second, "bob did not see alice's decrypted message")
 
 			})
 		})
diff --git a/tests/federation_connectivity_test.go b/tests/federation_connectivity_test.go
index 6991a7a..53a3c8e 100644
--- a/tests/federation_connectivity_test.go
+++ b/tests/federation_connectivity_test.go
@@ -40,7 +40,7 @@ func TestNewUserCannotGetKeysForOfflineServer(t *testing.T) {
 			waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 			evID := alice.SendMessage(t, roomID, wantMsgBody)
 			t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see alice's message '%s'", wantMsgBody)
 
 			// now bob's HS becomes unreachable
 			tc.Deployment.PauseServer(t, "hs2")
@@ -58,7 +58,7 @@ func TestNewUserCannotGetKeysForOfflineServer(t *testing.T) {
 				waiter = alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantUndecryptableMsgBody))
 				undecryptableEventID := charlie.SendMessage(t, roomID, wantUndecryptableMsgBody)
 				t.Logf("alice (%s) waiting for event %s", alice.Type(), undecryptableEventID)
-				waiter.Wait(t, 5*time.Second)
+				waiter.Waitf(t, 5*time.Second, "alice did not see charlie's messages '%s'", wantUndecryptableMsgBody)
 
 				// now bob's server comes back online
 				tc.Deployment.UnpauseServer(t, "hs2")
@@ -76,7 +76,7 @@ func TestNewUserCannotGetKeysForOfflineServer(t *testing.T) {
 				waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 				evID = charlie.SendMessage(t, roomID, wantMsgBody)
 				t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-				waiter.Wait(t, 5*time.Second)
+				waiter.Waitf(t, 5*time.Second, "bob did not see charlie's message '%s'", wantMsgBody)
 
 				// make sure bob cannot decrypt the msg from when his server was offline
 				// TODO: this isn't ideal, see https://github.com/matrix-org/matrix-rust-sdk/issues/2864
@@ -122,11 +122,11 @@ func TestExistingSessionCannotGetKeysForOfflineServer(t *testing.T) {
 			waiter := bob.WaitUntilEventInRoom(t, roomIDab, api.CheckEventHasBody(wantMsgBody))
 			evID := alice.SendMessage(t, roomIDab, wantMsgBody)
 			t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see alice's message: '%s'", wantMsgBody)
 			waiter = bob.WaitUntilEventInRoom(t, roomIDbc, api.CheckEventHasBody(wantMsgBody))
 			evID = charlie.SendMessage(t, roomIDbc, wantMsgBody)
 			t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see charlie's message: '%s'", wantMsgBody)
 
 			// now bob's HS becomes unreachable
 			tc.Deployment.PauseServer(t, "hs2")
@@ -144,13 +144,13 @@ func TestExistingSessionCannotGetKeysForOfflineServer(t *testing.T) {
 			waiter = alice.WaitUntilEventInRoom(t, roomIDab, api.CheckEventHasBody(wantDecryptableMsgBody))
 			decryptableEventID := charlie.SendMessage(t, roomIDab, wantDecryptableMsgBody)
 			t.Logf("alice (%s) waiting for event %s", alice.Type(), decryptableEventID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "alice did not see charlie's message: '%s'", wantDecryptableMsgBody)
 
 			// now bob's server comes back online
 			tc.Deployment.UnpauseServer(t, "hs2")
 
 			waiter = bob.WaitUntilEventInRoom(t, roomIDab, api.CheckEventHasBody(wantDecryptableMsgBody))
-			waiter.Wait(t, 10*time.Second) // longer time to allow for retries
+			waiter.Waitf(t, 10*time.Second, "bob did not see charlie's message: '%s'", wantDecryptableMsgBody) // longer time to allow for retries
 		})
 	})
 }
diff --git a/tests/go_templates/testRoomKeyIsNotCycledOnClientRestartRust/test.go b/tests/go_templates/testRoomKeyIsNotCycledOnClientRestartRust/test.go
index 7623214..3dffaf5 100644
--- a/tests/go_templates/testRoomKeyIsNotCycledOnClientRestartRust/test.go
+++ b/tests/go_templates/testRoomKeyIsNotCycledOnClientRestartRust/test.go
@@ -36,7 +36,7 @@ func main() {
 	fmt.Println("Sent event " + eventID + " waiting for remote echo")
 
 	waiter := client.WaitUntilEventInRoom(t, roomID, api.CheckEventHasEventID(eventID))
-	waiter.Wait(t, 5*time.Second)
+	waiter.Waitf(t, 5*time.Second, "client did not see event %s", eventID)
 
 	time.Sleep(time.Second)
 	fmt.Println("exiting")
diff --git a/tests/key_backup_test.go b/tests/key_backup_test.go
index c266690..d772e2a 100644
--- a/tests/key_backup_test.go
+++ b/tests/key_backup_test.go
@@ -41,7 +41,7 @@ func TestCanBackupKeys(t *testing.T) {
 			waiter := backupCreator.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(body))
 			evID := backupCreator.SendMessage(t, roomID, body)
 			t.Logf("backupCreator (%s) waiting for event %s", backupCreator.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "backup creator did not see own message %s", evID)
 
 			// Now backupCreator backs up his keys. Some clients may automatically do this, but let's be explicit about it.
 			recoveryKey := backupCreator.MustBackupKeys(t)
@@ -101,7 +101,7 @@ func TestBackupWrongRecoveryKeyFails(t *testing.T) {
 			waiter := backupCreator.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(body))
 			evID := backupCreator.SendMessage(t, roomID, body)
 			t.Logf("backupCreator (%s) waiting for event %s", backupCreator.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "backup creator did not see own message %s", evID)
 
 			// Now backupCreator backs up his keys. Some clients may automatically do this, but let's be explicit about it.
 			recoveryKey := backupCreator.MustBackupKeys(t)
diff --git a/tests/membership_acls_test.go b/tests/membership_acls_test.go
index 3387871..f5f71c6 100644
--- a/tests/membership_acls_test.go
+++ b/tests/membership_acls_test.go
@@ -51,7 +51,7 @@ func TestAliceBobEncryptionWorks(t *testing.T) {
 
 			// Bob receives the message
 			t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 		})
 	})
 }
@@ -115,7 +115,7 @@ func TestCanDecryptMessagesAfterInviteButBeforeJoin(t *testing.T) {
 		sentinelBody := "Sentinel"
 		waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(sentinelBody))
 		alice.SendMessage(t, roomID, sentinelBody)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 
 		// Explicitly ask for a pagination, rather than assuming the SDK will return events
 		// earlier than the join by default. This is important because:
@@ -123,7 +123,7 @@ func TestCanDecryptMessagesAfterInviteButBeforeJoin(t *testing.T) {
 		// - sliding sync (FFI) it won't return events before the join by default, relying on clients using the prev_batch token.
 		waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 		bob.MustBackpaginate(t, roomID, 5) // number is arbitrary, just needs to be >=2
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob did not see backpaginated message")
 	})
 }
 
@@ -143,13 +143,13 @@ func TestBobCanSeeButNotDecryptHistoryInPublicRoom(t *testing.T) {
 			waiter := alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(beforeJoinBody))
 			evID := alice.SendMessage(t, roomID, beforeJoinBody)
 			t.Logf("alice (%s) waiting for event %s", alice.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "alice did not see own message")
 
 			// now bob joins the room
 			tc.Bob.MustJoinRoom(t, roomID, []string{clientTypeA.HS})
 			time.Sleep(time.Second) // wait for it to appear on the client else rust crashes if it cannot find the room FIXME
 			waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(bob.UserID(), "join"))
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see own join")
 
 			// bob hits scrollback and should see but not be able to decrypt the message
 			bob.MustBackpaginate(t, roomID, 5)
@@ -198,24 +198,24 @@ func TestOnRejoinBobCanSeeButNotDecryptHistoryInPublicRoom(t *testing.T) {
 		waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(bothJoinedBody))
 		evID := alice.SendMessage(t, roomID, bothJoinedBody)
 		t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 
 		// now bob leaves the room, wait for alice to see it
 		waiter = alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(bob.UserID(), "leave"))
 		tc.Bob.MustLeaveRoom(t, roomID)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "alice did not see bob's leave")
 
 		// now alice sends another message, which should use a key that bob does not have. Wait for the remote echo to come back.
 		onlyAliceBody := "Only me on my lonesome"
 		waiter = alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(onlyAliceBody))
 		evID = alice.SendMessage(t, roomID, onlyAliceBody)
 		t.Logf("alice (%s) waiting for event %s", alice.Type(), evID)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "alice did not see own message")
 
 		// now bob rejoins the room, wait until he sees it.
 		tc.Bob.MustJoinRoom(t, roomID, []string{clientTypeA.HS})
 		waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(bob.UserID(), "join"))
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob did not see own join")
 		// this is required for some reason else tests fail
 		time.Sleep(time.Second)
 
@@ -270,7 +270,7 @@ func TestOnNewDeviceBobCanSeeButNotDecryptHistoryInPublicRoom(t *testing.T) {
 		waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(onlyFirstDeviceBody))
 		evID := alice.SendMessage(t, roomID, onlyFirstDeviceBody)
 		t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 
 		// now bob logs in on a new device. He should NOT be able to decrypt this event (though can see it due to history visibility)
 		csapiBob2 := tc.MustRegisterNewDevice(t, tc.Bob, clientTypeB.HS, "NEW_DEVICE")
@@ -294,7 +294,7 @@ func TestOnNewDeviceBobCanSeeButNotDecryptHistoryInPublicRoom(t *testing.T) {
 		waiter = bob2.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(decryptableBody))
 		evID = alice.SendMessage(t, roomID, decryptableBody)
 		t.Logf("bob2 (%s) waiting for event %s", bob2.Type(), evID)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob2 did not see alice's message")
 
 		// now bob logs out
 		bob2StopSyncing()
@@ -310,7 +310,7 @@ func TestOnNewDeviceBobCanSeeButNotDecryptHistoryInPublicRoom(t *testing.T) {
 		waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(undecryptableBody))
 		evID = alice.SendMessage(t, roomID, undecryptableBody)
 		t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob did not see alice's event %s", evID)
 
 		// now bob logs in again
 		bob2 = tc.MustLoginClient(t, csapiBob2, clientTypeB)
diff --git a/tests/one_time_keys_test.go b/tests/one_time_keys_test.go
index e7f4b1d..364c4b7 100644
--- a/tests/one_time_keys_test.go
+++ b/tests/one_time_keys_test.go
@@ -134,9 +134,9 @@ func TestFallbackKeyIsUsedIfOneTimeKeysRunOut(t *testing.T) {
 				)
 				tc.Charlie.MustJoinRoom(t, roomID, []string{keyConsumerClientType.HS})
 				tc.Alice.MustJoinRoom(t, roomID, []string{keyConsumerClientType.HS})
-				charlie.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(alice.UserID(), "join")).Wait(t, 5*time.Second)
-				bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(alice.UserID(), "join")).Wait(t, 5*time.Second)
-				alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(alice.UserID(), "join")).Wait(t, 5*time.Second)
+				charlie.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(alice.UserID(), "join")).Waitf(t, 5*time.Second, "charlie did not see alice's join")
+				bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(alice.UserID(), "join")).Waitf(t, 5*time.Second, "bob did not see alice's join")
+				alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(alice.UserID(), "join")).Waitf(t, 5*time.Second, "alice did not see own join")
 				bob.SendMessage(t, roomID, "Hello world!")
 				charlie.SendMessage(t, roomID, "Goodbye world!")
 				waiter = alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody("Hello world!"))
@@ -146,9 +146,9 @@ func TestFallbackKeyIsUsedIfOneTimeKeysRunOut(t *testing.T) {
 				must.Equal(t, otkCount, 0, "OTKs were uploaded when they should have been blocked by mitmproxy")
 			})
 			// rust sdk needs /keys/upload to 200 OK before it will decrypt the hello world msg
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "alice did not see bob's message")
 			// check charlie's message is also here
-			alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody("Goodbye world!")).Wait(t, 5*time.Second)
+			alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody("Goodbye world!")).Waitf(t, 5*time.Second, "alice did not see charlie's message")
 
 			// now /keys/upload is unblocked, make sure we upload new keys
 			alice.SendMessage(t, roomID, "Kick the client to upload OTKs... hopefully")
@@ -253,7 +253,7 @@ func TestFailedKeysClaimRetries(t *testing.T) {
 				// call /keys/claim. We should retry though.
 				tc.Bob.MustJoinRoom(t, roomID, []string{clientType.HS})
 				time.Sleep(time.Second) // FIXME using WaitUntilEventInRoom panics on rust because the room isn't there yet
-				bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(tc.Bob.UserID, "join")).Wait(t, 5*time.Second)
+				bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(tc.Bob.UserID, "join")).Waitf(t, 5*time.Second, "bob did not see own join event")
 
 				// Now send a message. On Rust, just sending 1 msg is enough to kick retry schedule.
 				// JS SDK won't retry the /keys/claim automatically. Try sending another event to kick it.
diff --git a/tests/room_keys_test.go b/tests/room_keys_test.go
index 46362e8..fb23eaf 100644
--- a/tests/room_keys_test.go
+++ b/tests/room_keys_test.go
@@ -47,14 +47,14 @@ func TestRoomKeyIsCycledOnDeviceLogout(t *testing.T) {
 					EncRoomOptions.Invite([]string{tc.Bob.UserID}),
 				)
 				tc.Bob.MustJoinRoom(t, roomID, []string{clientTypeA.HS})
-				alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(tc.Bob.UserID, "join")).Wait(t, 5*time.Second)
+				alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(tc.Bob.UserID, "join")).Waitf(t, 5*time.Second, "alice did not see own join")
 				// check the room works
 				wantMsgBody := "Test Message"
 				waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 				waiter2 := alice2.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 				alice.SendMessage(t, roomID, wantMsgBody)
-				waiter.Wait(t, 5*time.Second)
-				waiter2.Wait(t, 5*time.Second)
+				waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
+				waiter2.Waitf(t, 5*time.Second, "alice2 did not see alice's message")
 
 				// we're going to sniff calls to /sendToDevice to ensure we see the new room key being sent.
 				ch := make(chan deploy.CallbackData, 10)
@@ -82,7 +82,7 @@ func TestRoomKeyIsCycledOnDeviceLogout(t *testing.T) {
 					wantMsgBody = "Another Test Message"
 					waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 					alice.SendMessage(t, roomID, wantMsgBody)
-					waiter.Wait(t, 5*time.Second)
+					waiter.Waitf(t, 5*time.Second, "bob did not see alice's new message")
 				})
 
 				// we should have seen a /sendToDevice call by now. If we didn't, this implies we didn't cycle
@@ -126,7 +126,7 @@ func TestRoomKeyIsCycledAfterEnoughMessages(t *testing.T) {
 				wantMsgBody := "Before we hit the threshold"
 				waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 				alice.SendMessage(t, roomID, wantMsgBody)
-				waiter.Wait(t, 5*time.Second)
+				waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 			}
 
 			// Sniff calls to /sendToDevice to ensure we see the new room key being sent.
@@ -150,12 +150,12 @@ func TestRoomKeyIsCycledAfterEnoughMessages(t *testing.T) {
 				// of these approaches will pass the test.
 				waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 				alice.SendMessage(t, roomID, wantMsgBody)
-				waiter.Wait(t, 5*time.Second)
+				waiter.Waitf(t, 5*time.Second, "bob did not see alice's message '%s'", wantMsgBody)
 
 				wantMsgBody = "After the threshold"
 				waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 				alice.SendMessage(t, roomID, wantMsgBody)
-				waiter.Wait(t, 5*time.Second)
+				waiter.Waitf(t, 5*time.Second, "bob did not seee alice's message '%s'", wantMsgBody)
 			})
 
 			// Then we did send out new keys
@@ -184,14 +184,14 @@ func TestRoomKeyIsCycledOnMemberLeaving(t *testing.T) {
 			)
 			tc.Bob.MustJoinRoom(t, roomID, []string{clientTypeA.HS})
 			tc.Charlie.MustJoinRoom(t, roomID, []string{clientTypeA.HS})
-			alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(tc.Charlie.UserID, "join")).Wait(t, 5*time.Second)
+			alice.WaitUntilEventInRoom(t, roomID, api.CheckEventHasMembership(tc.Charlie.UserID, "join")).Waitf(t, 5*time.Second, "alice did not see charlie's join")
 			// check the room works
 			wantMsgBody := "Test Message"
 			waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 			waiter2 := charlie.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 			alice.SendMessage(t, roomID, wantMsgBody)
-			waiter.Wait(t, 5*time.Second)
-			waiter2.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
+			waiter2.Waitf(t, 5*time.Second, "charlie did not see alice's message")
 
 			// we're going to sniff calls to /sendToDevice to ensure we see the new room key being sent.
 			ch := make(chan deploy.CallbackData, 10)
@@ -218,7 +218,7 @@ func TestRoomKeyIsCycledOnMemberLeaving(t *testing.T) {
 				wantMsgBody = "Another Test Message"
 				waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 				alice.SendMessage(t, roomID, wantMsgBody)
-				waiter.Wait(t, 5*time.Second)
+				waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 			})
 
 			// we should have seen a /sendToDevice call by now. If we didn't, this implies we didn't cycle
@@ -249,7 +249,7 @@ func TestRoomKeyIsNotCycled(t *testing.T) {
 			wantMsgBody := "Test Message"
 			waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 			alice.SendMessage(t, roomID, wantMsgBody)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 
 			// we're going to sniff calls to /sendToDevice to ensure we see the new room key being sent.
 			ch := make(chan deploy.CallbackData, 10)
@@ -279,7 +279,7 @@ func TestRoomKeyIsNotCycled(t *testing.T) {
 					wantMsgBody = "Another Test Message"
 					waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 					alice.SendMessage(t, roomID, wantMsgBody)
-					waiter.Wait(t, 5*time.Second)
+					waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 				})
 
 				// we should have seen a /sendToDevice call by now. If we didn't, this implies we didn't cycle
@@ -319,7 +319,7 @@ func TestRoomKeyIsNotCycled(t *testing.T) {
 					wantMsgBody = "Yet Another Test Message"
 					waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 					alice.SendMessage(t, roomID, wantMsgBody)
-					waiter.Wait(t, 5*time.Second)
+					waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 				})
 
 				// we should have seen a /sendToDevice call by now. If we didn't, this implies we didn't cycle
@@ -419,7 +419,7 @@ func testRoomKeyIsNotCycledOnClientRestartRust(t *testing.T, clientType api.Clie
 		must.NotError(t, "failed to run script", cmd.Run())
 
 		waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
-		waiter.Wait(t, 8*time.Second)
+		waiter.Waitf(t, 8*time.Second, "bob did not see alice's message")
 
 		// the script sent the msg and exited cleanly.
 		// Now recreate the same client and make sure we don't send new room keys.
@@ -448,7 +448,7 @@ func testRoomKeyIsNotCycledOnClientRestartRust(t *testing.T, clientType api.Clie
 			wantMsgBody = "Another Test Message"
 			waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 			alice.SendMessage(t, roomID, wantMsgBody)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 		})
 
 		// we should have seen a /sendToDevice call by now. If we didn't, this implies we didn't cycle
@@ -484,7 +484,7 @@ func testRoomKeyIsNotCycledOnClientRestartJS(t *testing.T, clientType api.Client
 	wantMsgBody := "Test Message"
 	waiter := bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 	alice.SendMessage(t, roomID, wantMsgBody)
-	waiter.Wait(t, 5*time.Second)
+	waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 
 	// we're going to sniff calls to /sendToDevice to ensure we do NOT see a new room key being sent.
 	ch := make(chan deploy.CallbackData, 10)
@@ -512,7 +512,7 @@ func testRoomKeyIsNotCycledOnClientRestartJS(t *testing.T, clientType api.Client
 		wantMsgBody = "Another Test Message"
 		waiter = bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody(wantMsgBody))
 		alice.SendMessage(t, roomID, wantMsgBody)
-		waiter.Wait(t, 5*time.Second)
+		waiter.Waitf(t, 5*time.Second, "bob did not see alice's message")
 	})
 
 	// we should have seen a /sendToDevice call by now. If we didn't, this implies we didn't cycle
diff --git a/tests/to_device_test.go b/tests/to_device_test.go
index 498c8ad..2fe5ac7 100644
--- a/tests/to_device_test.go
+++ b/tests/to_device_test.go
@@ -54,7 +54,7 @@ func TestClientRetriesSendToDevice(t *testing.T) {
 
 			// Bob receives the message
 			t.Logf("bob (%s) waiting for event %s", bob.Type(), evID)
-			waiter.Wait(t, 5*time.Second)
+			waiter.Waitf(t, 5*time.Second, "bob did not see event with body '%s'", wantMsgBody)
 		})
 	})
 }
@@ -87,7 +87,7 @@ func TestUnprocessedToDeviceMessagesArentLostOnRestart(t *testing.T) {
 			tc.WithClientSyncing(t, tc.AliceClientType, alice2, func(alice2 api.Client) { // sync to ensure alice2 has keys uploaded
 				// check the room works
 				alice.SendMessage(t, roomID, "Hello World!")
-				bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody("Hello World!")).Wait(t, 2*time.Second)
+				bob.WaitUntilEventInRoom(t, roomID, api.CheckEventHasBody("Hello World!")).Waitf(t, 2*time.Second, "bob did not see event with body 'Hello World!'")
 			})
 			// stop bob's client
 			bobStopSyncing()