From 2b4322c9d145e13effc8c7bc36b9e87713b5251d Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Mon, 13 Nov 2023 15:35:27 +0000 Subject: [PATCH] Improved logging; less sleeps --- internal/api/client.go | 52 ++++++++++++++++++++++++++++ internal/api/js.go | 35 ++++++++++++++++++- internal/api/rust.go | 64 ++++++++++++++++++++++++++--------- tests/membership_acls_test.go | 20 ++++++----- 4 files changed, 145 insertions(+), 26 deletions(-) diff --git a/internal/api/client.go b/internal/api/client.go index d284e3b..1564f79 100644 --- a/internal/api/client.go +++ b/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 diff --git a/internal/api/js.go b/internal/api/js.go index 0c188a7..48ad2ac 100644 --- a/internal/api/js.go +++ b/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 } diff --git a/internal/api/rust.go b/internal/api/rust.go index 0cc640c..65e3a8f 100644 --- a/internal/api/rust.go +++ b/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,13 +59,12 @@ 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() } @@ -73,11 +72,34 @@ func (c *RustClient) Close(t *testing.T) { // 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,7 +145,6 @@ 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{ @@ -134,6 +152,10 @@ func (c *RustClient) MustBackpaginate(t *testing.T, roomID string, count int) { })) } +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 +} diff --git a/tests/membership_acls_test.go b/tests/membership_acls_test.go index 7f66a90..ddc7c93 100644 --- a/tests/membership_acls_test.go +++ b/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)