Skip to content

Commit

Permalink
feat(GODT-3199): improve logging. (#405)
Browse files Browse the repository at this point in the history 
* feat(GODT-3199): add package log field.
* feat(GODT-3199): log ids for fetched body.
  • Loading branch information
@cuthix
cuthix authored Feb 27, 2024
1 parent 89b40fb commit 3734c76
Show file tree
Hide file tree
Showing 12 changed files with 87 additions and 60 deletions.
2 changes: 1 addition & 1 deletion imap/utils.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
25 changes: 14 additions & 11 deletions internal/backend/backend.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,8 @@ type Backend struct {
database db.ClientInterface

panicHandler async.PanicHandler

log *logrus.Entry
}

func New(dataDir, databaseDir string,
Expand All @@ -73,6 +75,7 @@ func New(dataDir, databaseDir string,
imapLimits: imapLimits,
panicHandler: panicHandler,
database: database,
log: logrus.WithField("pkg", "gluon/backend"),
}, nil
}

Expand All @@ -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")
}
}

Expand All @@ -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
Expand Down Expand Up @@ -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).
Expand Down Expand Up @@ -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
}
Expand Down
13 changes: 6 additions & 7 deletions internal/backend/connector_updates.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
}
}
}
Expand Down Expand Up @@ -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)
Expand All @@ -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
Expand Down
25 changes: 17 additions & 8 deletions internal/backend/user.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,8 @@ type user struct {
panicHandler async.PanicHandler

recoveredMessageHashes *utils.MessageHashesMap

log *logrus.Entry
}

func newUser(
Expand All @@ -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()
Expand Down Expand Up @@ -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)
}
}

Expand Down Expand Up @@ -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)
Expand All @@ -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:
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
Expand Down
9 changes: 4 additions & 5 deletions internal/session/command.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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
Expand Down
3 changes: 1 addition & 2 deletions internal/session/handle.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand All @@ -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 {
Expand Down
9 changes: 4 additions & 5 deletions internal/session/handle_idle.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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?
Expand All @@ -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")
}
}
}
Expand Down Expand Up @@ -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

Expand All @@ -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")
}
}
}
Expand All @@ -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)
Expand Down
7 changes: 5 additions & 2 deletions internal/session/session.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,6 +90,8 @@ type Session struct {
imapLimits limits.IMAP

panicHandler async.PanicHandler

log *logrus.Entry
}

func New(
Expand Down Expand Up @@ -118,6 +120,7 @@ func New(
cmdProfilerBuilder: profiler,
handleWG: async.MakeWaitGroup(panicHandler),
panicHandler: panicHandler,
log: logrus.WithField("pkg", "gluon/session").WithField("session", sessionID),
}
}

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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")
}
}

Expand Down
Loading

0 comments on commit 3734c76

Please sign in to comment.