Improved logging; less sleeps

internal/api/client.go

@@ -1,6 +1,7 @@
 package api
 
 import (
+	"fmt"
 	"testing"
 	"time"
 
@@ -24,6 +25,7 @@ type Client interface {
 	Close(t *testing.T)
 	// StartSyncing to begin syncing from sync v2 / sliding sync.
 	// Tests should call stopSyncing() at the end of the test.
+	// MUST BLOCK until the initial sync is complete.
 	StartSyncing(t *testing.T) (stopSyncing func())
 	// IsRoomEncrypted returns true if the room is encrypted. May return an error e.g if you
 	// provide a bogus room ID.
@@ -36,9 +38,59 @@ type Client interface {
 	WaitUntilEventInRoom(t *testing.T, roomID string, checker func(e Event) bool) Waiter
 	// Backpaginate in this room by `count` events.
 	MustBackpaginate(t *testing.T, roomID string, count int)
+	// Log something to stdout and the underlying client log file
+	Logf(t *testing.T, format string, args ...interface{})
+	// The user for this client
+	UserID() string
 	Type() ClientType
 }
 
+type LoggedClient struct {
+	Client
+}
+
+func (c *LoggedClient) Close(t *testing.T) {
+	t.Helper()
+	c.Logf(t, "%s Close", c.logPrefix())
+	c.Client.Close(t)
+}
+
+func (c *LoggedClient) StartSyncing(t *testing.T) (stopSyncing func()) {
+	t.Helper()
+	c.Logf(t, "%s StartSyncing starting to sync", c.logPrefix())
+	stopSyncing = c.Client.StartSyncing(t)
+	c.Logf(t, "%s StartSyncing now syncing", c.logPrefix())
+	return
+}
+
+func (c *LoggedClient) IsRoomEncrypted(t *testing.T, roomID string) (bool, error) {
+	t.Helper()
+	c.Logf(t, "%s IsRoomEncrypted %s", c.logPrefix(), roomID)
+	return c.Client.IsRoomEncrypted(t, roomID)
+}
+
+func (c *LoggedClient) SendMessage(t *testing.T, roomID, text string) {
+	t.Helper()
+	c.Logf(t, "%s SendMessage %s => %s", c.logPrefix(), roomID, text)
+	c.Client.SendMessage(t, roomID, text)
+}
+
+func (c *LoggedClient) WaitUntilEventInRoom(t *testing.T, roomID string, checker func(e Event) bool) Waiter {
+	t.Helper()
+	c.Logf(t, "%s WaitUntilEventInRoom %s", c.logPrefix(), roomID)
+	return c.Client.WaitUntilEventInRoom(t, roomID, checker)
+}
+
+func (c *LoggedClient) MustBackpaginate(t *testing.T, roomID string, count int) {
+	t.Helper()
+	c.Logf(t, "%s MustBackpaginate %d %s", c.logPrefix(), count, roomID)
+	c.Client.MustBackpaginate(t, roomID, count)
+}
+
+func (c *LoggedClient) logPrefix() string {
+	return fmt.Sprintf("[%s](%s)", c.UserID(), c.Type())
+}
+
 // ClientCreationOpts are generic opts to use when creating crypto clients.
 // Because this is generic, some features possible in some clients are unsupported here, notably
 // you cannot provide an existing access_token to the FFI binding layer, hence you don't see

internal/api/js.go

@@ -148,7 +148,7 @@ func NewJSClient(t *testing.T, opts ClientCreationOpts) (Client, error) {
 	jsc.ctx = ctx
 	jsc.cancel = cancel
 	jsc.baseJSURL = baseJSURL
-	return jsc, nil
+	return &LoggedClient{Client: jsc}, nil
 }
 
 // Close is called to clean up resources.
@@ -160,10 +160,36 @@ func (c *JSClient) Close(t *testing.T) {
 	c.listeners = make(map[int32]func(roomID string, ev Event))
 }
 
+func (c *JSClient) UserID() string {
+	return c.userID
+}
+
 // StartSyncing to begin syncing from sync v2 / sliding sync.
 // Tests should call stopSyncing() at the end of the test.
 func (c *JSClient) StartSyncing(t *testing.T) (stopSyncing func()) {
+	t.Logf("%s is starting to sync", c.userID)
+	chrome.MustExecute(t, c.ctx, fmt.Sprintf(`window.__client.on("sync", function(state) {
+		if (state !== "PREPARED") {
+			return;
+		}
+		console.log("%s"+"sync||{\"type\":\"sync\",\"content\":{}}");
+	});`, CONSOLE_LOG_CONTROL_STRING))
+	ch := make(chan struct{})
+	cancel := c.listenForUpdates(func(roomID string, ev Event) {
+		if roomID != "sync" {
+			return
+		}
+		close(ch)
+	})
 	chrome.AwaitExecute(t, c.ctx, `window.__client.startClient({});`)
+	select {
+	case <-time.After(5 * time.Second):
+		t.Fatalf("took >5s to StartSyncing")
+	case <-ch:
+	}
+	cancel()
+	t.Logf("%s is now syncing", c.userID)
+	time.Sleep(500 * time.Millisecond) // race condition means we don't query keys yet
 	return func() {
 		chrome.AwaitExecute(t, c.ctx, `window.__client.stopClient();`)
 	}
@@ -205,6 +231,13 @@ func (c *JSClient) WaitUntilEventInRoom(t *testing.T, roomID string, checker fun
 	}
 }
 
+func (c *JSClient) Logf(t *testing.T, format string, args ...interface{}) {
+	t.Helper()
+	formatted := fmt.Sprintf(t.Name()+": "+format, args...)
+	chrome.MustExecute(t, c.ctx, fmt.Sprintf(`console.log("%s");`, formatted))
+	t.Logf(format, args...)
+}
+
 func (c *JSClient) Type() ClientType {
 	return ClientTypeJS
 }

internal/api/rust.go

@@ -30,12 +30,12 @@ type RustRoomInfo struct {
 }
 
 type RustClient struct {
-	FFIClient   *matrix_sdk_ffi.Client
-	rooms       map[string]*RustRoomInfo
-	listeners   map[int32]func(roomID string)
-	listenerID  atomic.Int32
-	userID      string
-	syncService *matrix_sdk_ffi.SyncService
+	FFIClient  *matrix_sdk_ffi.Client
+	rooms      map[string]*RustRoomInfo
+	listeners  map[int32]func(roomID string)
+	listenerID atomic.Int32
+	userID     string
+	// syncService *matrix_sdk_ffi.SyncService
 }
 
 func NewRustClient(t *testing.T, opts ClientCreationOpts, ssURL string) (Client, error) {
@@ -59,25 +59,47 @@ func NewRustClient(t *testing.T, opts ClientCreationOpts, ssURL string) (Client,
 		rooms:     make(map[string]*RustRoomInfo),
 		listeners: make(map[int32]func(roomID string)),
 	}
-	c.logf(t, "NewRustClient[%s] created client", opts.UserID)
-	return c, nil
+	c.Logf(t, "NewRustClient[%s] created client", opts.UserID)
+	return &LoggedClient{Client: c}, nil
 }
 
 func (c *RustClient) Close(t *testing.T) {
 	t.Helper()
-	c.logf(t, "Close[%s]", c.userID)
 	c.FFIClient.Destroy()
 }
 
 // StartSyncing to begin syncing from sync v2 / sliding sync.
 // Tests should call stopSyncing() at the end of the test.
 func (c *RustClient) StartSyncing(t *testing.T) (stopSyncing func()) {
 	t.Helper()
-	c.logf(t, "StartSyncing[%s]", c.userID)
 	syncService, err := c.FFIClient.SyncService().FinishBlocking()
 	must.NotError(t, fmt.Sprintf("[%s]failed to make sync service", c.userID), err)
-	c.syncService = syncService
+	//c.syncService = syncService
+	/* ch := make(chan matrix_sdk_ffi.SyncServiceState, 10)
+	th := syncService.State(&syncServiceStateObserver{
+		ch: ch,
+	}) */
 	go syncService.StartBlocking()
+
+	/*
+		isSyncing := false
+
+		for !isSyncing {
+			select {
+			case <-time.After(5 * time.Second):
+				t.Fatalf("timed out after 5s StartSyncing")
+			case state := <-ch:
+				fmt.Println(state)
+				if state == matrix_sdk_ffi.SyncServiceStateRunning {
+					isSyncing = true
+				}
+			}
+		}
+
+		th.Cancel() */
+
+	time.Sleep(time.Second)
+
 	return func() {
 		t.Logf("%s: Stopping sync service", c.userID)
 		syncService.StopBlocking()
@@ -88,7 +110,6 @@ func (c *RustClient) StartSyncing(t *testing.T) (stopSyncing func()) {
 // provide a bogus room ID.
 func (c *RustClient) IsRoomEncrypted(t *testing.T, roomID string) (bool, error) {
 	t.Helper()
-	c.logf(t, "IsRoomEncrypted[%s] %s", c.userID, roomID)
 	r := c.findRoom(roomID)
 	if r == nil {
 		rooms := c.FFIClient.Rooms()
@@ -99,7 +120,6 @@ func (c *RustClient) IsRoomEncrypted(t *testing.T, roomID string) (bool, error)
 
 func (c *RustClient) WaitUntilEventInRoom(t *testing.T, roomID string, checker func(Event) bool) Waiter {
 	t.Helper()
-	c.logf(t, "WaitUntilEventInRoom[%s] %s", c.userID, roomID)
 	c.ensureListening(t, roomID)
 	return &timelineWaiter{
 		roomID:  roomID,
@@ -116,7 +136,6 @@ func (c *RustClient) Type() ClientType {
 // room. Returns the event ID of the sent event.
 func (c *RustClient) SendMessage(t *testing.T, roomID, text string) {
 	t.Helper()
-	c.logf(t, "SendMessage[%s] %s => %s", c.userID, roomID, text)
 	// we need a timeline listener before we can send messages, AND that listener must be attached to the
 	// same *Room you call .Send on :S
 	r := c.ensureListening(t, roomID)
@@ -126,14 +145,17 @@ func (c *RustClient) SendMessage(t *testing.T, roomID, text string) {
 
 func (c *RustClient) MustBackpaginate(t *testing.T, roomID string, count int) {
 	t.Helper()
-	c.logf(t, "[%s] MustBackpaginate %d %s", c.userID, count, roomID)
 	r := c.findRoom(roomID)
 	must.NotEqual(t, r, nil, "unknown room")
 	must.NotError(t, "failed to backpaginate", r.PaginateBackwards(matrix_sdk_ffi.PaginationOptionsSingleRequest{
 		EventLimit: uint16(count),
 	}))
 }
 
+func (c *RustClient) UserID() string {
+	return c.userID
+}
+
 func (c *RustClient) findRoom(roomID string) *matrix_sdk_ffi.Room {
 	rooms := c.FFIClient.Rooms()
 	for i, r := range rooms {
@@ -152,7 +174,7 @@ func (c *RustClient) findRoom(roomID string) *matrix_sdk_ffi.Room {
 	return nil
 }
 
-func (c *RustClient) logf(t *testing.T, format string, args ...interface{}) {
+func (c *RustClient) Logf(t *testing.T, format string, args ...interface{}) {
 	t.Helper()
 	matrix_sdk_ffi.LogEvent("rust.go", &zero, matrix_sdk_ffi.LogLevelInfo, t.Name(), fmt.Sprintf(format, args...))
 	t.Logf(format, args...)
@@ -341,6 +363,8 @@ func timelineItemToEvent(item *matrix_sdk_ffi.TimelineItem) *Event {
 		case matrix_sdk_ffi.MembershipChangeKickedAndBanned:
 			complementEvent.Membership = "ban"
 		case matrix_sdk_ffi.MembershipChangeJoined:
+			fallthrough
+		case matrix_sdk_ffi.MembershipChangeInvitationAccepted:
 			complementEvent.Membership = "join"
 		case matrix_sdk_ffi.MembershipChangeLeft:
 			fallthrough
@@ -367,3 +391,11 @@ func timelineItemToEvent(item *matrix_sdk_ffi.TimelineItem) *Event {
 	}
 	return &complementEvent
 }
+
+type syncServiceStateObserver struct {
+	ch chan matrix_sdk_ffi.SyncServiceState
+}
+
+func (s *syncServiceStateObserver) OnUpdate(state matrix_sdk_ffi.SyncServiceState) {
+	s.ch <- state
+}

tests/membership_acls_test.go

@@ -127,24 +127,26 @@ func TestCanDecryptMessagesAfterInviteButBeforeJoin(t *testing.T) {
 		// SDK testing below
 		// -----------------
 
-		// Alice logs in.
-		alice := MustLoginClient(t, clientTypeA, api.FromComplementClient(csapiAlice, "complement-crypto-password"), ss)
-		defer alice.Close(t)
-
-		// Bob logs in BEFORE Alice starts syncing. This is important because the act of logging in should cause
+		// Bob logs in BEFORE Alice. This is important because the act of logging in should cause
 		// Bob to upload OTKs which will be needed to send the encrypted event.
 		bob := MustLoginClient(t, clientTypeB, api.FromComplementClient(csapiBob, "complement-crypto-password"), ss)
 		defer bob.Close(t)
 
-		// Alice and Bob start syncing
-		aliceStopSyncing := alice.StartSyncing(t)
-		defer aliceStopSyncing()
+		// Alice logs in.
+		alice := MustLoginClient(t, clientTypeA, api.FromComplementClient(csapiAlice, "complement-crypto-password"), ss)
+		defer alice.Close(t)
+
+		// Alice and Bob start syncing.
+		// FIXME: Bob must sync before Alice otherwise Alice does not seem to get Bob's device in /keys/query. By putting
+		// Bob first, we ensure that the _first_ device list sync for the room includes Bob.
 		bobStopSyncing := bob.StartSyncing(t)
 		defer bobStopSyncing()
+		aliceStopSyncing := alice.StartSyncing(t)
+		defer aliceStopSyncing()
 
 		time.Sleep(time.Second) // TODO: find another way to wait until initial sync is done
 
-		wantMsgBody := "Hello world"
+		wantMsgBody := "Message sent when bob is invited not joined"
 
 		// Check the room is in fact encrypted
 		isEncrypted, err := alice.IsRoomEncrypted(t, roomID)