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

@@ -72,12 +72,15 @@ func newManager(cfg Config) *manager {
 
 	// Configure retry mechanism.
 	//
-	// SetRetryCount(30): The most probable value of Retry-After is 1s (max
+	// SetRetryCount(5): The most probable value of Retry-After from our
-	// 10s). Retrying up to 30 times will most probably cause a delay of
+	// API is 1s (max 10s). Retrying up to 5 times will on average cause a
-	// 30s. The worst case scenario is 5min which is OK for background
+	// delay of 40s.
-	// requests. We shuold use context to control a foreground requests
+	//
-	// which should be finish or fail sooner.
+	// NOTE: Increasing to values larger than 10 causing significant delay.
-	m.rc.SetRetryCount(30)
+	// 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)

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...)
 }

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) MessagePreparationStarted(username string) {
-func (ctx *TestContext) MessagePreparationFinished() { ctx.pmapiController.UnlockEvents() }
+	ctx.pmapiController.LockEvents(username)
+}
+func (ctx *TestContext) MessagePreparationFinished(username string) {
+	ctx.pmapiController.UnlockEvents(username)
+}

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()
+	LockEvents(username string)
-	UnlockEvents()
+	UnlockEvents(username string)
 }
 
 func newPMAPIController(listener listener.Listener) (PMAPIController, pmapi.Manager) {

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) {}

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 "INBOX" for "userMoreAddresses"
-    And there are messages in mailbox "Folders/mbox" for "userMoreAddresses"
       | from              | to          | subject |
       | john.doe@mail.com | [primary]   | foo     |
       | jane.doe@mail.com | [secondary] | bar     |

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"

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

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"

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{

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")
 }

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"
 	}

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())
@@ -103,6 +104,7 @@ func thereAreMessagesInMailboxesForAddressOfUser(mailboxNames, bddAddressID, bdd
 			MIMEType:   pmapi.ContentTypePlainText,
 			LabelIDs:   labelIDs,
 			AddressID:  account.AddressID(),
+			ExternalID: fmt.Sprintf("%d@integration.setup.test", time.Now().Unix()),
 		}
 		header := make(textproto.MIMEHeader)
 
@@ -275,18 +277,18 @@ 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 {
@@ -299,6 +301,7 @@ func thereAreSomeMessagesInMailboxesForAddressOfUser(numberOfMessages int, mailb
 			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
+}