From 7bb7e1a518cea6f05c0eee7ea72b53d632fc1df7 Mon Sep 17 00:00:00 2001 From: Michal Horejsek Date: Mon, 15 Feb 2021 08:32:58 +0100 Subject: [PATCH] GODT-1041 Log IMAP requests to debug Apple Mail re-sync issue --- internal/imap/mailbox.go | 30 ++++++++++++++++++++++++++++++ internal/imap/mailbox_message.go | 8 +++++++- internal/imap/mailbox_messages.go | 26 +++++++++++++++++++++++++- 3 files changed, 62 insertions(+), 2 deletions(-) diff --git a/internal/imap/mailbox.go b/internal/imap/mailbox.go index d8d6203b..8dc09ccb 100644 --- a/internal/imap/mailbox.go +++ b/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() diff --git a/internal/imap/mailbox_message.go b/internal/imap/mailbox_message.go index b6a0f7f9..84793d25 100644 --- a/internal/imap/mailbox_message.go +++ b/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() diff --git a/internal/imap/mailbox_messages.go b/internal/imap/mailbox_messages.go index be6d15a2..b77ebf4c 100644 --- a/internal/imap/mailbox_messages.go +++ b/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 {