GODT-1754: Add logs for unilateral updates and SEARCH.

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

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()
 

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{
+	l := iu.updateLog(address, mailboxName).
-		"address": address,
+		WithFields(logrus.Fields{
-		"mailbox": mailboxName,
 			"seqNum":  sequenceNumber,
 			"uid":     uid,
 			"flags":   message.GetFlags(msg),
 			"deleted": hasDeletedFlag,
-	}).Trace("IDLE update")
+		})
+	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{
+	l := iu.updateLog(address, mailboxName).
-		"address": address,
+		WithField("seqNum", sequenceNumber)
-		"mailbox": mailboxName,
+	l.Info("IDLE delete")
-		"seqNum":  sequenceNumber,
-	}).Trace("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{
+	l := iu.updateLog(address, mailboxName)
-		"address": address,
+	l.Info("IDLE mailbox info")
-		"mailbox": mailboxName,
-	}).Trace("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{
+	l := iu.updateLog(address, mailboxName).
-		"address":      address,
+		WithFields(logrus.Fields{
-		"mailbox":      mailboxName,
 			"total":        total,
 			"unread":       unread,
 			"unreadSeqNum": unreadSeqNum,
-	}).Trace("IDLE status")
+		})
+	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)
+}

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

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
 		}

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()
+	aes, err := aes.NewCipher(algo.Hash256(passphrase))
-
-	if _, err := hash.Write(passphrase); err != nil {
-		return err
-	}
-
-	aes, err := aes.NewCipher(hash.Sum(nil))
 	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))
 }

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 <https://www.gnu.org/licenses/>.
 
-package cache
+package algo
 
 import (
 	"crypto/sha256"
+	"encoding/base64"
 	"encoding/hex"
 )
 
-func getHash(name string) string {
+func Hash256(b []byte) []byte {
-	hash := sha256.New()
+	h := sha256.Sum256(b)
-
+	return h[:]
-	if _, err := hash.Write([]byte(name)); err != nil {
+}
-		// sha256.Write always returns nill err so this should never happen
+
-		panic(err)
+func HashBase64SHA256(s string) string {
-	}
+	return base64.StdEncoding.EncodeToString(
-
+		Hash256([]byte(s)),
-	return hex.EncodeToString(hash.Sum(nil))
+	)
+}
+
+func HashHexSHA256(s string) string {
+	return hex.EncodeToString(
+		Hash256([]byte(s)),
+	)
 }

pkg/message/build_boundary.go

@@ -18,8 +18,7 @@
 package message
 
 import (
-	"crypto/sha256"
+	"github.com/ProtonMail/proton-bridge/v2/pkg/algo"
-	"encoding/hex"
 )
 
 type boundary struct {
@@ -31,13 +30,6 @@ func newBoundary(seed string) *boundary {
 }
 
 func (bw *boundary) gen() string {
-	hash := sha256.New()
+	bw.val = algo.HashHexSHA256(bw.val)
-
-	if _, err := hash.Write([]byte(bw.val)); err != nil {
-		panic(err)
-	}
-
-	bw.val = hex.EncodeToString(hash.Sum(nil))
-
 	return bw.val
 }

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`, algo.HashBase64SHA256(string(cert.RawSubjectPublicKeyInfo)))
-	return fmt.Sprintf(`pin-sha256=%q`, base64.StdEncoding.EncodeToString(hash[:]))
 }