GODT-1041 Log IMAP requests to debug Apple Mail re-sync issue

internal/imap/mailbox.go

@@ -19,6 +19,7 @@ package imap
 
 import (
 	"strings"
+	"time"
 
 	"github.com/ProtonMail/proton-bridge/pkg/message"
 	"github.com/ProtonMail/proton-bridge/pkg/pmapi"
@@ -56,6 +57,25 @@ func newIMAPMailbox(panicHandler panicHandler, user *imapUser, storeMailbox stor
 	}
 }
 
+// logCommand is helper to log commands requested by IMAP client with their
+// params, result, and duration, but without private data.
+// It's logged as INFO so it's logged for every user by default. This should
+// help devs to find out reasons why clients, mostly Apple Mail, does re-sync.
+// FETCH, APPEND, STORE, COPY, MOVE, and EXPUNGE should be using this helper.
+func (im *imapMailbox) logCommand(callback func() error, cmd string, params ...interface{}) error {
+	start := time.Now()
+	err := callback()
+	// Not using im.log to not include addressID which is not needed in this case.
+	log.WithFields(logrus.Fields{
+		"userID":   im.storeUser.UserID(),
+		"labelID":  im.storeMailbox.LabelID(),
+		"duration": time.Since(start),
+		"err":      err,
+		"params":   params,
+	}).Info(cmd)
+	return err
+}
+
 // Name returns this mailbox name.
 func (im *imapMailbox) Name() string {
 	// Called from go-imap in goroutines - we need to handle panics for each function.
@@ -183,6 +203,10 @@ func (im *imapMailbox) Expunge() error {
 		defer im.user.appendExpungeLock.Unlock()
 	}
 
+	return im.logCommand(im.expunge, "EXPUNGE")
+}
+
+func (im *imapMailbox) expunge() error {
 	im.user.backend.updates.block(im.user.currentAddressLowercase, im.name, operationDeleteMessage)
 	defer im.user.backend.updates.unblock(im.user.currentAddressLowercase, im.name, operationDeleteMessage)
 
@@ -192,6 +216,12 @@ func (im *imapMailbox) Expunge() error {
 // UIDExpunge permanently removes messages that have the \Deleted flag set
 // and UID passed from SeqSet from the currently selected mailbox.
 func (im *imapMailbox) UIDExpunge(seqSet *imap.SeqSet) error {
+	return im.logCommand(func() error {
+		return im.uidExpunge(seqSet)
+	}, "UID EXPUNGE", seqSet)
+}
+
+func (im *imapMailbox) uidExpunge(seqSet *imap.SeqSet) error {
 	// See comment of appendExpungeLock.
 	if im.storeMailbox.LabelID() == pmapi.TrashLabel || im.storeMailbox.LabelID() == pmapi.SpamLabel {
 		im.user.appendExpungeLock.Lock()

internal/imap/mailbox_message.go

@@ -66,7 +66,13 @@ func (dnc *doNotCacheError) errorOrNil() error {
 //
 // If the Backend implements Updater, it must notify the client immediately
 // via a mailbox update.
-func (im *imapMailbox) CreateMessage(flags []string, date time.Time, body imap.Literal) error { // nolint[funlen]
+func (im *imapMailbox) CreateMessage(flags []string, date time.Time, body imap.Literal) error {
+	return im.logCommand(func() error {
+		return im.createMessage(flags, date, body)
+	}, "APPEND", flags, date)
+}
+
+func (im *imapMailbox) createMessage(flags []string, date time.Time, body imap.Literal) error { // nolint[funlen]
 	// Called from go-imap in goroutines - we need to handle panics for each function.
 	defer im.panicHandler.HandlePanic()
 

internal/imap/mailbox_messages.go

@@ -38,6 +38,12 @@ import (
 // If the Backend implements Updater, it must notify the client immediately
 // via a message update.
 func (im *imapMailbox) UpdateMessagesFlags(uid bool, seqSet *imap.SeqSet, operation imap.FlagsOp, flags []string) error {
+	return im.logCommand(func() error {
+		return im.updateMessagesFlags(uid, seqSet, operation, flags)
+	}, "STORE", uid, seqSet, operation, flags)
+}
+
+func (im *imapMailbox) updateMessagesFlags(uid bool, seqSet *imap.SeqSet, operation imap.FlagsOp, flags []string) error {
 	log.WithFields(logrus.Fields{
 		"flags":     flags,
 		"operation": operation,
@@ -198,6 +204,12 @@ func (im *imapMailbox) addOrRemoveFlags(operation imap.FlagsOp, messageIDs, flag
 // destination mailbox. The flags and internal date of the message(s) SHOULD
 // be preserved, and the Recent flag SHOULD be set, in the copy.
 func (im *imapMailbox) CopyMessages(uid bool, seqSet *imap.SeqSet, targetLabel string) error {
+	return im.logCommand(func() error {
+		return im.copyMessages(uid, seqSet, targetLabel)
+	}, "COPY", uid, seqSet, targetLabel)
+}
+
+func (im *imapMailbox) copyMessages(uid bool, seqSet *imap.SeqSet, targetLabel string) error {
 	// Called from go-imap in goroutines - we need to handle panics for each function.
 	defer im.panicHandler.HandlePanic()
 
@@ -209,6 +221,12 @@ func (im *imapMailbox) CopyMessages(uid bool, seqSet *imap.SeqSet, targetLabel s
 // This should not be used until MOVE extension has option to send UIDPLUS
 // responses.
 func (im *imapMailbox) MoveMessages(uid bool, seqSet *imap.SeqSet, targetLabel string) error {
+	return im.logCommand(func() error {
+		return im.moveMessages(uid, seqSet, targetLabel)
+	}, "MOVE", uid, seqSet, targetLabel)
+}
+
+func (im *imapMailbox) moveMessages(uid bool, seqSet *imap.SeqSet, targetLabel string) error {
 	// Called from go-imap in goroutines - we need to handle panics for each function.
 	defer im.panicHandler.HandlePanic()
 
@@ -463,7 +481,13 @@ func (im *imapMailbox) SearchMessages(isUID bool, criteria *imap.SearchCriteria)
 // 3501 section 6.4.5 for a list of items that can be requested.
 //
 // Messages must be sent to msgResponse. When the function returns, msgResponse must be closed.
-func (im *imapMailbox) ListMessages(isUID bool, seqSet *imap.SeqSet, items []imap.FetchItem, msgResponse chan<- *imap.Message) (err error) { //nolint[funlen]
+func (im *imapMailbox) ListMessages(isUID bool, seqSet *imap.SeqSet, items []imap.FetchItem, msgResponse chan<- *imap.Message) error {
+	return im.logCommand(func() error {
+		return im.listMessages(isUID, seqSet, items, msgResponse)
+	}, "FETCH", isUID, seqSet, items)
+}
+
+func (im *imapMailbox) listMessages(isUID bool, seqSet *imap.SeqSet, items []imap.FetchItem, msgResponse chan<- *imap.Message) (err error) { //nolint[funlen]
 	defer func() {
 		close(msgResponse)
 		if err != nil {