feat(GODT-3199): improve logging.

imap/utils.go

@@ -2,7 +2,7 @@ package imap
 
 // ShortID return a string containing a short version of the given ID. Use only for debug display.
 func ShortID(id string) string {
-	const l = 12
+	const l = 36
 
 	if len(id) < l {
 		return id

internal/backend/backend.go

@@ -53,6 +53,8 @@ type Backend struct {
 	database db.ClientInterface
 
 	panicHandler async.PanicHandler
+
+	log *logrus.Entry
 }
 
 func New(dataDir, databaseDir string,
@@ -73,6 +75,7 @@ func New(dataDir, databaseDir string,
 		imapLimits:    imapLimits,
 		panicHandler:  panicHandler,
 		database:      database,
+		log:           logrus.WithField("pkg", "gluon/backend"),
 	}, nil
 }
 
@@ -97,7 +100,7 @@ func (b *Backend) AddUser(ctx context.Context, userID string, conn connector.Con
 
 	onErrorExit := func() {
 		if err := storeBuilder.Close(); err != nil {
-			logrus.WithError(err).Error("Failed to close store builder")
+			b.log.WithError(err).Error("Failed to close store builder")
 		}
 	}
 
@@ -109,48 +112,48 @@ func (b *Backend) AddUser(ctx context.Context, userID string, conn connector.Con
 
 	if err := database.Init(ctx, uidValidityGenerator); err != nil {
 		if err := database.Close(); err != nil {
-			logrus.WithError(err).Errorf("Failed to close db after migration failure")
+			b.log.WithError(err).Errorf("Failed to close db after migration failure")
 		}
 
 		if !errors.Is(err, db.ErrMigrationFailed) && !errors.Is(err, db.ErrInvalidDatabaseVersion) {
 			onErrorExit()
 			return false, err
 		}
 
-		logrus.WithError(err).Errorf("First database migration failed")
+		b.log.WithError(err).Errorf("First database migration failed")
 		reporter.ExceptionWithContext(ctx, "database migration failed", reporter.Context{
 			"error": err,
 		})
 
-		logrus.Debugf("First migration failed, recreating database")
+		b.log.Debugf("First migration failed, recreating database")
 
 		if err := b.database.Delete(b.getDBDir(), userID); err != nil {
-			logrus.WithError(err).Errorf("Failed to delete old database")
+			b.log.WithError(err).Errorf("Failed to delete old database")
 			onErrorExit()
 
 			return false, fmt.Errorf("failed to remove database after migration: %w", err)
 		}
 
 		database, isNew, err = b.database.New(b.getDBDir(), userID)
 		if err != nil {
-			logrus.WithError(err).Errorf("Failed to create new database")
+			b.log.WithError(err).Errorf("Failed to create new database")
 			onErrorExit()
 
 			return false, err
 		}
 
 		if !isNew {
-			logrus.Errorf("Expected new database to not exist")
+			b.log.Errorf("Expected new database to not exist")
 
 			if err := database.Close(); err != nil {
-				logrus.WithError(err).Errorf("failed to closed db")
+				b.log.WithError(err).Errorf("failed to closed db")
 			}
 
 			return false, fmt.Errorf("expected database to be new after failed migration cleanup")
 		}
 
 		if err := database.Init(ctx, uidValidityGenerator); err != nil {
-			logrus.WithError(err).Errorf("Second database migration failed")
+			b.log.WithError(err).Errorf("Second database migration failed")
 			onErrorExit()
 
 			return false, err
@@ -245,7 +248,7 @@ func (b *Backend) GetState(ctx context.Context, username string, password []byte
 		return nil, err
 	}
 
-	logrus.
+	b.log.
 		WithField("userID", userID).
 		WithField("username", username).
 		WithField("stateID", state.StateID).
@@ -285,7 +288,7 @@ func (b *Backend) Close(ctx context.Context) error {
 		delete(b.users, userID)
 	}
 
-	logrus.Debug("Backend was closed")
+	b.log.Debug("Backend was closed")
 
 	return nil
 }

internal/backend/connector_updates.go

@@ -16,13 +16,12 @@ import (
 	"github.com/ProtonMail/gluon/rfc822"
 	"github.com/bradenaw/juniper/parallel"
 	"github.com/bradenaw/juniper/xslices"
-	"github.com/sirupsen/logrus"
 	"golang.org/x/exp/slices"
 )
 
 // apply an incoming update originating from the connector.
 func (user *user) apply(ctx context.Context, update imap.Update) error {
-	logrus.WithField("update", update).WithField("user-id", user.userID).Debug("Applying update")
+	user.log.WithField("update", update).Debug("Applying update")
 
 	err := func() error {
 		switch update := update.(type) {
@@ -208,7 +207,7 @@ func (user *user) applyMessagesCreated(ctx context.Context, update *imap.Message
 	err := userDBWrite(ctx, user, func(ctx context.Context, tx db.Transaction) ([]state.Update, error) {
 		for _, message := range update.Messages {
 			if slices.Contains(message.MailboxIDs, ids.GluonInternalRecoveryMailboxRemoteID) {
-				logrus.Errorf("attempting to import messages into protected mailbox (recovery), skipping")
+				user.log.Errorf("attempting to import messages into protected mailbox (recovery), skipping")
 				continue
 			}
 
@@ -251,7 +250,7 @@ func (user *user) applyMessagesCreated(ctx context.Context, update *imap.Message
 					if err != nil {
 						// If a mailbox doesn't exist and we are allowed to skip move to next mailbox.
 						if update.IgnoreUnknownMailboxIDs {
-							logrus.WithField("MailboxID", mboxID.ShortID()).
+							user.log.WithField("MailboxID", mboxID.ShortID()).
 								WithField("MessageID", message.Message.ID.ShortID()).
 								Warn("Unknown Mailbox ID, skipping add to mailbox")
 							continue
@@ -336,7 +335,7 @@ func (user *user) applyMessagesCreated(ctx context.Context, update *imap.Message
 		for _, message := range messagesToCreate {
 			if err := user.store.DeleteUnchecked(message.InternalID); err != nil {
 				if !os.IsNotExist(err) {
-					logrus.WithError(err).Errorf("Failed to delete cache message %v after failed transaction", message.InternalID)
+					user.log.WithError(err).Errorf("Failed to delete cache message %v after failed transaction", message.InternalID)
 				}
 			}
 		}
@@ -571,7 +570,7 @@ func (user *user) applyMessageDeleted(ctx context.Context, update *imap.MessageD
 }
 
 func (user *user) applyMessageUpdated(ctx context.Context, update *imap.MessageUpdated) error {
-	log := logrus.WithField("message updated", update.Message.ID.ShortID())
+	log := user.log.WithField("message updated", update.Message.ID.ShortID())
 
 	internalMessageID, err := db.ClientReadType(ctx, user.db, func(ctx context.Context, client db.ReadOnly) (imap.InternalMessageID, error) {
 		return client.GetMessageIDFromRemoteID(ctx, update.Message.ID)
@@ -598,7 +597,7 @@ func (user *user) applyMessageUpdated(ctx context.Context, update *imap.MessageU
 		// compare and see if the literal has changed.
 		onDiskLiteral, err := user.store.Get(internalMessageID)
 		if err != nil {
-			logrus.Debugf("failed to retrieve literal from cache: %v", err)
+			user.log.Debugf("failed to retrieve literal from cache: %v", err)
 		}
 
 		updateLiteral := update.Literal

internal/backend/user.go

@@ -47,6 +47,8 @@ type user struct {
 	panicHandler async.PanicHandler
 
 	recoveredMessageHashes *utils.MessageHashesMap
+
+	log *logrus.Entry
 }
 
 func newUser(
@@ -62,6 +64,11 @@ func newUser(
 ) (*user, error) {
 	recoveredMessageHashes := utils.NewMessageHashesMap()
 
+	log := logrus.WithFields(logrus.Fields{
+		"pkg":    "gluon/user",
+		"userID": userID,
+	})
+
 	// Create recovery mailbox if it does not exist
 	recoveryMBox, err := db.ClientWriteType(ctx, database, func(ctx context.Context, tx db.Transaction) (*db.Mailbox, error) {
 		uidValidity, err := uidValidityGenerator.Generate()
@@ -92,12 +99,12 @@ func newUser(
 		for _, m := range messages {
 			literal, err := st.Get(m.InternalID)
 			if err != nil {
-				logrus.WithError(err).Errorf("Failed to load %v for store for recovered message hashes map", m.InternalID)
+				log.WithError(err).Errorf("Failed to load %v for store for recovered message hashes map", m.InternalID)
 				continue
 			}
 
 			if _, err := recoveredMessageHashes.Insert(m.InternalID, literal); err != nil {
-				logrus.WithError(err).Errorf("Failed insert literal for %v into recovered message hashes map", m.InternalID)
+				log.WithError(err).Errorf("Failed insert literal for %v into recovered message hashes map", m.InternalID)
 			}
 		}
 
@@ -129,25 +136,27 @@ func newUser(
 		panicHandler: panicHandler,
 
 		recoveredMessageHashes: recoveredMessageHashes,
+
+		log: log,
 	}
 
 	cacheProvider := NewDBIMAPState(database, user)
 
 	if err := conn.Init(ctx, cacheProvider); err != nil {
-		logrus.WithError(err).Errorf("Failed to init connector")
+		log.WithError(err).Errorf("Failed to init connector")
 		return nil, err
 	}
 
 	if err := user.deleteAllMessagesMarkedDeleted(ctx); err != nil {
-		logrus.WithError(err).Error("Failed to remove deleted messages")
+		log.WithError(err).Error("Failed to remove deleted messages")
 		reporter.MessageWithContext(ctx,
 			"Failed to remove deleted messages",
 			reporter.Context{"error": err},
 		)
 	}
 
 	if err := user.cleanupStaleStoreData(ctx); err != nil {
-		logrus.WithError(err).Error("Failed to cleanup stale store data")
+		log.WithError(err).Error("Failed to cleanup stale store data")
 	}
 
 	user.updateWG.Add(1)
@@ -171,7 +180,7 @@ func newUser(
 						reporter.Context{"error": err, "update": update.String()},
 					)
 
-					logrus.WithError(err).Errorf("Failed to apply update: %v", err)
+					log.WithError(err).Errorf("Failed to apply update: %v", err)
 				}
 
 			case <-user.updateQuitCh:
@@ -242,7 +251,7 @@ func (user *user) deleteAllMessagesMarkedDeleted(ctx context.Context) error {
 func (user *user) queueStateUpdate(updates ...state.Update) {
 	if err := user.forState(func(state *state.State) error {
 		if !state.QueueUpdates(updates...) {
-			logrus.Errorf("Failed to push update to state %v", state.StateID)
+			user.log.Errorf("Failed to push update to state %v", state.StateID)
 		}
 
 		return nil
@@ -321,7 +330,7 @@ func (user *user) removeState(ctx context.Context, st *state.State) error {
 
 	// If we fail to delete messages on disk, it shouldn't count as an error at this point.
 	if err := user.store.Delete(messageIDs...); err != nil {
-		logrus.WithError(err).Error("Failed to delete messages during removeState")
+		user.log.WithError(err).Error("Failed to delete messages during removeState")
 	}
 
 	return state.Close(ctx)

internal/session/command.go

@@ -11,7 +11,6 @@ import (
 	"github.com/ProtonMail/gluon/logging"
 	"github.com/ProtonMail/gluon/reporter"
 	"github.com/ProtonMail/gluon/rfcparser"
-	"github.com/sirupsen/logrus"
 )
 
 type commandResult struct {
@@ -58,26 +57,26 @@ func (s *Session) startCommandReader(ctx context.Context) <-chan commandResult {
 				// check if we are receiving raw TLS requests, if so skip.
 				for _, tlsHeader := range tlsHeaders {
 					if bytes.HasPrefix(bytesRead, tlsHeader) {
-						logrus.Errorf("TLS Handshake detected while not running with TLS/SSL")
+						s.log.Errorf("TLS Handshake detected while not running with TLS/SSL")
 						return
 					}
 				}
 
-				logrus.WithError(err).WithField("type", parser.LastParsedCommand()).Error("Failed to parse IMAP command")
+				s.log.WithError(err).WithField("type", parser.LastParsedCommand()).Error("Failed to parse IMAP command")
 
 				reporter.MessageWithContext(ctx,
 					"Failed to parse IMAP command",
 					reporter.Context{"error": err, "cmd": parser.LastParsedCommand()},
 				)
 			} else {
-				logrus.Debug(cmd.SanitizedString())
+				s.log.Debug(cmd.SanitizedString())
 			}
 
 			switch c := cmd.Payload.(type) {
 			case *command.StartTLS:
 				// TLS needs to be handled here to ensure that next command read is over the TLS connection.
 				if err = s.handleStartTLS(cmd.Tag, c); err != nil {
-					logrus.WithError(err).Error("Cannot upgrade connection")
+					s.log.WithError(err).Error("Cannot upgrade connection")
 					return
 				} else {
 					continue

internal/session/handle.go

@@ -8,7 +8,6 @@ import (
 	"github.com/ProtonMail/gluon/internal/response"
 	"github.com/ProtonMail/gluon/internal/state"
 	"github.com/ProtonMail/gluon/logging"
-	"github.com/sirupsen/logrus"
 )
 
 func (s *Session) handleOther(
@@ -23,7 +22,7 @@ func (s *Session) handleOther(
 			defer close(resCh)
 
 			if err := s.handleCommand(ctx, tag, cmd, resCh); err != nil {
-				logrus.WithError(err).WithField("cmd", cmd.SanitizedString()).Error("Command failed")
+				s.log.WithError(err).WithField("cmd", cmd.SanitizedString()).Error("Command failed")
 				if res, ok := response.FromError(err); ok {
 					resCh <- res
 				} else {

internal/session/handle_idle.go

@@ -9,7 +9,6 @@ import (
 	"github.com/ProtonMail/gluon/internal/response"
 	"github.com/ProtonMail/gluon/logging"
 	"github.com/ProtonMail/gluon/profiling"
-	"github.com/sirupsen/logrus"
 )
 
 // GOMSRV-86: What does it mean to do IDLE when you're not selected?
@@ -29,7 +28,7 @@ func (s *Session) handleIdle(ctx context.Context, tag string, _ *command.Idle, c
 			} else {
 				for res := range resCh {
 					if err := res.Send(s); err != nil {
-						logrus.WithError(err).Error("Failed to send IDLE update")
+						s.log.WithError(err).Error("Failed to send IDLE update")
 					}
 				}
 			}
@@ -67,7 +66,7 @@ func (s *Session) handleIdle(ctx context.Context, tag string, _ *command.Idle, c
 
 			case stateUpdate := <-s.state.GetStateUpdatesCh():
 				if err := s.state.ApplyUpdate(ctx, stateUpdate); err != nil {
-					logrus.WithError(err).Error("Failed to apply state update during idle")
+					s.log.WithError(err).Error("Failed to apply state update during idle")
 				}
 				continue
 
@@ -89,7 +88,7 @@ func (s *Session) handleIdle(ctx context.Context, tag string, _ *command.Idle, c
 func sendMergedResponses(s *Session, buffer []response.Response) {
 	for _, res := range response.Merge(buffer) {
 		if err := res.Send(s); err != nil {
-			logrus.WithError(err).Error("Failed to send IDLE update")
+			s.log.WithError(err).Error("Failed to send IDLE update")
 		}
 	}
 }
@@ -110,7 +109,7 @@ func sendResponsesInBulks(s *Session, resCh chan response.Response, idleBulkTime
 
 			if res != nil {
 				buffer = append(buffer, res)
-				logrus.WithField("response", res).Trace("Buffered")
+				s.log.WithField("response", res).Trace("Buffered")
 			}
 		case <-ticker.C:
 			sendMergedResponses(s, buffer)

internal/session/session.go

@@ -90,6 +90,8 @@ type Session struct {
 	imapLimits limits.IMAP
 
 	panicHandler async.PanicHandler
+
+	log *logrus.Entry
 }
 
 func New(
@@ -118,6 +120,7 @@ func New(
 		cmdProfilerBuilder: profiler,
 		handleWG:           async.MakeWaitGroup(panicHandler),
 		panicHandler:       panicHandler,
+		log:                logrus.WithField("pkg", "gluon/session").WithField("session", sessionID),
 	}
 }
 
@@ -171,7 +174,7 @@ func (s *Session) serve(ctx context.Context) error {
 		select {
 		case update := <-s.state.GetStateUpdatesCh():
 			if err := s.state.ApplyUpdate(ctx, update); err != nil {
-				logrus.WithError(err).Error("Failed to apply state update")
+				s.log.WithError(err).Error("Failed to apply state update")
 			}
 
 			continue
@@ -275,7 +278,7 @@ func (s *Session) done(ctx context.Context) {
 
 	if s.state != nil {
 		if err := s.state.ReleaseState(ctx); err != nil {
-			logrus.WithError(err).Error("Failed to close state")
+			s.log.WithError(err).Error("Failed to close state")
 		}
 	}