From 9bb16dec48ec906c3d4e6c89bebe3e49e1412e92 Mon Sep 17 00:00:00 2001 From: Jakub Date: Tue, 2 Aug 2022 12:39:48 +0200 Subject: [PATCH] GODT-1754: Add logs for unilateral updates and SEARCH. --- internal/imap/backend.go | 5 +- internal/imap/mailbox_messages.go | 11 ++- internal/imap/updates.go | 98 ++++++++++++++-------- internal/imap/updates_test.go | 4 +- internal/imap/user.go | 7 ++ internal/store/cache/disk.go | 14 +--- {internal/store/cache => pkg/algo}/hash.go | 27 +++--- pkg/message/build_boundary.go | 12 +-- pkg/pmapi/dialer_pinning_checker.go | 7 +- 9 files changed, 112 insertions(+), 73 deletions(-) rename {internal/store/cache => pkg/algo}/hash.go (72%) diff --git a/internal/imap/backend.go b/internal/imap/backend.go index 6b5cc1de..124cfc33 100644 --- a/internal/imap/backend.go +++ b/internal/imap/backend.go @@ -93,10 +93,9 @@ func newIMAPBackend( eventListener listener.Listener, listWorkers int, ) *imapBackend { - return &imapBackend{ + ib := &imapBackend{ panicHandler: panicHandler, bridge: bridge, - updates: newIMAPUpdates(), eventListener: eventListener, users: map[string]*imapUser{}, @@ -106,6 +105,8 @@ func newIMAPBackend( imapCacheLock: &sync.RWMutex{}, listWorkers: listWorkers, } + ib.updates = newIMAPUpdates(ib) + return ib } func (ib *imapBackend) getUser(address string) (*imapUser, error) { diff --git a/internal/imap/mailbox_messages.go b/internal/imap/mailbox_messages.go index 34e41265..c3ce6359 100644 --- a/internal/imap/mailbox_messages.go +++ b/internal/imap/mailbox_messages.go @@ -332,7 +332,16 @@ func (im *imapMailbox) labelMessages(uid bool, seqSet *imap.SeqSet, targetLabel // SearchMessages searches messages. The returned list must contain UIDs if // uid is set to true, or sequence numbers otherwise. -func (im *imapMailbox) SearchMessages(isUID bool, criteria *imap.SearchCriteria) (ids []uint32, err error) { //nolint:gocyclo,funlen +func (im *imapMailbox) SearchMessages(isUID bool, criteria *imap.SearchCriteria) (ids []uint32, err error) { + err = im.logCommand(func() error { + var searchError error + ids, searchError = im.searchMessages(isUID, criteria) + return searchError + }, "SEARCH", isUID, criteria.Format()) + return ids, err +} + +func (im *imapMailbox) searchMessages(isUID bool, criteria *imap.SearchCriteria) (ids []uint32, err error) { //nolint:gocyclo,funlen // Called from go-imap in goroutines - we need to handle panics for each function. defer im.panicHandler.HandlePanic() diff --git a/internal/imap/updates.go b/internal/imap/updates.go index 9f8d262a..cc84eb2c 100644 --- a/internal/imap/updates.go +++ b/internal/imap/updates.go @@ -23,6 +23,7 @@ import ( "time" "github.com/ProtonMail/proton-bridge/v2/internal/store" + "github.com/ProtonMail/proton-bridge/v2/pkg/algo" "github.com/ProtonMail/proton-bridge/v2/pkg/message" "github.com/ProtonMail/proton-bridge/v2/pkg/pmapi" imap "github.com/emersion/go-imap" @@ -42,14 +43,16 @@ type imapUpdates struct { blocking map[string]bool delayedExpunges map[string][]chan struct{} ch chan goIMAPBackend.Update + ib *imapBackend } -func newIMAPUpdates() *imapUpdates { +func newIMAPUpdates(ib *imapBackend) *imapUpdates { return &imapUpdates{ lock: &sync.Mutex{}, blocking: map[string]bool{}, delayedExpunges: map[string][]chan struct{}{}, ch: make(chan goIMAPBackend.Update), + ib: ib, } } @@ -113,6 +116,8 @@ func (iu *imapUpdates) CanDelete(mailboxID string) (bool, func()) { } func (iu *imapUpdates) Notice(address, notice string) { + l := iu.updateLog(address, "") + l.Info("Notice") update := new(goIMAPBackend.StatusUpdate) update.Update = goIMAPBackend.NewUpdate(address, "") update.StatusResp = &imap.StatusResp{ @@ -120,7 +125,7 @@ func (iu *imapUpdates) Notice(address, notice string) { Code: imap.CodeAlert, Info: notice, } - iu.sendIMAPUpdate(update, false) + iu.sendIMAPUpdate(l, update, false) } func (iu *imapUpdates) UpdateMessage( @@ -128,14 +133,14 @@ func (iu *imapUpdates) UpdateMessage( uid, sequenceNumber uint32, msg *pmapi.Message, hasDeletedFlag bool, ) { - log.WithFields(logrus.Fields{ - "address": address, - "mailbox": mailboxName, - "seqNum": sequenceNumber, - "uid": uid, - "flags": message.GetFlags(msg), - "deleted": hasDeletedFlag, - }).Trace("IDLE update") + l := iu.updateLog(address, mailboxName). + WithFields(logrus.Fields{ + "seqNum": sequenceNumber, + "uid": uid, + "flags": message.GetFlags(msg), + "deleted": hasDeletedFlag, + }) + l.Info("IDLE update") update := new(goIMAPBackend.MessageUpdate) update.Update = goIMAPBackend.NewUpdate(address, mailboxName) update.Message = imap.NewMessage(sequenceNumber, []imap.FetchItem{imap.FetchFlags, imap.FetchUid}) @@ -144,26 +149,22 @@ func (iu *imapUpdates) UpdateMessage( update.Message.Flags = append(update.Message.Flags, imap.DeletedFlag) } update.Message.Uid = uid - iu.sendIMAPUpdate(update, iu.isBlocking(address, mailboxName, operationUpdateMessage)) + iu.sendIMAPUpdate(l, update, iu.isBlocking(address, mailboxName, operationUpdateMessage)) } func (iu *imapUpdates) DeleteMessage(address, mailboxName string, sequenceNumber uint32) { - log.WithFields(logrus.Fields{ - "address": address, - "mailbox": mailboxName, - "seqNum": sequenceNumber, - }).Trace("IDLE delete") + l := iu.updateLog(address, mailboxName). + WithField("seqNum", sequenceNumber) + l.Info("IDLE delete") update := new(goIMAPBackend.ExpungeUpdate) update.Update = goIMAPBackend.NewUpdate(address, mailboxName) update.SeqNum = sequenceNumber - iu.sendIMAPUpdate(update, iu.isBlocking(address, mailboxName, operationDeleteMessage)) + iu.sendIMAPUpdate(l, update, iu.isBlocking(address, mailboxName, operationDeleteMessage)) } func (iu *imapUpdates) MailboxCreated(address, mailboxName string) { - log.WithFields(logrus.Fields{ - "address": address, - "mailbox": mailboxName, - }).Trace("IDLE mailbox info") + l := iu.updateLog(address, mailboxName) + l.Info("IDLE mailbox info") update := new(goIMAPBackend.MailboxInfoUpdate) update.Update = goIMAPBackend.NewUpdate(address, "") update.MailboxInfo = &imap.MailboxInfo{ @@ -171,29 +172,30 @@ func (iu *imapUpdates) MailboxCreated(address, mailboxName string) { Delimiter: store.PathDelimiter, Name: mailboxName, } - iu.sendIMAPUpdate(update, false) + iu.sendIMAPUpdate(l, update, false) } func (iu *imapUpdates) MailboxStatus(address, mailboxName string, total, unread, unreadSeqNum uint32) { - log.WithFields(logrus.Fields{ - "address": address, - "mailbox": mailboxName, - "total": total, - "unread": unread, - "unreadSeqNum": unreadSeqNum, - }).Trace("IDLE status") + l := iu.updateLog(address, mailboxName). + WithFields(logrus.Fields{ + "total": total, + "unread": unread, + "unreadSeqNum": unreadSeqNum, + }) + l.Info("IDLE status") update := new(goIMAPBackend.MailboxUpdate) update.Update = goIMAPBackend.NewUpdate(address, mailboxName) update.MailboxStatus = imap.NewMailboxStatus(mailboxName, []imap.StatusItem{imap.StatusMessages, imap.StatusUnseen}) update.MailboxStatus.Messages = total update.MailboxStatus.Unseen = unread update.MailboxStatus.UnseenSeqNum = unreadSeqNum - iu.sendIMAPUpdate(update, true) + iu.sendIMAPUpdate(l, update, true) } -func (iu *imapUpdates) sendIMAPUpdate(update goIMAPBackend.Update, isBlocking bool) { +func (iu *imapUpdates) sendIMAPUpdate(updateLog *logrus.Entry, update goIMAPBackend.Update, isBlocking bool) { + l := updateLog.WithField("blocking", isBlocking) if iu.ch == nil { - log.Trace("IMAP IDLE unavailable") + l.Info("IMAP IDLE unavailable") return } @@ -201,7 +203,7 @@ func (iu *imapUpdates) sendIMAPUpdate(update goIMAPBackend.Update, isBlocking bo go func() { select { case <-time.After(1 * time.Second): - log.Warn("IMAP update could not be sent (timeout)") + l.Warn("IMAP update could not be sent (timeout)") return case iu.ch <- update: } @@ -214,7 +216,35 @@ func (iu *imapUpdates) sendIMAPUpdate(update goIMAPBackend.Update, isBlocking bo select { case <-done: case <-time.After(1 * time.Second): - log.Warn("IMAP update could not be delivered (timeout)") + l.Warn("IMAP update could not be delivered (timeout)") return } } + +func (iu *imapUpdates) getIDs(address, mailboxName string) (addressID, mailboxID string) { + addressID = "unknown-" + algo.HashBase64SHA256(address) + mailboxID = "unknown-" + algo.HashBase64SHA256(mailboxName) + + if iu == nil || iu.ib == nil { + return + } + + user, err := iu.ib.getUser(address) + if err != nil || user == nil || user.storeAddress == nil { + return + } + addressID = user.addressID + + if v := user.mailboxIDs[mailboxName]; v != "" { + mailboxID = v + } + + return +} + +func (iu *imapUpdates) updateLog(address, mailboxName string) *logrus.Entry { + addressID, mailboxID := iu.getIDs(address, mailboxName) + return log. + WithField("address", addressID). + WithField("mailbox", mailboxID) +} diff --git a/internal/imap/updates_test.go b/internal/imap/updates_test.go index f632c0ea..7fac2d3d 100644 --- a/internal/imap/updates_test.go +++ b/internal/imap/updates_test.go @@ -25,7 +25,7 @@ import ( ) func TestUpdatesCanDelete(t *testing.T) { - u := newIMAPUpdates() + u := newIMAPUpdates(nil) can, _ := u.CanDelete("mbox") require.True(t, can) @@ -38,7 +38,7 @@ func TestUpdatesCanDelete(t *testing.T) { } func TestUpdatesCannotDelete(t *testing.T) { - u := newIMAPUpdates() + u := newIMAPUpdates(nil) u.forbidExpunge("mbox") can, wait := u.CanDelete("mbox") diff --git a/internal/imap/user.go b/internal/imap/user.go index 6e87e79e..96a450b8 100644 --- a/internal/imap/user.go +++ b/internal/imap/user.go @@ -53,6 +53,9 @@ type imapUser struct { // not cause huge slow down as EXPUNGE is implicitly called also after // UNSELECT, CLOSE, or LOGOUT. appendExpungeLock sync.Mutex + + addressID string // cached value for logs to avoid lock + mailboxIDs map[string]string // cached values for logs to avoid lock } // newIMAPUser returns struct implementing go-imap/user interface. @@ -84,6 +87,8 @@ func newIMAPUser( storeAddress: storeAddress, currentAddressLowercase: strings.ToLower(address), + addressID: addressID, + mailboxIDs: map[string]string{}, }, err } @@ -128,6 +133,8 @@ func (iu *imapUser) ListMailboxes(showOnlySubcribed bool) ([]goIMAPBackend.Mailb mailboxes := []goIMAPBackend.Mailbox{} for _, storeMailbox := range iu.storeAddress.ListMailboxes() { + iu.mailboxIDs[storeMailbox.Name()] = storeMailbox.LabelID() + if storeMailbox.LabelID() == pmapi.AllMailLabel && !iu.backend.bridge.IsAllMailVisible() { continue } diff --git a/internal/store/cache/disk.go b/internal/store/cache/disk.go index 5f9992e8..6a611b38 100644 --- a/internal/store/cache/disk.go +++ b/internal/store/cache/disk.go @@ -21,7 +21,6 @@ import ( "crypto/aes" "crypto/cipher" "crypto/rand" - "crypto/sha256" "errors" "fmt" "io/ioutil" @@ -29,6 +28,7 @@ import ( "path/filepath" "sync" + "github.com/ProtonMail/proton-bridge/v2/pkg/algo" "github.com/ProtonMail/proton-bridge/v2/pkg/semaphore" "github.com/ricochet2200/go-disk-usage/du" ) @@ -100,13 +100,7 @@ func (c *onDiskCache) Lock(userID string) { } func (c *onDiskCache) Unlock(userID string, passphrase []byte) error { - hash := sha256.New() - - if _, err := hash.Write(passphrase); err != nil { - return err - } - - aes, err := aes.NewCipher(hash.Sum(nil)) + aes, err := aes.NewCipher(algo.Hash256(passphrase)) if err != nil { return err } @@ -279,9 +273,9 @@ func (c *onDiskCache) update() { } func (c *onDiskCache) getUserPath(userID string) string { - return filepath.Join(c.path, getHash(userID)) + return filepath.Join(c.path, algo.HashHexSHA256(userID)) } func (c *onDiskCache) getMessagePath(userID, messageID string) string { - return filepath.Join(c.getUserPath(userID), getHash(messageID)) + return filepath.Join(c.getUserPath(userID), algo.HashHexSHA256(messageID)) } diff --git a/internal/store/cache/hash.go b/pkg/algo/hash.go similarity index 72% rename from internal/store/cache/hash.go rename to pkg/algo/hash.go index 1c3454b1..ad7be95e 100644 --- a/internal/store/cache/hash.go +++ b/pkg/algo/hash.go @@ -15,20 +15,27 @@ // You should have received a copy of the GNU General Public License // along with Proton Mail Bridge. If not, see . -package cache +package algo import ( "crypto/sha256" + "encoding/base64" "encoding/hex" ) -func getHash(name string) string { - hash := sha256.New() - - if _, err := hash.Write([]byte(name)); err != nil { - // sha256.Write always returns nill err so this should never happen - panic(err) - } - - return hex.EncodeToString(hash.Sum(nil)) +func Hash256(b []byte) []byte { + h := sha256.Sum256(b) + return h[:] +} + +func HashBase64SHA256(s string) string { + return base64.StdEncoding.EncodeToString( + Hash256([]byte(s)), + ) +} + +func HashHexSHA256(s string) string { + return hex.EncodeToString( + Hash256([]byte(s)), + ) } diff --git a/pkg/message/build_boundary.go b/pkg/message/build_boundary.go index fa94611a..6ce3c01e 100644 --- a/pkg/message/build_boundary.go +++ b/pkg/message/build_boundary.go @@ -18,8 +18,7 @@ package message import ( - "crypto/sha256" - "encoding/hex" + "github.com/ProtonMail/proton-bridge/v2/pkg/algo" ) type boundary struct { @@ -31,13 +30,6 @@ func newBoundary(seed string) *boundary { } func (bw *boundary) gen() string { - hash := sha256.New() - - if _, err := hash.Write([]byte(bw.val)); err != nil { - panic(err) - } - - bw.val = hex.EncodeToString(hash.Sum(nil)) - + bw.val = algo.HashHexSHA256(bw.val) return bw.val } diff --git a/pkg/pmapi/dialer_pinning_checker.go b/pkg/pmapi/dialer_pinning_checker.go index d07f765a..79027e8f 100644 --- a/pkg/pmapi/dialer_pinning_checker.go +++ b/pkg/pmapi/dialer_pinning_checker.go @@ -18,13 +18,13 @@ package pmapi import ( - "crypto/sha256" "crypto/tls" "crypto/x509" - "encoding/base64" "errors" "fmt" "net" + + "github.com/ProtonMail/proton-bridge/v2/pkg/algo" ) // ErrTLSMismatch indicates that no TLS fingerprint match could be found. @@ -63,6 +63,5 @@ func (p *pinChecker) checkCertificate(conn net.Conn) error { } func certFingerprint(cert *x509.Certificate) string { - hash := sha256.Sum256(cert.RawSubjectPublicKeyInfo) - return fmt.Sprintf(`pin-sha256=%q`, base64.StdEncoding.EncodeToString(hash[:])) + return fmt.Sprintf(`pin-sha256=%q`, algo.HashBase64SHA256(string(cert.RawSubjectPublicKeyInfo))) }