From c9b6cc162b5a986c7051912a3d00c6c772008a9c Mon Sep 17 00:00:00 2001 From: Jakub Date: Mon, 26 Feb 2024 14:16:50 +0100 Subject: [PATCH] feat(GODT-3199): add package log field. --- go.mod | 4 +- go.sum | 8 +-- internal/bridge/api.go | 2 +- internal/bridge/bridge.go | 34 +++++------ internal/bridge/configure.go | 2 +- internal/bridge/debug.go | 8 ++- internal/bridge/heartbeat.go | 4 +- internal/bridge/imap.go | 8 ++- internal/bridge/settings.go | 17 +++--- internal/bridge/user.go | 62 +++++++++++---------- internal/bridge/user_events.go | 4 +- internal/logging/imap_logger.go | 2 +- internal/logging/smtp_logger.go | 4 +- internal/services/imapsmtpserver/imap.go | 17 +++--- internal/services/imapsmtpserver/service.go | 58 +++++++++---------- internal/services/imapsmtpserver/smtp.go | 11 ++-- internal/user/user.go | 2 +- 17 files changed, 129 insertions(+), 118 deletions(-) diff --git a/go.mod b/go.mod index 6f7f954f..9f77c312 100644 --- a/go.mod +++ b/go.mod @@ -5,9 +5,9 @@ go 1.21 require ( github.com/0xAX/notificator v0.0.0-20220220101646-ee9b8921e557 github.com/Masterminds/semver/v3 v3.2.0 - github.com/ProtonMail/gluon v0.17.1-0.20240102132144-89b40fb6fe7e + github.com/ProtonMail/gluon v0.17.1-0.20240227105633-3734c7694bcd github.com/ProtonMail/go-autostart v0.0.0-20210130080809-00ed301c8e9a - github.com/ProtonMail/go-proton-api v0.4.1-0.20240226155311-30339d1d26ee + github.com/ProtonMail/go-proton-api v0.4.1-0.20240226161523-ec58ed7ea4b9 github.com/ProtonMail/gopenpgp/v2 v2.7.4-proton github.com/PuerkitoBio/goquery v1.8.1 github.com/abiosoft/ishell v2.0.0+incompatible diff --git a/go.sum b/go.sum index b4bfed5b..ee149ec2 100644 --- a/go.sum +++ b/go.sum @@ -27,8 +27,8 @@ github.com/OneOfOne/xxhash v1.2.2/go.mod h1:HSdplMjZKSmBqAxg5vPj2TmRDmfkzw+cTzAE github.com/ProtonMail/bcrypt v0.0.0-20210511135022-227b4adcab57/go.mod h1:HecWFHognK8GfRDGnFQbW/LiV7A3MX3gZVs45vk5h8I= github.com/ProtonMail/bcrypt v0.0.0-20211005172633-e235017c1baf h1:yc9daCCYUefEs69zUkSzubzjBbL+cmOXgnmt9Fyd9ug= github.com/ProtonMail/bcrypt v0.0.0-20211005172633-e235017c1baf/go.mod h1:o0ESU9p83twszAU8LBeJKFAAMX14tISa0yk4Oo5TOqo= -github.com/ProtonMail/gluon v0.17.1-0.20240102132144-89b40fb6fe7e h1:DR97ydcuS4/EjTTCkp7F9IRCi+ykD1UoAP7UBFtEcRA= -github.com/ProtonMail/gluon v0.17.1-0.20240102132144-89b40fb6fe7e/go.mod h1:Og5/Dz1MiGpCJn51XujZwxiLG7WzvvjE5PRpZBQmAHo= +github.com/ProtonMail/gluon v0.17.1-0.20240227105633-3734c7694bcd h1:AjJsf5xQGmZPg6GLn+wB+eBoGRopJlG70lQBfSyfX+M= +github.com/ProtonMail/gluon v0.17.1-0.20240227105633-3734c7694bcd/go.mod h1:Og5/Dz1MiGpCJn51XujZwxiLG7WzvvjE5PRpZBQmAHo= github.com/ProtonMail/go-autostart v0.0.0-20210130080809-00ed301c8e9a h1:D+aZah+k14Gn6kmL7eKxoo/4Dr/lK3ChBcwce2+SQP4= github.com/ProtonMail/go-autostart v0.0.0-20210130080809-00ed301c8e9a/go.mod h1:oTGdE7/DlWIr23G0IKW3OXK9wZ5Hw1GGiaJFccTvZi4= github.com/ProtonMail/go-crypto v0.0.0-20230321155629-9a39f2531310/go.mod h1:8TI4H3IbrackdNgv+92dI+rhpCaLqM0IfpgCgenFvRE= @@ -38,8 +38,8 @@ github.com/ProtonMail/go-message v0.13.1-0.20230526094639-b62c999c85b7 h1:+j+Kd/ github.com/ProtonMail/go-message v0.13.1-0.20230526094639-b62c999c85b7/go.mod h1:NBAn21zgCJ/52WLDyed18YvYFm5tEoeDauubFqLokM4= github.com/ProtonMail/go-mime v0.0.0-20230322103455-7d82a3887f2f h1:tCbYj7/299ekTTXpdwKYF8eBlsYsDVoggDAuAjoK66k= github.com/ProtonMail/go-mime v0.0.0-20230322103455-7d82a3887f2f/go.mod h1:gcr0kNtGBqin9zDW9GOHcVntrwnjrK+qdJ06mWYBybw= -github.com/ProtonMail/go-proton-api v0.4.1-0.20240226155311-30339d1d26ee h1:AW5GJkshqTLz8IAv1bs30De8wL7AkwLj22/UMZWUsXA= -github.com/ProtonMail/go-proton-api v0.4.1-0.20240226155311-30339d1d26ee/go.mod h1:t+hb0BfkmZ9fpvzVRpHC7limoowym6ln/j0XL9a8DDw= +github.com/ProtonMail/go-proton-api v0.4.1-0.20240226161523-ec58ed7ea4b9 h1:tcQpGQljNsZmfuA6L4hAzio8/AIx5OXcU2JUdyX/qxw= +github.com/ProtonMail/go-proton-api v0.4.1-0.20240226161523-ec58ed7ea4b9/go.mod h1:t+hb0BfkmZ9fpvzVRpHC7limoowym6ln/j0XL9a8DDw= github.com/ProtonMail/go-smtp v0.0.0-20231109081432-2b3d50599865 h1:EP1gnxLL5Z7xBSymE9nSTM27nRYINuvssAtDmG0suD8= github.com/ProtonMail/go-smtp v0.0.0-20231109081432-2b3d50599865/go.mod h1:qm27SGYgoIPRot6ubfQ/GpiPy/g3PaZAVRxiO/sDUgQ= github.com/ProtonMail/go-srp v0.0.7 h1:Sos3Qk+th4tQR64vsxGIxYpN3rdnG9Wf9K4ZloC1JrI= diff --git a/internal/bridge/api.go b/internal/bridge/api.go index c48a0759..6017dfea 100644 --- a/internal/bridge/api.go +++ b/internal/bridge/api.go @@ -40,7 +40,7 @@ func defaultAPIOptions( proton.WithAppVersion(constants.AppVersion(version.Original())), proton.WithCookieJar(cookieJar), proton.WithTransport(transport), - proton.WithLogger(logrus.StandardLogger()), + proton.WithLogger(logrus.WithField("pkg", "gpa/client")), proton.WithPanicHandler(panicHandler), } } diff --git a/internal/bridge/bridge.go b/internal/bridge/bridge.go index def83447..d6f3f878 100644 --- a/internal/bridge/bridge.go +++ b/internal/bridge/bridge.go @@ -132,6 +132,8 @@ type Bridge struct { syncService *syncservice.Service } +var logPkg = logrus.WithField("pkg", "bridge") //nolint:gochecknoglobals + // New creates a new bridge. func New( locator Locator, // the locator to provide paths to store data @@ -322,7 +324,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Handle connection up/down events. bridge.api.AddStatusObserver(func(status proton.Status) { - logrus.Info("API status changed: ", status) + logPkg.Info("API status changed: ", status) switch { case status == proton.StatusUp: @@ -337,7 +339,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // If any call returns a bad version code, we need to update. bridge.api.AddErrorHandler(proton.AppVersionBadCode, func() { - logrus.Warn("App version is bad") + logPkg.Warn("App version is bad") bridge.publish(events.UpdateForced{}) }) @@ -350,7 +352,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Log all manager API requests (client requests are logged separately). bridge.api.AddPostRequestHook(func(_ *resty.Client, r *resty.Response) error { if _, ok := proton.ClientIDFromContext(r.Request.Context()); !ok { - logrus.Infof("[MANAGER] %v: %v %v", r.Status(), r.Request.Method, r.Request.URL) + logrus.WithField("pkg", "gpa/manager").Infof("%v: %v %v", r.Status(), r.Request.Method, r.Request.URL) } return nil @@ -359,7 +361,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Publish a TLS issue event if a TLS issue is encountered. bridge.tasks.Once(func(ctx context.Context) { async.RangeContext(ctx, tlsReporter.GetTLSIssueCh(), func(struct{}) { - logrus.Warn("TLS issue encountered") + logPkg.Warn("TLS issue encountered") bridge.publish(events.TLSIssue{}) }) }) @@ -367,7 +369,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Publish a raise event if the focus service is called. bridge.tasks.Once(func(ctx context.Context) { async.RangeContext(ctx, bridge.focusService.GetRaiseCh(), func(struct{}) { - logrus.Info("Focus service requested raise") + logPkg.Info("Focus service requested raise") bridge.publish(events.Raise{}) }) }) @@ -375,7 +377,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Handle any IMAP events that are forwarded to the bridge from gluon. bridge.tasks.Once(func(ctx context.Context) { async.RangeContext(ctx, bridge.imapEventCh, func(event imapEvents.Event) { - logrus.WithField("event", fmt.Sprintf("%T", event)).Debug("Received IMAP event") + logPkg.WithField("event", fmt.Sprintf("%T", event)).Debug("Received IMAP event") bridge.handleIMAPEvent(event) }) }) @@ -383,7 +385,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Attempt to load users from the vault when triggered. bridge.goLoad = bridge.tasks.Trigger(func(ctx context.Context) { if err := bridge.loadUsers(ctx); err != nil { - logrus.WithError(err).Error("Failed to load users") + logPkg.WithError(err).Error("Failed to load users") if netErr := new(proton.NetError); !errors.As(err, &netErr) { sentry.ReportError(bridge.reporter, "Failed to load users", err) } @@ -396,7 +398,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Check for updates when triggered. bridge.goUpdate = bridge.tasks.PeriodicOrTrigger(constants.UpdateCheckInterval, 0, func(ctx context.Context) { - logrus.Info("Checking for updates") + logPkg.Info("Checking for updates") version, err := bridge.updater.GetVersionInfo(ctx, bridge.api, bridge.vault.GetUpdateChannel()) if err != nil { @@ -434,7 +436,7 @@ func (bridge *Bridge) GetErrors() []error { } func (bridge *Bridge) Close(ctx context.Context) { - logrus.Info("Closing bridge") + logPkg.Info("Closing bridge") // Stop heart beat before closing users. bridge.heartbeat.stop() @@ -448,7 +450,7 @@ func (bridge *Bridge) Close(ctx context.Context) { // Close the servers if err := bridge.serverManager.CloseServers(ctx); err != nil { - logrus.WithError(err).Error("Failed to close servers") + logPkg.WithError(err).Error("Failed to close servers") } bridge.syncService.Close() @@ -474,12 +476,12 @@ func (bridge *Bridge) publish(event events.Event) { bridge.watchersLock.RLock() defer bridge.watchersLock.RUnlock() - logrus.WithField("event", event).Debug("Publishing event") + logPkg.WithField("event", event).Debug("Publishing event") for _, watcher := range bridge.watchers { if watcher.IsWatching(event) { if ok := watcher.Send(event); !ok { - logrus.WithField("event", event).Warn("Failed to send event to watcher") + logPkg.WithField("event", event).Warn("Failed to send event to watcher") } } } @@ -512,13 +514,13 @@ func (bridge *Bridge) remWatcher(watcher *watcher.Watcher[events.Event]) { } func (bridge *Bridge) onStatusUp(_ context.Context) { - logrus.Info("Handling API status up") + logPkg.Info("Handling API status up") bridge.goLoad() } func (bridge *Bridge) onStatusDown(ctx context.Context) { - logrus.Info("Handling API status down") + logPkg.Info("Handling API status down") for backoff := time.Second; ; backoff = min(backoff*2, 30*time.Second) { select { @@ -526,10 +528,10 @@ func (bridge *Bridge) onStatusDown(ctx context.Context) { return case <-time.After(backoff): - logrus.Info("Pinging API") + logPkg.Info("Pinging API") if err := bridge.api.Ping(ctx); err != nil { - logrus.WithError(err).Warn("Ping failed, API is still unreachable") + logPkg.WithError(err).Warn("Ping failed, API is still unreachable") } else { return } diff --git a/internal/bridge/configure.go b/internal/bridge/configure.go index 4d6c8f5a..3f1873b4 100644 --- a/internal/bridge/configure.go +++ b/internal/bridge/configure.go @@ -34,7 +34,7 @@ import ( // ConfigureAppleMail configures Apple Mail for the given userID and address. // If configuring Apple Mail for Catalina or newer, it ensures Bridge is using SSL. func (bridge *Bridge) ConfigureAppleMail(ctx context.Context, userID, address string) error { - logrus.WithFields(logrus.Fields{ + logPkg.WithFields(logrus.Fields{ "userID": userID, "address": logging.Sensitive(address), }).Info("Configuring Apple Mail") diff --git a/internal/bridge/debug.go b/internal/bridge/debug.go index e6d68cd1..43e09fba 100644 --- a/internal/bridge/debug.go +++ b/internal/bridge/debug.go @@ -65,7 +65,11 @@ func (bridge *Bridge) CheckClientState(ctx context.Context, checkFlags bool, pro if progressCB != nil { progressCB(fmt.Sprintf("Checking state for user %v", usr.Name())) } - log := logrus.WithField("user", usr.Name()).WithField("diag", "state-check") + log := logrus.WithFields(logrus.Fields{ + "pkg": "bridge/debug", + "user": usr.Name(), + "diag": "state-check", + }) log.Debug("Retrieving all server metadata") meta, err := usr.GetDiagnosticMetadata(ctx) if err != nil { @@ -280,7 +284,7 @@ func clientGetMessageIDs(client *goimapclient.Client, mailbox string) (map[strin internalID, ok := header.GetChecked("X-Pm-Internal-Id") if !ok { - logrus.Errorf("Message %v does not have internal id", internalID) + logrus.WithField("pkg", "bridge/debug").Errorf("Message %v does not have internal id", internalID) continue } diff --git a/internal/bridge/heartbeat.go b/internal/bridge/heartbeat.go index 70cab80f..9abf1b66 100644 --- a/internal/bridge/heartbeat.go +++ b/internal/bridge/heartbeat.go @@ -97,7 +97,7 @@ func (h *heartBeatState) start() { h.taskStarted = true h.task.PeriodicOrTrigger(h.taskInterval, 0, func(ctx context.Context) { - logrus.Debug("Checking for heartbeat") + logrus.WithField("pkg", "bridge/heartbeat").Debug("Checking for heartbeat") h.TrySending(ctx) }) @@ -135,7 +135,7 @@ func (bridge *Bridge) SendHeartbeat(ctx context.Context, heartbeat *telemetry.He if err := bridge.reporter.ReportMessageWithContext("Cannot parse heartbeat data.", reporter.Context{ "error": err, }); err != nil { - logrus.WithError(err).Error("Failed to parse heartbeat data.") + logrus.WithField("pkg", "bridge/heartbeat").WithError(err).Error("Failed to parse heartbeat data.") } return false } diff --git a/internal/bridge/imap.go b/internal/bridge/imap.go index c0734190..58b93d3c 100644 --- a/internal/bridge/imap.go +++ b/internal/bridge/imap.go @@ -35,10 +35,12 @@ func (bridge *Bridge) restartIMAP(ctx context.Context) error { } func (bridge *Bridge) handleIMAPEvent(event imapEvents.Event) { + log := logrus.WithField("pkg", "bridge/event/imap") + switch event := event.(type) { case imapEvents.UserAdded: for labelID, count := range event.Counts { - logrus.WithFields(logrus.Fields{ + log.WithFields(logrus.Fields{ "gluonID": event.UserID, "labelID": labelID, "count": count, @@ -46,7 +48,7 @@ func (bridge *Bridge) handleIMAPEvent(event imapEvents.Event) { } case imapEvents.IMAPID: - logrus.WithFields(logrus.Fields{ + log.WithFields(logrus.Fields{ "sessionID": event.SessionID, "name": event.IMAPID.Name, "version": event.IMAPID.Version, @@ -57,7 +59,7 @@ func (bridge *Bridge) handleIMAPEvent(event imapEvents.Event) { } case imapEvents.LoginFailed: - logrus.WithFields(logrus.Fields{ + log.WithFields(logrus.Fields{ "sessionID": event.SessionID, "username": event.Username, "pkg": "imap", diff --git a/internal/bridge/settings.go b/internal/bridge/settings.go index 0ac22fcb..1cfee6e0 100644 --- a/internal/bridge/settings.go +++ b/internal/bridge/settings.go @@ -27,7 +27,6 @@ import ( "github.com/ProtonMail/proton-bridge/v3/internal/services/userevents" "github.com/ProtonMail/proton-bridge/v3/internal/updater" "github.com/ProtonMail/proton-bridge/v3/internal/vault" - "github.com/sirupsen/logrus" ) func (bridge *Bridge) GetKeychainApp() (string, error) { @@ -134,7 +133,7 @@ func (bridge *Bridge) SetGluonDir(ctx context.Context, newGluonDir string) error bridge.usersLock.RLock() defer func() { - logrus.Info("Restarting user event loops") + logPkg.Info("Restarting user event loops") for _, u := range bridge.users { u.ResumeEventLoop() } @@ -149,20 +148,20 @@ func (bridge *Bridge) SetGluonDir(ctx context.Context, newGluonDir string) error waiters := make([]waiter, 0, len(bridge.users)) - logrus.Info("Pausing user event loops for gluon dir change") + logPkg.Info("Pausing user event loops for gluon dir change") for id, u := range bridge.users { waiters = append(waiters, waiter{w: u.PauseEventLoopWithWaiter(), id: id}) } - logrus.Info("Waiting on user event loop completion") + logPkg.Info("Waiting on user event loop completion") for _, waiter := range waiters { if err := waiter.w.WaitPollFinished(ctx); err != nil { - logrus.WithError(err).Errorf("Failed to wait on event loop pause for user %v", waiter.id) + logPkg.WithError(err).Errorf("Failed to wait on event loop pause for user %v", waiter.id) return fmt.Errorf("failed on event loop pause: %w", err) } } - logrus.Info("Changing gluon directory") + logPkg.Info("Changing gluon directory") return bridge.serverManager.SetGluonDir(ctx, newGluonDir) } @@ -330,13 +329,13 @@ func (bridge *Bridge) FactoryReset(ctx context.Context) { // Wipe the vault. gluonCacheDir, err := bridge.locator.ProvideGluonCachePath() if err != nil { - logrus.WithError(err).Error("Failed to provide gluon dir") + logPkg.WithError(err).Error("Failed to provide gluon dir") } else if err := bridge.vault.Reset(gluonCacheDir); err != nil { - logrus.WithError(err).Error("Failed to reset vault") + logPkg.WithError(err).Error("Failed to reset vault") } // Lastly, delete all files except the vault. if err := bridge.locator.Clear(bridge.vault.Path()); err != nil { - logrus.WithError(err).Error("Failed to clear data paths") + logPkg.WithError(err).Error("Failed to clear data paths") } } diff --git a/internal/bridge/user.go b/internal/bridge/user.go index 9d4413ec..8a5a4258 100644 --- a/internal/bridge/user.go +++ b/internal/bridge/user.go @@ -38,6 +38,8 @@ import ( "github.com/sirupsen/logrus" ) +var logUser = logrus.WithField("pkg", "bridge/user") //nolint:gochecknoglobals + type UserState int const ( @@ -122,7 +124,7 @@ func (bridge *Bridge) QueryUserInfo(query string) (UserInfo, error) { // LoginAuth begins the login process. It returns an authorized client that might need 2FA. func (bridge *Bridge) LoginAuth(ctx context.Context, username string, password []byte) (*proton.Client, proton.Auth, error) { - logrus.WithField("username", logging.Sensitive(username)).Info("Authorizing user for login") + logUser.WithField("username", logging.Sensitive(username)).Info("Authorizing user for login") if username == "crash@bandicoot" { panic("Your wish is my command.. I crash!") @@ -134,10 +136,10 @@ func (bridge *Bridge) LoginAuth(ctx context.Context, username string, password [ } if ok := safe.RLockRet(func() bool { return mapHas(bridge.users, auth.UserID) }, bridge.usersLock); ok { - logrus.WithField("userID", auth.UserID).Warn("User already logged in") + logUser.WithField("userID", auth.UserID).Warn("User already logged in") if err := client.AuthDelete(ctx); err != nil { - logrus.WithError(err).Warn("Failed to delete auth") + logUser.WithError(err).Warn("Failed to delete auth") } return nil, proton.Auth{}, ErrUserAlreadyLoggedIn @@ -153,7 +155,7 @@ func (bridge *Bridge) LoginUser( auth proton.Auth, keyPass []byte, ) (string, error) { - logrus.WithField("userID", auth.UserID).Info("Logging in authorized user") + logUser.WithField("userID", auth.UserID).Info("Logging in authorized user") userID, err := try.CatchVal( func() (string, error) { @@ -165,7 +167,7 @@ func (bridge *Bridge) LoginUser( // Failure to unlock will allow retries, so we do not delete auth. if !errors.Is(err, ErrFailedToUnlock) { if deleteErr := client.AuthDelete(ctx); deleteErr != nil { - logrus.WithError(deleteErr).Error("Failed to delete auth") + logUser.WithError(deleteErr).Error("Failed to delete auth") } } return "", fmt.Errorf("failed to login user: %w", err) @@ -188,7 +190,7 @@ func (bridge *Bridge) LoginFull( getTOTP func() (string, error), getKeyPass func() ([]byte, error), ) (string, error) { - logrus.WithField("username", logging.Sensitive(username)).Info("Performing full user login") + logUser.WithField("username", logging.Sensitive(username)).Info("Performing full user login") client, auth, err := bridge.LoginAuth(ctx, username, password) if err != nil { @@ -196,7 +198,7 @@ func (bridge *Bridge) LoginFull( } if auth.TwoFA.Enabled&proton.HasTOTP != 0 { - logrus.WithField("userID", auth.UserID).Info("Requesting TOTP") + logUser.WithField("userID", auth.UserID).Info("Requesting TOTP") totp, err := getTOTP() if err != nil { @@ -211,7 +213,7 @@ func (bridge *Bridge) LoginFull( var keyPass []byte if auth.PasswordMode == proton.TwoPasswordMode { - logrus.WithField("userID", auth.UserID).Info("Requesting mailbox password") + logUser.WithField("userID", auth.UserID).Info("Requesting mailbox password") userKeyPass, err := getKeyPass() if err != nil { @@ -226,7 +228,7 @@ func (bridge *Bridge) LoginFull( userID, err := bridge.LoginUser(ctx, client, auth, keyPass) if err != nil { if deleteErr := client.AuthDelete(ctx); deleteErr != nil { - logrus.WithError(err).Error("Failed to delete auth") + logUser.WithError(err).Error("Failed to delete auth") } return "", err @@ -237,7 +239,7 @@ func (bridge *Bridge) LoginFull( // LogoutUser logs out the given user. func (bridge *Bridge) LogoutUser(ctx context.Context, userID string) error { - logrus.WithField("userID", userID).Info("Logging out user") + logUser.WithField("userID", userID).Info("Logging out user") return safe.LockRet(func() error { user, ok := bridge.users[userID] @@ -257,7 +259,7 @@ func (bridge *Bridge) LogoutUser(ctx context.Context, userID string) error { // DeleteUser deletes the given user. func (bridge *Bridge) DeleteUser(ctx context.Context, userID string) error { - logrus.WithField("userID", userID).Info("Deleting user") + logUser.WithField("userID", userID).Info("Deleting user") syncConfigDir, err := bridge.locator.ProvideIMAPSyncConfigPath() if err != nil { @@ -278,7 +280,7 @@ func (bridge *Bridge) DeleteUser(ctx context.Context, userID string) error { } if err := bridge.vault.DeleteUser(userID); err != nil { - logrus.WithError(err).Error("Failed to delete vault user") + logUser.WithError(err).Error("Failed to delete vault user") } bridge.publish(events.UserDeleted{ @@ -291,7 +293,7 @@ func (bridge *Bridge) DeleteUser(ctx context.Context, userID string) error { // SetAddressMode sets the address mode for the given user. func (bridge *Bridge) SetAddressMode(ctx context.Context, userID string, mode vault.AddressMode) error { - logrus.WithField("userID", userID).WithField("mode", mode).Info("Setting address mode") + logUser.WithField("userID", userID).WithField("mode", mode).Info("Setting address mode") return safe.RLockRet(func() error { user, ok := bridge.users[userID] @@ -327,7 +329,7 @@ func (bridge *Bridge) SetAddressMode(ctx context.Context, userID string, mode va // SendBadEventUserFeedback passes the feedback to the given user. func (bridge *Bridge) SendBadEventUserFeedback(_ context.Context, userID string, doResync bool) error { - logrus.WithField("userID", userID).WithField("doResync", doResync).Info("Passing bad event feedback to user") + logUser.WithField("userID", userID).WithField("doResync", doResync).Info("Passing bad event feedback to user") return safe.RLockRet(func() error { ctx := context.Background() @@ -338,7 +340,7 @@ func (bridge *Bridge) SendBadEventUserFeedback(_ context.Context, userID string, "Failed to handle event: feedback failed: no such user", reporter.Context{"user_id": userID}, ); rerr != nil { - logrus.WithError(rerr).Error("Failed to report feedback failure") + logUser.WithError(rerr).Error("Failed to report feedback failure") } return ErrNoSuchUser @@ -349,7 +351,7 @@ func (bridge *Bridge) SendBadEventUserFeedback(_ context.Context, userID string, "Failed to handle event: feedback resync", reporter.Context{"user_id": userID}, ); rerr != nil { - logrus.WithError(rerr).Error("Failed to report feedback failure") + logUser.WithError(rerr).Error("Failed to report feedback failure") } return user.BadEventFeedbackResync(ctx) @@ -359,7 +361,7 @@ func (bridge *Bridge) SendBadEventUserFeedback(_ context.Context, userID string, "Failed to handle event: feedback logout", reporter.Context{"user_id": userID}, ); rerr != nil { - logrus.WithError(rerr).Error("Failed to report feedback failure") + logUser.WithError(rerr).Error("Failed to report feedback failure") } bridge.logoutUser(ctx, user, true, false, false) @@ -403,11 +405,11 @@ func (bridge *Bridge) loginUser(ctx context.Context, client *proton.Client, auth // loadUsers tries to load each user in the vault that isn't already loaded. func (bridge *Bridge) loadUsers(ctx context.Context) error { - logrus.WithField("count", len(bridge.vault.GetUserIDs())).Info("Loading users") - defer logrus.Info("Finished loading users") + logUser.WithField("count", len(bridge.vault.GetUserIDs())).Info("Loading users") + defer logUser.Info("Finished loading users") return bridge.vault.ForUser(runtime.NumCPU(), func(user *vault.User) error { - log := logrus.WithField("userID", user.UserID()) + log := logUser.WithField("userID", user.UserID()) if user.AuthUID() == "" { log.Info("User is not connected (skipping)") @@ -451,7 +453,7 @@ func (bridge *Bridge) loadUser(ctx context.Context, user *vault.User) error { if apiErr := new(proton.APIError); errors.As(err, &apiErr) && (apiErr.Code == proton.AuthRefreshTokenInvalid) { // The session cannot be refreshed, we sign out the user by clearing his auth secrets. if err := user.Clear(); err != nil { - logrus.WithError(err).Warn("Failed to clear user secrets") + logUser.WithError(err).Warn("Failed to clear user secrets") } } @@ -496,24 +498,24 @@ func (bridge *Bridge) addUser( if err := bridge.addUserWithVault(ctx, client, apiUser, vaultUser, isNew); err != nil { if _, ok := err.(*resty.ResponseError); ok || isLogin { - logrus.WithError(err).Error("Failed to add user, clearing its secrets from vault") + logUser.WithError(err).Error("Failed to add user, clearing its secrets from vault") if err := vaultUser.Clear(); err != nil { - logrus.WithError(err).Error("Failed to clear user secrets") + logUser.WithError(err).Error("Failed to clear user secrets") } } else { - logrus.WithError(err).Error("Failed to add user") + logUser.WithError(err).Error("Failed to add user") } if err := vaultUser.Close(); err != nil { - logrus.WithError(err).Error("Failed to close vault user") + logUser.WithError(err).Error("Failed to close vault user") } if isNew { - logrus.Warn("Deleting newly added vault user") + logUser.Warn("Deleting newly added vault user") if err := bridge.vault.DeleteUser(apiUser.ID); err != nil { - logrus.WithError(err).Error("Failed to delete vault user") + logUser.WithError(err).Error("Failed to delete vault user") } } @@ -567,7 +569,7 @@ func (bridge *Bridge) addUserWithVault( // For example, if the user's addresses change, we need to update them in gluon. bridge.tasks.Once(func(ctx context.Context) { async.RangeContext(ctx, user.GetEventCh(), func(event events.Event) { - logrus.WithFields(logrus.Fields{ + logUser.WithFields(logrus.Fields{ "userID": apiUser.ID, "event": event, }).Debug("Received user event") @@ -618,14 +620,14 @@ func (bridge *Bridge) logoutUser(ctx context.Context, user *user.User, withAPI, user.SendConfigStatusAbort(ctx, withTelemetry) } - logrus.WithFields(logrus.Fields{ + logUser.WithFields(logrus.Fields{ "userID": user.ID(), "withAPI": withAPI, "withData": withData, }).Debug("Logging out user") if err := user.Logout(ctx, withAPI); err != nil { - logrus.WithError(err).Error("Failed to logout user") + logUser.WithError(err).Error("Failed to logout user") } bridge.heartbeat.SetNbAccount(len(bridge.users)) diff --git a/internal/bridge/user_events.go b/internal/bridge/user_events.go index c0527f6e..48417c17 100644 --- a/internal/bridge/user_events.go +++ b/internal/bridge/user_events.go @@ -58,7 +58,7 @@ func (bridge *Bridge) handleUserBadEvent(ctx context.Context, user *user.User, e "error": event.Error, "error_type": internal.ErrCauseType(event.Error), }); rerr != nil { - logrus.WithError(rerr).Error("Failed to report failed event handling") + logrus.WithField("pkg", "bridge/event").WithError(rerr).Error("Failed to report failed event handling") } user.OnBadEvent(ctx) @@ -70,6 +70,6 @@ func (bridge *Bridge) handleUncategorizedErrorEvent(event events.UncategorizedEv "error_type": internal.ErrCauseType(event.Error), "error": event.Error, }); rerr != nil { - logrus.WithError(rerr).Error("Failed to report failed event handling") + logrus.WithField("pkg", "bridge/event").WithError(rerr).Error("Failed to report failed event handling") } } diff --git a/internal/logging/imap_logger.go b/internal/logging/imap_logger.go index d906f0b6..9ae614b8 100644 --- a/internal/logging/imap_logger.go +++ b/internal/logging/imap_logger.go @@ -27,5 +27,5 @@ func NewIMAPLogger() *IMAPLogger { } func (l *IMAPLogger) Write(p []byte) (n int, err error) { - return logrus.WithField("pkg", "IMAP").WriterLevel(logrus.TraceLevel).Write(p) + return logrus.WithField("pkg", "log/IMAP").WriterLevel(logrus.TraceLevel).Write(p) } diff --git a/internal/logging/smtp_logger.go b/internal/logging/smtp_logger.go index 86073689..b88475c9 100644 --- a/internal/logging/smtp_logger.go +++ b/internal/logging/smtp_logger.go @@ -27,7 +27,7 @@ type SMTPErrorLogger struct { } func NewSMTPLogger() *SMTPErrorLogger { - return &SMTPErrorLogger{l: logrus.WithField("pkg", "SMTP")} + return &SMTPErrorLogger{l: logrus.WithField("pkg", "log/SMTP")} } func (s *SMTPErrorLogger) Printf(format string, args ...interface{}) { @@ -44,7 +44,7 @@ type SMTPDebugLogger struct { } func NewSMTPDebugLogger() *SMTPDebugLogger { - return &SMTPDebugLogger{l: logrus.WithField("pkg", "SMTP")} + return &SMTPDebugLogger{l: logrus.WithField("pkg", "log/SMTP")} } func (l *SMTPDebugLogger) Write(p []byte) (n int, err error) { diff --git a/internal/services/imapsmtpserver/imap.go b/internal/services/imapsmtpserver/imap.go index 07d7e779..d1d8d9c4 100644 --- a/internal/services/imapsmtpserver/imap.go +++ b/internal/services/imapsmtpserver/imap.go @@ -39,6 +39,8 @@ import ( "github.com/sirupsen/logrus" ) +var logIMAP = logrus.WithField("pkg", "server/imap") //nolint:gochecknoglobals + type IMAPSettingsProvider interface { TLSConfig() *tls.Config LogClient() bool @@ -79,7 +81,7 @@ func newIMAPServer( gluonCacheDir = ApplyGluonCachePathSuffix(gluonCacheDir) gluonConfigDir = ApplyGluonConfigPathSuffix(gluonConfigDir) - logrus.WithFields(logrus.Fields{ + logIMAP.WithFields(logrus.Fields{ "gluonStore": gluonCacheDir, "gluonDB": gluonConfigDir, "version": version, @@ -88,10 +90,9 @@ func newIMAPServer( }).Info("Creating IMAP server") if logClient || logServer { - log := logrus.WithField("protocol", "IMAP") - log.Warning("================================================") - log.Warning("THIS LOG WILL CONTAIN **DECRYPTED** MESSAGE DATA") - log.Warning("================================================") + logIMAP.Warning("================================================") + logIMAP.Warning("THIS LOG WILL CONTAIN **DECRYPTED** MESSAGE DATA") + logIMAP.Warning("================================================") } var imapClientLog io.Writer @@ -143,7 +144,7 @@ func newIMAPServer( tasks.Once(func(ctx context.Context) { async.RangeContext(ctx, imapServer.GetErrorCh(), func(err error) { - logrus.WithError(err).Error("IMAP server error") + logIMAP.WithError(err).Error("IMAP server error") }) }) @@ -176,7 +177,7 @@ func (*storeBuilder) Delete(path, userID string) error { } func moveGluonCacheDir(settings IMAPSettingsProvider, oldGluonDir, newGluonDir string) error { - logrus.Infof("gluon cache moving from %s to %s", oldGluonDir, newGluonDir) + logIMAP.WithField("pkg", "service/imap").Infof("gluon cache moving from %s to %s", oldGluonDir, newGluonDir) oldCacheDir := ApplyGluonCachePathSuffix(oldGluonDir) if err := files.CopyDir(oldCacheDir, ApplyGluonCachePathSuffix(newGluonDir)); err != nil { return fmt.Errorf("failed to copy gluon dir: %w", err) @@ -187,7 +188,7 @@ func moveGluonCacheDir(settings IMAPSettingsProvider, oldGluonDir, newGluonDir s } if err := os.RemoveAll(oldCacheDir); err != nil { - logrus.WithError(err).Error("failed to remove old gluon cache dir") + logIMAP.WithError(err).Error("failed to remove old gluon cache dir") } return nil diff --git a/internal/services/imapsmtpserver/service.go b/internal/services/imapsmtpserver/service.go index ce71ef7d..33581f03 100644 --- a/internal/services/imapsmtpserver/service.go +++ b/internal/services/imapsmtpserver/service.go @@ -190,16 +190,16 @@ func (sm *Service) run(ctx context.Context, subscription events.Subscription) { case evt := <-eventSub.GetChannel(): switch evt.(type) { case events.ConnStatusDown: - logrus.Info("Server Manager, network down stopping listeners") + sm.log.Info("Server Manager, network down stopping listeners") if err := sm.closeSMTPServer(ctx); err != nil { - logrus.WithError(err).Error("Failed to close SMTP server") + sm.log.WithError(err).Error("Failed to close SMTP server") } if err := sm.stopIMAPListener(ctx); err != nil { - logrus.WithError(err) + sm.log.WithError(err) } case events.ConnStatusUp: - logrus.Info("Server Manager, network up starting listeners") + sm.log.Info("Server Manager, network up starting listeners") sm.handleLoadedUserCountChange(ctx) } @@ -241,12 +241,12 @@ func (sm *Service) run(ctx context.Context, subscription events.Subscription) { request.Reply(ctx, nil, err) case *smRequestAddSMTPAccount: - logrus.WithField("user", r.account.UserID()).Debug("Adding SMTP Account") + sm.log.WithField("user", r.account.UserID()).Debug("Adding SMTP Account") sm.smtpAccounts.AddAccount(r.account) request.Reply(ctx, nil, nil) case *smRequestRemoveSMTPAccount: - logrus.WithField("user", r.account.UserID()).Debug("Removing SMTP Account") + sm.log.WithField("user", r.account.UserID()).Debug("Removing SMTP Account") sm.smtpAccounts.RemoveAccount(r.account) request.Reply(ctx, nil, nil) } @@ -255,29 +255,29 @@ func (sm *Service) run(ctx context.Context, subscription events.Subscription) { } func (sm *Service) handleLoadedUserCountChange(ctx context.Context) { - logrus.Infof("Validating Listener State %v", sm.loadedUserCount) + sm.log.Infof("Validating Listener State %v", sm.loadedUserCount) if sm.shouldStartServers() { if sm.imapListener == nil { if err := sm.serveIMAP(ctx); err != nil { - logrus.WithError(err).Error("Failed to start IMAP server") + sm.log.WithError(err).Error("Failed to start IMAP server") } } if sm.smtpListener == nil { if err := sm.restartSMTP(ctx); err != nil { - logrus.WithError(err).Error("Failed to start SMTP server") + sm.log.WithError(err).Error("Failed to start SMTP server") } } } else { if sm.imapListener != nil { if err := sm.stopIMAPListener(ctx); err != nil { - logrus.WithError(err).Error("Failed to stop IMAP server") + sm.log.WithError(err).Error("Failed to stop IMAP server") } } if sm.smtpListener != nil { if err := sm.closeSMTPServer(ctx); err != nil { - logrus.WithError(err).Error("Failed to stop SMTP server") + sm.log.WithError(err).Error("Failed to stop SMTP server") } } } @@ -286,12 +286,12 @@ func (sm *Service) handleLoadedUserCountChange(ctx context.Context) { func (sm *Service) handleClose(ctx context.Context) { // Close the IMAP server. if err := sm.closeIMAPServer(ctx); err != nil { - logrus.WithError(err).Error("Failed to close IMAP server") + sm.log.WithError(err).Error("Failed to close IMAP server") } // Close the SMTP server. if err := sm.closeSMTPServer(ctx); err != nil { - logrus.WithError(err).Error("Failed to close SMTP server") + sm.log.WithError(err).Error("Failed to close SMTP server") } // Cancel and wait needs to be called here since the SMTP server does not have a way to exit @@ -325,7 +325,7 @@ func (sm *Service) handleAddIMAPUserImpl(ctx context.Context, return fmt.Errorf("no imap server instance running") } - log := logrus.WithFields(logrus.Fields{ + log := sm.log.WithFields(logrus.Fields{ "addrID": addrID, }) log.Info("Adding user to imap server") @@ -341,7 +341,7 @@ func (sm *Service) handleAddIMAPUserImpl(ctx context.Context, if isNew { // If the DB was newly created, clear the sync status; gluon's DB was not found. - logrus.Warn("IMAP user DB was newly created, clearing sync status") + sm.log.Warn("IMAP user DB was newly created, clearing sync status") // Remove the user from IMAP so we can clear the sync status. if err := sm.imapServer.RemoveUser(ctx, gluonID, false); err != nil { @@ -415,7 +415,7 @@ func (sm *Service) handleRemoveIMAPUser(ctx context.Context, withData bool, idPr return fmt.Errorf("no imap server instance running") } - logrus.WithFields(logrus.Fields{ + sm.log.WithFields(logrus.Fields{ "withData": withData, "addresses": addrIDs, }).Debug("Removing IMAP user") @@ -423,7 +423,7 @@ func (sm *Service) handleRemoveIMAPUser(ctx context.Context, withData bool, idPr for _, addrID := range addrIDs { gluonID, ok := idProvider.GetGluonID(addrID) if !ok { - logrus.Warnf("Could not find Gluon ID for addrID %v", addrID) + sm.log.Warnf("Could not find Gluon ID for addrID %v", addrID) continue } @@ -480,7 +480,7 @@ func (sm *Service) closeSMTPServer(ctx context.Context) error { // even after the server has been closed. So we close the listener ourselves to unblock it. if sm.smtpListener != nil { - logrus.Info("Closing SMTP Listener") + sm.log.Info("Closing SMTP Listener") if err := sm.smtpListener.Close(); err != nil { return fmt.Errorf("failed to close SMTP listener: %w", err) } @@ -489,9 +489,9 @@ func (sm *Service) closeSMTPServer(ctx context.Context) error { } if sm.smtpServer != nil { - logrus.Info("Closing SMTP server") + sm.log.Info("Closing SMTP server") if err := sm.smtpServer.Close(); err != nil { - logrus.WithError(err).Debug("Failed to close SMTP server (expected -- we close the listener ourselves)") + sm.log.WithError(err).Debug("Failed to close SMTP server (expected -- we close the listener ourselves)") } sm.smtpServer = nil @@ -504,7 +504,7 @@ func (sm *Service) closeSMTPServer(ctx context.Context) error { func (sm *Service) closeIMAPServer(ctx context.Context) error { if sm.imapListener != nil { - logrus.Info("Closing IMAP Listener") + sm.log.Info("Closing IMAP Listener") if err := sm.imapListener.Close(); err != nil { return fmt.Errorf("failed to close IMAP listener: %w", err) @@ -516,7 +516,7 @@ func (sm *Service) closeIMAPServer(ctx context.Context) error { } if sm.imapServer != nil { - logrus.Info("Closing IMAP server") + sm.log.Info("Closing IMAP server") if err := sm.imapServer.Close(ctx); err != nil { return fmt.Errorf("failed to close IMAP server: %w", err) } @@ -530,7 +530,7 @@ func (sm *Service) closeIMAPServer(ctx context.Context) error { } func (sm *Service) restartIMAP(ctx context.Context) error { - logrus.Info("Restarting IMAP server") + sm.log.Info("Restarting IMAP server") if sm.imapListener != nil { if err := sm.imapListener.Close(); err != nil { @@ -550,7 +550,7 @@ func (sm *Service) restartIMAP(ctx context.Context) error { } func (sm *Service) restartSMTP(ctx context.Context) error { - logrus.Info("Restarting SMTP server") + sm.log.Info("Restarting SMTP server") if err := sm.closeSMTPServer(ctx); err != nil { return fmt.Errorf("failed to close SMTP: %w", err) @@ -569,7 +569,7 @@ func (sm *Service) restartSMTP(ctx context.Context) error { func (sm *Service) serveSMTP(ctx context.Context) error { port, err := func() (int, error) { - logrus.WithFields(logrus.Fields{ + sm.log.WithFields(logrus.Fields{ "port": sm.smtpSettings.Port(), "ssl": sm.smtpSettings.UseSSL(), }).Info("Starting SMTP server") @@ -583,7 +583,7 @@ func (sm *Service) serveSMTP(ctx context.Context) error { sm.tasks.Once(func(context.Context) { if err := sm.smtpServer.Serve(smtpListener); err != nil { - logrus.WithError(err).Info("SMTP server stopped") + sm.log.WithError(err).Info("SMTP server stopped") } }) @@ -615,7 +615,7 @@ func (sm *Service) serveIMAP(ctx context.Context) error { return 0, fmt.Errorf("no IMAP server instance running") } - logrus.WithFields(logrus.Fields{ + sm.log.WithFields(logrus.Fields{ "port": sm.imapSettings.Port(), "ssl": sm.imapSettings.UseSSL(), }).Info("Starting IMAP server") @@ -654,7 +654,7 @@ func (sm *Service) serveIMAP(ctx context.Context) error { } func (sm *Service) stopIMAPListener(ctx context.Context) error { - logrus.Info("Stopping IMAP listener") + sm.log.Info("Stopping IMAP listener") if sm.imapListener != nil { if err := sm.imapListener.Close(); err != nil { return err @@ -682,7 +682,7 @@ func (sm *Service) handleSetGluonDir(ctx context.Context, newGluonDir string) er sm.loadedUserCount = 0 if err := moveGluonCacheDir(sm.imapSettings, currentGluonDir, newGluonDir); err != nil { - logrus.WithError(err).Error("failed to move GluonCacheDir") + sm.log.WithError(err).Error("failed to move GluonCacheDir") if err := sm.imapSettings.SetCacheDirectory(currentGluonDir); err != nil { return fmt.Errorf("failed to revert GluonCacheDir: %w", err) diff --git a/internal/services/imapsmtpserver/smtp.go b/internal/services/imapsmtpserver/smtp.go index 20824386..dfdaff8a 100644 --- a/internal/services/imapsmtpserver/smtp.go +++ b/internal/services/imapsmtpserver/smtp.go @@ -29,6 +29,8 @@ import ( "github.com/sirupsen/logrus" ) +var logSMTP = logrus.WithField("pkg", "server/smtp") //nolint:gochecknoglobals + type SMTPSettingsProvider interface { TLSConfig() *tls.Config Log() bool @@ -39,7 +41,7 @@ type SMTPSettingsProvider interface { } func newSMTPServer(accounts *smtpservice.Accounts, settings SMTPSettingsProvider) *smtp.Server { - logrus.WithField("logSMTP", settings.Log()).Info("Creating SMTP server") + logSMTP.WithField("logSMTP", settings.Log()).Info("Creating SMTP server") smtpServer := smtp.NewServer(smtpservice.NewBackend(accounts, settings.Identifier())) @@ -57,10 +59,9 @@ func newSMTPServer(accounts *smtpservice.Accounts, settings SMTPSettingsProvider }) if settings.Log() { - log := logrus.WithField("protocol", "SMTP") - log.Warning("================================================") - log.Warning("THIS LOG WILL CONTAIN **DECRYPTED** MESSAGE DATA") - log.Warning("================================================") + logSMTP.Warning("================================================") + logSMTP.Warning("THIS LOG WILL CONTAIN **DECRYPTED** MESSAGE DATA") + logSMTP.Warning("================================================") smtpServer.Debug = logging.NewSMTPDebugLogger() } diff --git a/internal/user/user.go b/internal/user/user.go index 171d6dd3..f65548a7 100644 --- a/internal/user/user.go +++ b/internal/user/user.go @@ -294,7 +294,7 @@ func newImpl( // Log all requests made by the user. user.client.AddPostRequestHook(func(_ *resty.Client, r *resty.Response) error { - user.log.Infof("%v: %v %v", r.Status(), r.Request.Method, r.Request.URL) + user.log.WithField("pkg", "gpa/client").Infof("%v: %v %v", r.Status(), r.Request.Method, r.Request.URL) return nil })