From 22f427d5221a29b3cb49c2eec0a54569e0d90a37 Mon Sep 17 00:00:00 2001 From: Jakub Date: Tue, 4 Jan 2022 08:17:54 +0100 Subject: [PATCH] GODT-1474: Optimising live integration tests - pkg/pmapi: Reduce max number of retries - test/features: tweak create mailbox scenarios. - test/context: change order of clean up steps - test/context: logger field - test/context: message preparation per username - test/context: check that eventID has changed after adding messages - test/features: make sure we wait 15sec before detecting import duplicates --- pkg/pmapi/manager.go | 15 +++--- test/context/cleaner.go | 4 +- test/context/context.go | 13 +++-- test/context/pmapi_controller.go | 4 +- test/fakeapi/controller_control.go | 4 +- test/features/imap/idle/two_users.feature | 3 +- test/features/imap/mailbox/create.feature | 2 + test/features/imap/message/create.feature | 11 +++- test/features/imap/message/drafts.feature | 4 +- test/liveapi/controller.go | 3 ++ test/liveapi/events.go | 65 ++++++++++++++++++++++- test/mocks/imap_client.go | 2 + test/store_setup_test.go | 54 +++++++++++-------- 13 files changed, 138 insertions(+), 46 deletions(-) diff --git a/pkg/pmapi/manager.go b/pkg/pmapi/manager.go index c9406bbe..66cc1781 100644 --- a/pkg/pmapi/manager.go +++ b/pkg/pmapi/manager.go @@ -72,12 +72,15 @@ func newManager(cfg Config) *manager { // Configure retry mechanism. // - // SetRetryCount(30): The most probable value of Retry-After is 1s (max - // 10s). Retrying up to 30 times will most probably cause a delay of - // 30s. The worst case scenario is 5min which is OK for background - // requests. We shuold use context to control a foreground requests - // which should be finish or fail sooner. - m.rc.SetRetryCount(30) + // SetRetryCount(5): The most probable value of Retry-After from our + // API is 1s (max 10s). Retrying up to 5 times will on average cause a + // delay of 40s. + // + // NOTE: Increasing to values larger than 10 causing significant delay. + // The resty is increasing the delay between retries up to 1 minute + // (SetRetryMaxWaitTime) so for 10 retries the cumulative delay can be + // up to 5min. + m.rc.SetRetryCount(5) m.rc.SetRetryMaxWaitTime(time.Minute) m.rc.SetRetryAfter(catchRetryAfter) m.rc.AddRetryCondition(m.shouldRetry) diff --git a/test/context/cleaner.go b/test/context/cleaner.go index 347de339..a5233904 100644 --- a/test/context/cleaner.go +++ b/test/context/cleaner.go @@ -62,7 +62,7 @@ func (ctx *TestContext) addCleanup(c func(), label string) { cleaner.file, cleaner.lineNumber = filepath.Base(file), line } - ctx.cleanupSteps = append(ctx.cleanupSteps, cleaner) + ctx.cleanupSteps = append([]*Cleaner{cleaner}, ctx.cleanupSteps...) } // addCleanupChecked adds an operation that may return an error to be performed at the end of the test. @@ -83,5 +83,5 @@ func (ctx *TestContext) addCleanupChecked(f func() error, label string) { cleaner.file, cleaner.lineNumber = filepath.Base(file), line } - ctx.cleanupSteps = append(ctx.cleanupSteps, cleaner) + ctx.cleanupSteps = append([]*Cleaner{cleaner}, ctx.cleanupSteps...) } diff --git a/test/context/context.go b/test/context/context.go index 241d56de..426e3f84 100644 --- a/test/context/context.go +++ b/test/context/context.go @@ -107,9 +107,12 @@ func New() *TestContext { smtpLastResponses: make(map[string]*mocks.SMTPResponse), smtpResponseLocker: &sync.Mutex{}, bddMessageIDsToAPIIDs: make(map[string]string), - logger: logrus.StandardLogger(), + logger: logrus.StandardLogger().WithField("ctx", "scenario"), } + ctx.logger.Info("New context") + ctx.addCleanup(func() { ctx.logger.Info("Context end") }, "End of context") + // Ensure that the config is cleaned up after the test is over. ctx.addCleanupChecked(ctx.locations.Clear, "Cleaning bridge config data") @@ -163,5 +166,9 @@ func (ctx *TestContext) GetLastError() error { return ctx.lastError } -func (ctx *TestContext) MessagePreparationStarted() { ctx.pmapiController.LockEvents() } -func (ctx *TestContext) MessagePreparationFinished() { ctx.pmapiController.UnlockEvents() } +func (ctx *TestContext) MessagePreparationStarted(username string) { + ctx.pmapiController.LockEvents(username) +} +func (ctx *TestContext) MessagePreparationFinished(username string) { + ctx.pmapiController.UnlockEvents(username) +} diff --git a/test/context/pmapi_controller.go b/test/context/pmapi_controller.go index 10a22ce3..24c4ec49 100644 --- a/test/context/pmapi_controller.go +++ b/test/context/pmapi_controller.go @@ -43,8 +43,8 @@ type PMAPIController interface { WasCalled(method, path string, expectedRequest []byte) bool WasCalledRegex(methodRegex, pathRegex string, expectedRequest []byte) (bool, error) GetCalls(method, path string) [][]byte - LockEvents() - UnlockEvents() + LockEvents(username string) + UnlockEvents(username string) } func newPMAPIController(listener listener.Listener) (PMAPIController, pmapi.Manager) { diff --git a/test/fakeapi/controller_control.go b/test/fakeapi/controller_control.go index 1e0b0799..8935a753 100644 --- a/test/fakeapi/controller_control.go +++ b/test/fakeapi/controller_control.go @@ -230,7 +230,7 @@ func (ctl *Controller) GetAuthClient(username string) pmapi.Client { } // LockEvents doesn't needs to be implemented for fakeAPI. -func (ctl *Controller) LockEvents() {} +func (ctl *Controller) LockEvents(string) {} // UnlockEvents doesn't needs to be implemented for fakeAPI. -func (ctl *Controller) UnlockEvents() {} +func (ctl *Controller) UnlockEvents(string) {} diff --git a/test/features/imap/idle/two_users.feature b/test/features/imap/idle/two_users.feature index 0059bd34..5152409f 100644 --- a/test/features/imap/idle/two_users.feature +++ b/test/features/imap/idle/two_users.feature @@ -14,8 +14,7 @@ Feature: IMAP IDLE with two users Scenario: IDLE statements are not leaked to other alias Given there is connected user "userMoreAddresses" And there is "userMoreAddresses" in "combined" address mode - And there is "userMoreAddresses" with mailbox "Folders/mbox" - And there are messages in mailbox "Folders/mbox" for "userMoreAddresses" + And there are messages in mailbox "INBOX" for "userMoreAddresses" | from | to | subject | | john.doe@mail.com | [primary] | foo | | jane.doe@mail.com | [secondary] | bar | diff --git a/test/features/imap/mailbox/create.feature b/test/features/imap/mailbox/create.feature index 4250699e..7c37210c 100644 --- a/test/features/imap/mailbox/create.feature +++ b/test/features/imap/mailbox/create.feature @@ -2,6 +2,8 @@ Feature: IMAP create mailbox Background: Given there is connected user "user" And there is IMAP client logged in as "user" + And "user" does not have mailbox "Folders/mbox" + And "user" does not have mailbox "Labels/mbox" Scenario: Create folder When IMAP client creates mailbox "Folders/mbox" diff --git a/test/features/imap/message/create.feature b/test/features/imap/message/create.feature index d1fa2302..f3e014ca 100644 --- a/test/features/imap/message/create.feature +++ b/test/features/imap/message/create.feature @@ -58,14 +58,21 @@ Feature: IMAP create messages # Importing duplicate messages when messageID cannot be found in Sent already. # - # Previously, we discarded messages for which sender matches account address to + # Previously, we discarded messages for which sender matches account address to # avoid duplicates, but this led to discarding messages imported through mail client. + # + # NOTE: We need to introduce cooldown here in order to detect duplicates + # properly. Once mail is imported to API the Sphinx indices for duplicate + # detection are updated every 10s. Therefore it is good to leave at least 15 + # second gap after import in order to be able to correctly handle the case + # when we try to detect duplicate imports Scenario: Imports a similar (duplicate) message to sent Given there are messages in mailbox "Sent" for "userMoreAddresses" | from | to | subject | body | | [primary] | chosen@one.com | Meet the Twins | Hello, Mr. Anderson | + And wait for Sphinx to create duplication indices And there is IMAP client selected in "Sent" Then mailbox "Sent" for "userMoreAddresses" has 1 messages When IMAP client creates message "Meet the Twins" from address "primary" of "userMoreAddresses" to "chosen@one.com" with body "Hello, Mr. Anderson" in "Sent" - Then IMAP response is "OK" + Then IMAP response is "OK \[APPENDUID 4 2\] APPEND completed" And mailbox "Sent" for "userMoreAddresses" has 2 messages diff --git a/test/features/imap/message/drafts.feature b/test/features/imap/message/drafts.feature index 36f6d274..79113b9a 100644 --- a/test/features/imap/message/drafts.feature +++ b/test/features/imap/message/drafts.feature @@ -27,7 +27,7 @@ Feature: IMAP operations with Drafts Then IMAP response contains "Nope" When IMAP client sends command "UID FETCH 1 RFC822.SIZE" Then IMAP response is "OK" - Then IMAP response contains "495" + Then IMAP response contains "538" When IMAP client sends command "UID FETCH 1 BODYSTRUCTURE" Then IMAP response is "OK" Then IMAP response contains "4 14" @@ -40,7 +40,7 @@ Feature: IMAP operations with Drafts Then IMAP response does not contain "Nope" When IMAP client sends command "UID FETCH 2 RFC822.SIZE" Then IMAP response is "OK" - Then IMAP response contains "499" + Then IMAP response contains "542" When IMAP client sends command "UID FETCH 2 BODYSTRUCTURE" Then IMAP response is "OK" Then IMAP response contains "8 14" diff --git a/test/liveapi/controller.go b/test/liveapi/controller.go index 378688f3..675cb398 100644 --- a/test/liveapi/controller.go +++ b/test/liveapi/controller.go @@ -36,6 +36,8 @@ type Controller struct { // State controlled by test. noInternetConnection bool + + lastEventByUsername map[string]string } func NewController() (*Controller, pmapi.Manager) { @@ -46,6 +48,7 @@ func NewController() (*Controller, pmapi.Manager) { messageIDsByUsername: map[string][]string{}, noInternetConnection: false, + lastEventByUsername: map[string]string{}, } persistentClients.manager.SetTransport(&fakeTransport{ diff --git a/test/liveapi/events.go b/test/liveapi/events.go index 9de24bdc..2791f560 100644 --- a/test/liveapi/events.go +++ b/test/liveapi/events.go @@ -17,10 +17,71 @@ package liveapi -func (ctl *Controller) LockEvents() { +import ( + "context" + "time" +) + +func (ctl *Controller) LockEvents(username string) { + ctl.recordEvent(username) persistentClients.eventsPaused.Add(1) } -func (ctl *Controller) UnlockEvents() { +func (ctl *Controller) UnlockEvents(username string) { persistentClients.eventsPaused.Done() + ctl.waitForEventChange(username) +} + +func (ctl *Controller) recordEvent(username string) { + ctl.lastEventByUsername[username] = "" + client, err := getPersistentClient(username) + if err != nil { + ctl.log.WithError(err).Error("Cannot get persistent client to record event") + return + } + + event, err := client.GetEvent(context.Background(), "") + if err != nil { + ctl.log.WithError(err).Error("Cannot record event") + return + } + + ctl.lastEventByUsername[username] = event.EventID + ctl.log.WithField("last", event.EventID).Debug("Event recorded") +} + +func (ctl *Controller) waitForEventChange(username string) { + lastEvent := ctl.lastEventByUsername[username] + ctl.lastEventByUsername[username] = "" + + log := ctl.log.WithField("last", lastEvent) + + if lastEvent == "" { + log.Debug("Nothing to wait for, event not recoreded") + return + } + + client, err := getPersistentClient(username) + if err != nil { + log.WithError(err).Error("Cannot get persistent client to check event") + return + } + + for i, delay := range []int{1, 5, 10, 30} { + ilog := log.WithField("try", i) + event, err := client.GetEvent(context.Background(), "") + if err != nil { + ilog.WithError(err).Error("Cannot check event") + return + } + if lastEvent != event.EventID { + ilog.WithField("current", event.EventID).Debug("Event changed") + return + } + + ilog.WithField("delay", delay).Warn("Retrying event change again") + time.Sleep(time.Duration(delay) * time.Second) + } + + ctl.log.WithError(err).Warn("Event check timed out") } diff --git a/test/mocks/imap_client.go b/test/mocks/imap_client.go index 1d2322ab..78c88d6f 100644 --- a/test/mocks/imap_client.go +++ b/test/mocks/imap_client.go @@ -23,6 +23,7 @@ import ( "net" "strings" "sync" + "time" "github.com/ProtonMail/proton-bridge/pkg/message" "github.com/stretchr/testify/assert" @@ -176,6 +177,7 @@ func (c *IMAPClient) AppendBody(mailboxName, subject, from, to, body string) *IM msg := fmt.Sprintf("Subject: %s\r\n", subject) msg += fmt.Sprintf("From: %s\r\n", from) msg += fmt.Sprintf("To: %s\r\n", to) + msg += fmt.Sprintf("Message-Id: <%d@imapbridge.com>\r\n", time.Now().Unix()) if mailboxName != "Sent" { msg += "Received: by 2002:0:0:0:0:0:0:0 with SMTP id 0123456789abcdef; Wed, 30 Dec 2020 01:23:45 0000\r\n" } diff --git a/test/store_setup_test.go b/test/store_setup_test.go index 0a70e0a2..0f8cc622 100644 --- a/test/store_setup_test.go +++ b/test/store_setup_test.go @@ -37,6 +37,7 @@ func StoreSetupFeatureContext(s *godog.ScenarioContext) { s.Step(`^there are (\d+) messages in mailbox(?:es)? "([^"]*)" for "([^"]*)"$`, thereAreSomeMessagesInMailboxesForUser) s.Step(`^there are messages for "([^"]*)" as follows$`, thereAreSomeMessagesForUserAsFollows) s.Step(`^there are (\d+) messages in mailbox(?:es)? "([^"]*)" for address "([^"]*)" of "([^"]*)"$`, thereAreSomeMessagesInMailboxesForAddressOfUser) + s.Step(`^wait for Sphinx to create duplication indices$`, waitForSphinx) } func thereIsUserWithMailboxes(bddUserID string, mailboxes *godog.Table) error { @@ -75,18 +76,18 @@ func thereAreMessagesInMailboxesForUser(mailboxNames, bddUserID string, messages } func thereAreMessagesInMailboxesForAddressOfUser(mailboxNames, bddAddressID, bddUserID string, messages *godog.Table) error { - // It is needed to prevent event processing before syncing these message - // otherwise the seqID and UID will be in reverse order. The - // synchronization add newest message first, the eventloop adds the oldest - // message first. - ctx.MessagePreparationStarted() - defer ctx.MessagePreparationFinished() - account := ctx.GetTestAccountWithAddress(bddUserID, bddAddressID) if account == nil { return godog.ErrPending } + // It is needed to prevent event processing before syncing these message + // otherwise the seqID and UID will be in reverse order. The + // synchronization add newest message first, the eventloop adds the oldest + // message first. + ctx.MessagePreparationStarted(account.Username()) + defer ctx.MessagePreparationFinished(account.Username()) + labelIDs, err := ctx.GetPMAPIController().GetLabelIDs(account.Username(), strings.Split(mailboxNames, ",")) if err != nil { return internalError(err, "getting labels %s for %s", mailboxNames, account.Username()) @@ -100,9 +101,10 @@ func thereAreMessagesInMailboxesForAddressOfUser(mailboxNames, bddAddressID, bdd for i := len(messages.Rows) - 1; i > 0; i-- { row := messages.Rows[i] message := &pmapi.Message{ - MIMEType: pmapi.ContentTypePlainText, - LabelIDs: labelIDs, - AddressID: account.AddressID(), + MIMEType: pmapi.ContentTypePlainText, + LabelIDs: labelIDs, + AddressID: account.AddressID(), + ExternalID: fmt.Sprintf("%d@integration.setup.test", time.Now().Unix()), } header := make(textproto.MIMEHeader) @@ -275,30 +277,31 @@ func processMailboxStructureDataTable(structure *godog.Table, callback func(stri } func thereAreSomeMessagesInMailboxesForAddressOfUser(numberOfMessages int, mailboxNames, bddAddressID, bddUserID string) error { - // It is needed to prevent event processing before syncing these message - // otherwise the seqID and UID will be in reverse order. The - // synchronization add newest message first, the eventloop adds the oldest - // message first. - ctx.MessagePreparationStarted() - defer ctx.MessagePreparationFinished() - account := ctx.GetTestAccountWithAddress(bddUserID, bddAddressID) if account == nil { return godog.ErrPending } + // It is needed to prevent event processing before syncing these message + // otherwise the seqID and UID will be in reverse order. The + // synchronization add newest message first, the eventloop adds the oldest + // message first. + ctx.MessagePreparationStarted(account.Username()) + defer ctx.MessagePreparationFinished(account.Username()) + for i := 1; i <= numberOfMessages; i++ { labelIDs, err := ctx.GetPMAPIController().GetLabelIDs(account.Username(), strings.Split(mailboxNames, ",")) if err != nil { return internalError(err, "getting labels %s for %s", mailboxNames, account.Username()) } lastMessageID, err := ctx.GetPMAPIController().AddUserMessage(account.Username(), &pmapi.Message{ - MIMEType: "text/plain", - LabelIDs: labelIDs, - AddressID: account.AddressID(), - Subject: fmt.Sprintf("Test message #%d", i), - Sender: &mail.Address{Address: "anyone@example.com"}, - ToList: []*mail.Address{{Address: account.Address()}}, + MIMEType: "text/plain", + LabelIDs: labelIDs, + AddressID: account.AddressID(), + Subject: fmt.Sprintf("Test message #%d", i), + Sender: &mail.Address{Address: "anyone@example.com"}, + ToList: []*mail.Address{{Address: account.Address()}}, + ExternalID: fmt.Sprintf("%d@integration.setup.test", time.Now().Unix()), }) if err != nil { return internalError(err, "adding message") @@ -311,3 +314,8 @@ func thereAreSomeMessagesInMailboxesForAddressOfUser(numberOfMessages int, mailb } return internalError(ctx.WaitForSync(account.Username()), "waiting for sync") } + +func waitForSphinx() error { + time.Sleep(15 * time.Second) + return nil +}