Improve readability of test failures (#386)

pkg/rtc/room_test.go

@@ -323,24 +323,27 @@ func TestActiveSpeakers(t *testing.T) {
 		require.NotEmpty(t, speakers)
 		require.Equal(t, string(p.ID()), speakers[0].Sid)
 
-		testutils.WithTimeout(t, "ensure everyone has gotten an audio update", func() bool {
+		testutils.WithTimeout(t, func() string {
 			for _, op := range participants {
 				op := op.(*typesfakes.FakeLocalParticipant)
 				updates := getActiveSpeakerUpdates(op)
 				if len(updates) == 0 {
-					return false
+					return fmt.Sprintf("%s did not get any audio updates", op.Identity())
 				}
 			}
-			return true
+			return ""
 		})
 
 		// no longer speaking, send update with empty items
 		p.GetAudioLevelReturns(127, false)
 
-		testutils.WithTimeout(t, "ensure no one is speaking", func() bool {
+		testutils.WithTimeout(t, func() string {
 			updates := getActiveSpeakerUpdates(p)
 			lastUpdate := updates[len(updates)-1]
-			return len(lastUpdate.Speakers) == 0
+			if len(lastUpdate.Speakers) != 0 {
+				return fmt.Sprintf("expected no speakers, but found %d", len(lastUpdate.Speakers))
+			}
+			return ""
 		})
 	})
 
@@ -353,48 +356,48 @@ func TestActiveSpeakers(t *testing.T) {
 		p.GetAudioLevelReturns(30, true)
 		convertedLevel := rtc.ConvertAudioLevel(30)
 
-		testutils.WithTimeout(t, "checking first update is received", func() bool {
+		testutils.WithTimeout(t, func() string {
 			updates := getActiveSpeakerUpdates(op)
 			if len(updates) == 0 {
-				return false
+				return "no speaker updates received"
 			}
 			lastSpeakers := updates[len(updates)-1].Speakers
 			if len(lastSpeakers) == 0 {
-				return false
+				return "no speakers in the update"
 			}
 			if lastSpeakers[0].Level > convertedLevel {
-				return true
+				return ""
 			}
-			return false
+			return "level mismatch"
 		})
 
-		testutils.WithTimeout(t, "eventually reaches actual levels", func() bool {
+		testutils.WithTimeout(t, func() string {
 			updates := getActiveSpeakerUpdates(op)
 			if len(updates) == 0 {
-				return false
+				return "no updates received"
 			}
 			lastSpeakers := updates[len(updates)-1].Speakers
 			if len(lastSpeakers) == 0 {
-				return false
+				return "no speakers found"
 			}
 			if lastSpeakers[0].Level > convertedLevel {
-				return true
+				return ""
 			}
-			return false
+			return "did not match expected levels"
 		})
 
 		p.GetAudioLevelReturns(127, false)
 
-		testutils.WithTimeout(t, "eventually goes back to 0", func() bool {
+		testutils.WithTimeout(t, func() string {
 			updates := getActiveSpeakerUpdates(op)
 			if len(updates) == 0 {
-				return false
+				return "no speaker updates received"
 			}
 			lastSpeakers := updates[len(updates)-1].Speakers
 			if len(lastSpeakers) == 0 {
-				return true
+				return ""
 			}
-			return false
+			return "speakers didn't go back to zero"
 		})
 	})
 }

pkg/rtc/transport_test.go

@@ -37,9 +37,15 @@ func TestMissingAnswerDuringICERestart(t *testing.T) {
 	require.NoError(t, transportA.CreateAndSendOffer(nil))
 
 	// ensure we are connected the first time
-	testutils.WithTimeout(t, "initial ICE connectivity", func() bool {
-		return transportA.pc.ICEConnectionState() == webrtc.ICEConnectionStateConnected &&
-			transportB.pc.ICEConnectionState() == webrtc.ICEConnectionStateConnected
+	testutils.WithTimeout(t, func() string {
+		if transportA.pc.ICEConnectionState() != webrtc.ICEConnectionStateConnected {
+			return "transportA did not become connected"
+		}
+
+		if transportB.pc.ICEConnectionState() != webrtc.ICEConnectionStateConnected {
+			return "transportB did not become connected"
+		}
+		return ""
 	})
 	require.Equal(t, webrtc.ICEConnectionStateConnected, transportA.pc.ICEConnectionState())
 	require.Equal(t, webrtc.ICEConnectionStateConnected, transportB.pc.ICEConnectionState())
@@ -57,9 +63,14 @@ func TestMissingAnswerDuringICERestart(t *testing.T) {
 		ICERestart: true,
 	}))
 
-	testutils.WithTimeout(t, "restarted ICE connectivity", func() bool {
-		return transportA.pc.ICEConnectionState() == webrtc.ICEConnectionStateConnected &&
-			transportB.pc.ICEConnectionState() == webrtc.ICEConnectionStateConnected
+	testutils.WithTimeout(t, func() string {
+		if transportA.pc.ICEConnectionState() != webrtc.ICEConnectionStateConnected {
+			return "transportA did not reconnect after ICE restart"
+		}
+		if transportB.pc.ICEConnectionState() != webrtc.ICEConnectionStateConnected {
+			return "transportB did not reconnect after ICE restart"
+		}
+		return ""
 	})
 }
 

pkg/sfu/streamtracker_test.go

@@ -1,6 +1,7 @@
 package sfu
 
 import (
+	"fmt"
 	"testing"
 	"time"
 
@@ -21,8 +22,12 @@ func TestStreamTracker(t *testing.T) {
 		// observe first packet
 		tracker.Observe(1)
 
-		testutils.WithTimeout(t, "first packet makes stream active", func() bool {
-			return callbackCalled.get()
+		testutils.WithTimeout(t, func() string {
+			if callbackCalled.get() {
+				return ""
+			} else {
+				return "first packet didn't activate stream"
+			}
 		})
 
 		require.Equal(t, StreamStatusActive, tracker.Status())
@@ -34,8 +39,12 @@ func TestStreamTracker(t *testing.T) {
 		require.Equal(t, StreamStatusStopped, tracker.Status())
 
 		tracker.Observe(1)
-		testutils.WithTimeout(t, "first packet makes stream active", func() bool {
-			return tracker.Status() == StreamStatusActive
+		testutils.WithTimeout(t, func() string {
+			if tracker.Status() == StreamStatusActive {
+				return ""
+			} else {
+				return "first packet did not activate stream"
+			}
 		})
 
 		callbackCalled := atomicBool(0)
@@ -55,8 +64,12 @@ func TestStreamTracker(t *testing.T) {
 		require.Equal(t, StreamStatusStopped, tracker.Status())
 
 		tracker.Observe(1)
-		testutils.WithTimeout(t, "first packet makes stream active", func() bool {
-			return tracker.Status() == StreamStatusActive
+		testutils.WithTimeout(t, func() string {
+			if tracker.Status() == StreamStatusActive {
+				return ""
+			} else {
+				return "first packet did not activate stream"
+			}
 		})
 
 		tracker.maybeSetStopped()
@@ -73,8 +86,12 @@ func TestStreamTracker(t *testing.T) {
 	t.Run("does not change to inactive when paused", func(t *testing.T) {
 		tracker := NewStreamTracker(5, 60, 500*time.Millisecond)
 		tracker.Observe(1)
-		testutils.WithTimeout(t, "first packet makes stream active", func() bool {
-			return tracker.Status() == StreamStatusActive
+		testutils.WithTimeout(t, func() string {
+			if tracker.Status() == StreamStatusActive {
+				return ""
+			} else {
+				return "first packet did not activate stream"
+			}
 		})
 
 		tracker.SetPaused(true)
@@ -93,8 +110,12 @@ func TestStreamTracker(t *testing.T) {
 		// observe first packet
 		tracker.Observe(1)
 
-		testutils.WithTimeout(t, "first packet makes stream active", func() bool {
-			return callbackCalled.get() == 1
+		testutils.WithTimeout(t, func() string {
+			if callbackCalled.get() == 1 {
+				return ""
+			} else {
+				return fmt.Sprintf("expected onStatusChanged to be called once, actual: %d", callbackCalled.get())
+			}
 		})
 
 		require.Equal(t, StreamStatusActive, tracker.Status())
@@ -117,8 +138,12 @@ func TestStreamTracker(t *testing.T) {
 		// first packet after reset
 		tracker.Observe(1)
 
-		testutils.WithTimeout(t, "first packet after reset makes stream active", func() bool {
-			return callbackCalled.get() == 2
+		testutils.WithTimeout(t, func() string {
+			if callbackCalled.get() == 2 {
+				return ""
+			} else {
+				return fmt.Sprintf("expected onStatusChanged to be called twice, actual %d", callbackCalled.get())
+			}
 		})
 
 		require.Equal(t, StreamStatusActive, tracker.Status())

pkg/testutils/timeout.go

@@ -4,26 +4,24 @@ import (
 	"context"
 	"testing"
 	"time"
-
-	"github.com/livekit/protocol/logger"
 )
 
 var (
 	ConnectTimeout = 30 * time.Second
 )
 
-func WithTimeout(t *testing.T, description string, f func() bool) bool {
-	logger.Infow(description)
+func WithTimeout(t *testing.T, f func() string) {
 	ctx, cancel := context.WithTimeout(context.Background(), ConnectTimeout)
 	defer cancel()
+	lastErr := ""
 	for {
 		select {
 		case <-ctx.Done():
-			t.Fatal("timed out: " + description)
-			return false
+			t.Fatal("timed out: " + lastErr)
 		case <-time.After(10 * time.Millisecond):
-			if f() {
-				return true
+			lastErr = f()
+			if lastErr == "" {
+				return
 			}
 		}
 	}

test/multinode_roomservice_test.go

@@ -1,6 +1,7 @@
 package test
 
 import (
+	"fmt"
 	"testing"
 
 	"github.com/livekit/livekit-server/pkg/testutils"
@@ -132,13 +133,17 @@ func TestMultiNodeMutePublishedTrack(t *testing.T) {
 
 	ctx := contextWithToken(adminRoomToken(testRoom))
 	// wait for it to be published before
-	testutils.WithTimeout(t, "ensure track is published", func() bool {
+	testutils.WithTimeout(t, func() string {
 		res, err := roomClient.GetParticipant(ctx, &livekit.RoomParticipantIdentity{
 			Room:     testRoom,
 			Identity: identity,
 		})
 		require.NoError(t, err)
-		return len(res.Tracks) == 2
+		if len(res.Tracks) == 2 {
+			return ""
+		} else {
+			return fmt.Sprintf("expected two tracks to be published, actual: %d", len(res.Tracks))
+		}
 	})
 
 	res, err := roomClient.MutePublishedTrack(ctx, &livekit.MuteRoomTrackRequest{

test/multinode_test.go

@@ -39,19 +39,17 @@ func TestMultiNodeRouting(t *testing.T) {
 		defer t1.Stop()
 	}
 
-	testutils.WithTimeout(t, "c2 should receive one track", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if len(c2.SubscribedTracks()) == 0 {
-			return false
+			return "c2 received no tracks"
 		}
-		// should have received two tracks
 		if len(c2.SubscribedTracks()[c1.ID()]) != 1 {
-			return false
+			return "c2 didn't receive track published by c1"
 		}
-
 		tr1 := c2.SubscribedTracks()[c1.ID()][0]
 		streamID, _ := rtc.UnpackStreamID(tr1.StreamID())
 		require.Equal(t, c1.ID(), streamID)
-		return true
+		return ""
 	})
 
 	remoteC1 := c2.GetRemoteParticipant(c1.ID())
@@ -176,8 +174,12 @@ func TestMultiNodeRefreshToken(t *testing.T) {
 	})
 	require.NoError(t, err)
 
-	testutils.WithTimeout(t, "waiting for refresh token", func() bool {
-		return c1.RefreshToken() != ""
+	testutils.WithTimeout(t, func() string {
+		if c1.RefreshToken() != "" {
+			return ""
+		} else {
+			return "did not receive refresh token"
+		}
 	})
 
 	// parse token to ensure it's correct

test/scenarios.go

@@ -1,6 +1,7 @@
 package test
 
 import (
+	"fmt"
 	"testing"
 	"time"
 
@@ -26,42 +27,36 @@ func scenarioPublishingUponJoining(t *testing.T) {
 	defer stopWriters(writers...)
 
 	logger.Infow("waiting to receive tracks from c1 and c2")
-	success := testutils.WithTimeout(t, "c3 should receive tracks from both clients", func() bool {
+	testutils.WithTimeout(t, func() string {
 		tracks := c3.SubscribedTracks()
 		if len(tracks[c1.ID()]) != 2 {
-			return false
+			return "did not receive tracks from c1"
 		}
 		if len(tracks[c2.ID()]) != 2 {
-			return false
+			return "did not receive tracks from c2"
 		}
-		return true
+		return ""
 	})
 
-	if !success {
-		t.FailNow()
-	}
-
 	// after a delay, c2 reconnects, then publishing
 	time.Sleep(syncDelay)
 	c2.Stop()
 
 	logger.Infow("waiting for c2 tracks to be gone")
-	success = testutils.WithTimeout(t, "c2 tracks should be gone", func() bool {
+	testutils.WithTimeout(t, func() string {
 		tracks := c3.SubscribedTracks()
+
 		if len(tracks[c1.ID()]) != 2 {
-			return false
+			return fmt.Sprintf("c3 should be subscribed to 2 tracks from c1, actual: %d", len(tracks[c1.ID()]))
 		}
 		if len(tracks[c2.ID()]) != 0 {
-			return false
+			return fmt.Sprintf("c3 should be subscribed to 0 tracks from c2, actual: %d", len(tracks[c2.ID()]))
 		}
 		if len(c1.SubscribedTracks()[c2.ID()]) != 0 {
-			return false
+			return fmt.Sprintf("c3 should be subscribed to 0 tracks from c2, actual: %d", len(c1.SubscribedTracks()[c2.ID()]))
 		}
-		return true
+		return ""
 	})
-	if !success {
-		t.FailNow()
-	}
 
 	logger.Infow("c2 reconnecting")
 	// connect to a diff port
@@ -71,15 +66,16 @@ func scenarioPublishingUponJoining(t *testing.T) {
 	writers = publishTracksForClients(t, c2)
 	defer stopWriters(writers...)
 
-	testutils.WithTimeout(t, "new c2 tracks should be published again", func() bool {
+	testutils.WithTimeout(t, func() string {
 		tracks := c3.SubscribedTracks()
+		// "new c2 tracks should be published again",
 		if len(tracks[c2.ID()]) != 2 {
-			return false
+			return fmt.Sprintf("c3 should be subscribed to 2 tracks from c2, actual: %d", len(tracks[c2.ID()]))
 		}
 		if len(c1.SubscribedTracks()[c2.ID()]) != 2 {
-			return false
+			return fmt.Sprintf("c1 should be subscribed to 2 tracks from c2, actual: %d", len(c1.SubscribedTracks()[c2.ID()]))
 		}
-		return true
+		return ""
 	})
 }
 
@@ -95,21 +91,25 @@ func scenarioReceiveBeforePublish(t *testing.T) {
 	defer stopWriters(writers...)
 
 	// c2 should see some bytes flowing through
-	success := testutils.WithTimeout(t, "waiting to receive bytes on c2", func() bool {
-		return c2.BytesReceived() > 20
+	testutils.WithTimeout(t, func() string {
+		if c2.BytesReceived() > 20 {
+			return ""
+		} else {
+			return fmt.Sprintf("c2 only received %d bytes", c2.BytesReceived())
+		}
 	})
-	if !success {
-		t.FailNow()
-	}
 
 	// now publish on C2
 	writers = publishTracksForClients(t, c2)
 	defer stopWriters(writers...)
 
-	success = testutils.WithTimeout(t, "waiting to receive c2 tracks on c1", func() bool {
-		return len(c1.SubscribedTracks()[c2.ID()]) == 2
+	testutils.WithTimeout(t, func() string {
+		if len(c1.SubscribedTracks()[c2.ID()]) == 2 {
+			return ""
+		} else {
+			return fmt.Sprintf("expected c1 to receive 2 tracks from c2, actual: %d", len(c1.SubscribedTracks()[c2.ID()]))
+		}
 	})
-	require.True(t, success)
 
 	// now leave, and ensure that it's immediate
 	c2.Stop()
@@ -135,8 +135,12 @@ func scenarioDataPublish(t *testing.T) {
 
 	require.NoError(t, c1.PublishData([]byte(payload), livekit.DataPacket_RELIABLE))
 
-	testutils.WithTimeout(t, "waiting for c2 to receive data", func() bool {
-		return received.Get()
+	testutils.WithTimeout(t, func() string {
+		if received.Get() {
+			return ""
+		} else {
+			return "c2 did not receive published data"
+		}
 	})
 }
 

test/singlenode_test.go

@@ -35,8 +35,14 @@ func TestClientCouldConnect(t *testing.T) {
 	waitUntilConnected(t, c1, c2)
 
 	// ensure they both see each other
-	testutils.WithTimeout(t, "c1 and c2 could connect", func() bool {
-		return len(c1.RemoteParticipants()) != 0 && len(c2.RemoteParticipants()) != 0
+	testutils.WithTimeout(t, func() string {
+		if len(c1.RemoteParticipants()) == 0 {
+			return "c1 did not see c2"
+		}
+		if len(c2.RemoteParticipants()) == 0 {
+			return "c2 did not see c1"
+		}
+		return ""
 	})
 }
 
@@ -70,13 +76,13 @@ func TestClientConnectDuplicate(t *testing.T) {
 	opts := &testclient.Options{
 		Publish: "duplicate_connection",
 	}
-	success := testutils.WithTimeout(t, "c2 should receive two tracks", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if len(c2.SubscribedTracks()) == 0 {
-			return false
+			return "c2 didn't subscribe to anything"
 		}
 		// should have received three tracks
 		if len(c2.SubscribedTracks()[c1.ID()]) != 2 {
-			return false
+			return "c2 didn't subscribe to both tracks from c1"
 		}
 
 		// participant ID can be appended with '#..' . but should contain orig id as prefix
@@ -86,11 +92,8 @@ func TestClientConnectDuplicate(t *testing.T) {
 		tr2 := c2.SubscribedTracks()[c1.ID()][1]
 		participantId2, _ := rtc.UnpackStreamID(tr2.StreamID())
 		require.Equal(t, c1.ID(), participantId2)
-		return true
+		return ""
 	})
-	if !success {
-		t.FailNow()
-	}
 
 	c1Dup := createRTCClientWithToken(token, defaultServerPort, opts)
 
@@ -100,20 +103,17 @@ func TestClientConnectDuplicate(t *testing.T) {
 	require.NoError(t, err)
 	defer t3.Stop()
 
-	success = testutils.WithTimeout(t, "c2 should receive third tracks", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if len(c2.SubscribedTracks()[c1Dup.ID()]) != 1 {
-			return false
+			return "c2 was not subscribed to track from duplicated c1"
 		}
 
 		tr3 := c2.SubscribedTracks()[c1Dup.ID()][0]
 		participantId3, _ := rtc.UnpackStreamID(tr3.StreamID())
 		require.Contains(t, c1Dup.ID(), participantId3)
 
-		return true
+		return ""
 	})
-	if !success {
-		t.FailNow()
-	}
 }
 
 func TestSinglePublisher(t *testing.T) {
@@ -137,19 +137,19 @@ func TestSinglePublisher(t *testing.T) {
 	require.NoError(t, err)
 	defer t2.Stop()
 
-	testutils.WithTimeout(t, "c2 should receive two tracks", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if len(c2.SubscribedTracks()) == 0 {
-			return false
+			return "c2 was not subscribed to anything"
 		}
 		// should have received two tracks
 		if len(c2.SubscribedTracks()[c1.ID()]) != 2 {
-			return false
+			return "c2 didn't subscribe to both tracks from c1"
 		}
 
 		tr1 := c2.SubscribedTracks()[c1.ID()][0]
 		participantId, _ := rtc.UnpackStreamID(tr1.StreamID())
 		require.Equal(t, c1.ID(), participantId)
-		return true
+		return ""
 	})
 	// ensure mime type is received
 	remoteC1 := c2.GetRemoteParticipant(c1.ID())
@@ -163,15 +163,15 @@ func TestSinglePublisher(t *testing.T) {
 
 	// ensure that new client that has joined also received tracks
 	waitUntilConnected(t, c3)
-	testutils.WithTimeout(t, "c3 should receive two tracks", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if len(c3.SubscribedTracks()) == 0 {
-			return false
+			return "c3 didn't subscribe to anything"
 		}
 		// should have received two tracks
 		if len(c3.SubscribedTracks()[c1.ID()]) != 2 {
-			return false
+			return "c3 didn't subscribe to tracks from c1"
 		}
-		return true
+		return ""
 	})
 
 	// ensure that the track ids are generated by server
@@ -183,19 +183,17 @@ func TestSinglePublisher(t *testing.T) {
 	// when c3 disconnects, ensure subscriber is cleaned up correctly
 	c3.Stop()
 
-	testutils.WithTimeout(t, "c3 is cleaned up as a subscriber", func() bool {
+	testutils.WithTimeout(t, func() string {
 		room := s.RoomManager().GetRoom(context.Background(), testRoom)
-		require.NotNil(t, room)
-
 		p := room.GetParticipant("c1")
 		require.NotNil(t, p)
 
 		for _, t := range p.GetPublishedTracks() {
 			if t.IsSubscriber(c3.ID()) {
-				return false
+				return "c3 was not a subscriber of c1's tracks"
 			}
 		}
-		return true
+		return ""
 	})
 }
 
@@ -245,26 +243,24 @@ func Test_RenegotiationWithDifferentCodecs(t *testing.T) {
 	require.NoError(t, err)
 	defer t2.Stop()
 
-	success := testutils.WithTimeout(t, "c2 should receive two tracks, video is vp8", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if len(c2.SubscribedTracks()) == 0 {
-			return false
+			return "c2 was not subscribed to anything"
 		}
 		// should have received two tracks
 		if len(c2.SubscribedTracks()[c1.ID()]) != 2 {
-			return false
+			return "c2 was not subscribed to tracks from c1"
 		}
 
 		tracks := c2.SubscribedTracks()[c1.ID()]
 		for _, t := range tracks {
 			if strings.EqualFold(t.Codec().MimeType, "video/vp8") {
-				return true
+				return ""
+
 			}
 		}
-		return false
+		return "did not receive track with vp8"
 	})
-	if !success {
-		t.FailNow()
-	}
 
 	t3, err := c1.AddStaticTrackWithCodec(webrtc.RTPCodecCapability{
 		MimeType:    "video/h264",
@@ -274,13 +270,13 @@ func Test_RenegotiationWithDifferentCodecs(t *testing.T) {
 	defer t3.Stop()
 	require.NoError(t, err)
 
-	success = testutils.WithTimeout(t, "c2 should receive two video tracks, one vp8 one h264", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if len(c2.SubscribedTracks()) == 0 {
-			return false
+			return "c2's not subscribed to anything"
 		}
 		// should have received three tracks
 		if len(c2.SubscribedTracks()[c1.ID()]) != 3 {
-			return false
+			return "c2's not subscribed to 3 tracks from c1"
 		}
 
 		var vp8Found, h264Found bool
@@ -292,11 +288,14 @@ func Test_RenegotiationWithDifferentCodecs(t *testing.T) {
 				h264Found = true
 			}
 		}
-		return vp8Found && h264Found
+		if !vp8Found {
+			return "did not receive track with vp8"
+		}
+		if !h264Found {
+			return "did not receive track with h264"
+		}
+		return ""
 	})
-	if !success {
-		t.FailNow()
-	}
 }
 
 func TestSingleNodeRoomList(t *testing.T) {
@@ -411,15 +410,15 @@ func TestSingleNodeUpdateSubscriptionPermissions(t *testing.T) {
 	defer stopWriters(writers...)
 
 	// wait sub receives tracks
-	testutils.WithTimeout(t, "waiting for sub to receive track metadata", func() bool {
+	testutils.WithTimeout(t, func() string {
 		pubRemote := sub.GetRemoteParticipant(pub.ID())
 		if pubRemote == nil {
-			return false
+			return "could not find remote publisher"
 		}
 		if len(pubRemote.Tracks) != 2 {
-			return false
+			return "did not receive metadata for published tracks"
 		}
-		return true
+		return ""
 	})
 
 	// set permissions out of band
@@ -434,8 +433,12 @@ func TestSingleNodeUpdateSubscriptionPermissions(t *testing.T) {
 	})
 	require.NoError(t, err)
 
-	testutils.WithTimeout(t, "waiting to get subscriptions", func() bool {
+	testutils.WithTimeout(t, func() string {
 		tracks := sub.SubscribedTracks()[pub.ID()]
-		return len(tracks) == 2
+		if len(tracks) == 2 {
+			return ""
+		} else {
+			return fmt.Sprintf("expected 2 tracks subscribed, actual: %d", len(tracks))
+		}
 	})
 }

test/webhook_test.go

@@ -31,14 +31,14 @@ func TestWebhooks(t *testing.T) {
 
 	c1 := createRTCClient("c1", defaultServerPort, nil)
 	waitUntilConnected(t, c1)
-	testutils.WithTimeout(t, "webhook events room_started and participant_joined", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if ts.GetEvent(webhook.EventRoomStarted) == nil {
-			return false
+			return "did not receive RoomStarted"
 		}
 		if ts.GetEvent(webhook.EventParticipantJoined) == nil {
-			return false
+			return "did not receive ParticipantJoined"
 		}
-		return true
+		return ""
 	})
 
 	// first participant join should have started the room
@@ -55,11 +55,11 @@ func TestWebhooks(t *testing.T) {
 	c2 := createRTCClient("c2", defaultServerPort, nil)
 	waitUntilConnected(t, c2)
 	defer c2.Stop()
-	testutils.WithTimeout(t, "webhook events participant_joined", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if ts.GetEvent(webhook.EventParticipantJoined) == nil {
-			return false
+			return "did not receive ParticipantJoined"
 		}
-		return true
+		return ""
 	})
 	joined = ts.GetEvent(webhook.EventParticipantJoined)
 	require.Equal(t, "c2", joined.Participant.Identity)
@@ -67,11 +67,11 @@ func TestWebhooks(t *testing.T) {
 
 	// first participant leaves
 	c1.Stop()
-	testutils.WithTimeout(t, "webhook events participant_left", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if ts.GetEvent(webhook.EventParticipantLeft) == nil {
-			return false
+			return "did not receive ParticipantLeft"
 		}
-		return true
+		return ""
 	})
 	left := ts.GetEvent(webhook.EventParticipantLeft)
 	require.Equal(t, "c1", left.Participant.Identity)
@@ -80,11 +80,11 @@ func TestWebhooks(t *testing.T) {
 	// room closed
 	rm := server.RoomManager().GetRoom(context.Background(), testRoom)
 	rm.Close()
-	testutils.WithTimeout(t, "webhook events room_finished", func() bool {
+	testutils.WithTimeout(t, func() string {
 		if ts.GetEvent(webhook.EventRoomFinished) == nil {
-			return false
+			return "did not receive RoomFinished"
 		}
-		return true
+		return ""
 	})
 	require.Equal(t, testRoom, ts.GetEvent(webhook.EventRoomFinished).Room.Name)
 }