diff --git a/go.mod b/go.mod index a9d2b8a2..09e2cecf 100644 --- a/go.mod +++ b/go.mod @@ -39,7 +39,7 @@ require ( github.com/stretchr/testify v1.8.0 github.com/urfave/cli/v2 v2.20.3 github.com/vmihailenco/msgpack/v5 v5.3.5 - gitlab.protontech.ch/go/liteapi v0.39.2 + gitlab.protontech.ch/go/liteapi v0.41.1-0.20221103233913-df73097358ad go.uber.org/goleak v1.2.0 golang.org/x/exp v0.0.0-20221023144134-a1e5550cf13e golang.org/x/net v0.1.0 diff --git a/go.sum b/go.sum index 94dd1260..bc4a08f4 100644 --- a/go.sum +++ b/go.sum @@ -403,8 +403,8 @@ github.com/xrash/smetrics v0.0.0-20201216005158-039620a65673/go.mod h1:N3UwUGtsr github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= github.com/zclconf/go-cty v1.11.0 h1:726SxLdi2SDnjY+BStqB9J1hNp4+2WlzyXLuimibIe0= github.com/zclconf/go-cty v1.11.0/go.mod h1:s9IfD1LK5ccNMSWCVFCE2rJfHiZgi7JijgeWIMfhLvA= -gitlab.protontech.ch/go/liteapi v0.39.2 h1:HWxuO6c9cnRAzpLaj2SrOD1jJEWVa4nAUH1TkVPA4t4= -gitlab.protontech.ch/go/liteapi v0.39.2/go.mod h1:IM7ADWjgIL2hXopzx0WNamizEuMgM2QZl7QH12FNflk= +gitlab.protontech.ch/go/liteapi v0.41.1-0.20221103233913-df73097358ad h1:TDEX2GTorFS7slKuLndtmHVLpMEtnk7pIBNk/va9IL8= +gitlab.protontech.ch/go/liteapi v0.41.1-0.20221103233913-df73097358ad/go.mod h1:IM7ADWjgIL2hXopzx0WNamizEuMgM2QZl7QH12FNflk= go.etcd.io/bbolt v1.3.2/go.mod h1:IbVyRI1SCnLcuJnV2u8VeU0CEYM7e686BmAb1XKL+uU= go.opencensus.io v0.21.0/go.mod h1:mSImk1erAIZhrmZN+AvHh14ztQfjbGwt4TtuofqLduU= go.opencensus.io v0.22.0/go.mod h1:+kGneAE2xo2IficOXnaByMWTGM9T73dGwxeWcUqIpI8= diff --git a/internal/bridge/bridge.go b/internal/bridge/bridge.go index 79f19a14..b415e8d9 100644 --- a/internal/bridge/bridge.go +++ b/internal/bridge/bridge.go @@ -269,6 +269,8 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // Handle connection up/down events. bridge.api.AddStatusObserver(func(status liteapi.Status) { + logrus.Info("API status changed: ", status) + switch { case status == liteapi.StatusUp: bridge.publish(events.ConnStatusUp{}) @@ -282,6 +284,7 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { // If any call returns a bad version code, we need to update. bridge.api.AddErrorHandler(liteapi.AppVersionBadCode, func() { + logrus.Warn("App version is bad") bridge.publish(events.UpdateForced{}) }) @@ -291,9 +294,19 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { return nil }) + // Log all manager API requests (client requests are logged separately). + bridge.api.AddPostRequestHook(func(_ *resty.Client, r *resty.Response) error { + if _, ok := liteapi.ClientIDFromContext(r.Request.Context()); !ok { + logrus.Infof("[MANAGER] %v: %v %v", r.Status(), r.Request.Method, r.Request.URL) + } + + return nil + }) + // 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") bridge.publish(events.TLSIssue{}) }) }) @@ -301,6 +314,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") bridge.publish(events.Raise{}) }) }) @@ -308,12 +322,15 @@ 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") bridge.handleIMAPEvent(event) }) }) // Attempt to lazy load users when triggered. bridge.goLoad = bridge.tasks.Trigger(func(ctx context.Context) { + logrus.Info("Loading users") + if err := bridge.loadUsers(ctx); err != nil { logrus.WithError(err).Error("Failed to load users") } else { @@ -323,7 +340,9 @@ func (bridge *Bridge) init(tlsReporter TLSReporter) error { defer bridge.goLoad() // Check for updates when triggered. - bridge.goUpdate = bridge.tasks.PeriodicOrTrigger(constants.UpdateCheckInterval, 0, func(ctx context.Context) { + bridge.goUpdate = bridge.tasks.PeriodicOrTrigger(constants.UpdateCheckInterval, 0, func(context.Context) { + logrus.Info("Checking for updates") + version, err := bridge.updater.GetVersionInfo(bridge.api, bridge.vault.GetUpdateChannel()) if err != nil { logrus.WithError(err).Error("Failed to get version info") @@ -353,6 +372,8 @@ func (bridge *Bridge) GetErrors() []error { } func (bridge *Bridge) Close(ctx context.Context) { + logrus.Info("Closing bridge") + // Close the IMAP server. if err := bridge.closeIMAP(ctx); err != nil { logrus.WithError(err).Error("Failed to close IMAP server") @@ -396,6 +417,8 @@ func (bridge *Bridge) publish(event events.Event) { bridge.watchersLock.RLock() defer bridge.watchersLock.RUnlock() + logrus.WithField("event", event).Debug("Publishing event") + for _, watcher := range bridge.watchers { if watcher.IsWatching(event) { if ok := watcher.Send(event); !ok { @@ -432,6 +455,8 @@ func (bridge *Bridge) remWatcher(watcher *watcher.Watcher[events.Event]) { } func (bridge *Bridge) onStatusUp(ctx context.Context) { + logrus.Info("Handling API status up") + safe.RLock(func() { for _, user := range bridge.users { user.OnStatusUp(ctx) @@ -442,6 +467,8 @@ func (bridge *Bridge) onStatusUp(ctx context.Context) { } func (bridge *Bridge) onStatusDown(ctx context.Context) { + logrus.Info("Handling API status down") + safe.RLock(func() { for _, user := range bridge.users { user.OnStatusDown(ctx) @@ -455,7 +482,7 @@ func (bridge *Bridge) onStatusDown(ctx context.Context) { case <-time.After(backoff): if err := bridge.api.Ping(ctx); err != nil { - logrus.WithError(err).Debug("Failed to ping API, will retry") + logrus.WithError(err).Warn("Failed to ping API, will retry") } else { return } diff --git a/internal/bridge/configure.go b/internal/bridge/configure.go index 020c709f..0ca8d113 100644 --- a/internal/bridge/configure.go +++ b/internal/bridge/configure.go @@ -22,14 +22,21 @@ import ( "github.com/ProtonMail/proton-bridge/v2/internal/clientconfig" "github.com/ProtonMail/proton-bridge/v2/internal/constants" + "github.com/ProtonMail/proton-bridge/v2/internal/logging" "github.com/ProtonMail/proton-bridge/v2/internal/safe" "github.com/ProtonMail/proton-bridge/v2/internal/useragent" "github.com/ProtonMail/proton-bridge/v2/internal/vault" + "github.com/sirupsen/logrus" ) // 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(userID, address string) error { + logrus.WithFields(logrus.Fields{ + "userID": userID, + "address": logging.Sensitive(address), + }).Info("Configuring Apple Mail") + return safe.RLockRet(func() error { user, ok := bridge.users[userID] if !ok { diff --git a/internal/bridge/imap.go b/internal/bridge/imap.go index 7a7e2183..1a75a98e 100644 --- a/internal/bridge/imap.go +++ b/internal/bridge/imap.go @@ -44,6 +44,8 @@ const ( ) func (bridge *Bridge) serveIMAP() error { + logrus.Info("Starting IMAP server") + imapListener, err := newListener(bridge.vault.GetIMAPPort(), bridge.vault.GetIMAPSSL(), bridge.tlsConfig) if err != nil { return fmt.Errorf("failed to create IMAP listener: %w", err) @@ -63,6 +65,8 @@ func (bridge *Bridge) serveIMAP() error { } func (bridge *Bridge) restartIMAP() error { + logrus.Info("Restarting IMAP server") + if err := bridge.imapListener.Close(); err != nil { return fmt.Errorf("failed to close IMAP listener: %w", err) } @@ -71,6 +75,8 @@ func (bridge *Bridge) restartIMAP() error { } func (bridge *Bridge) closeIMAP(ctx context.Context) error { + logrus.Info("Closing IMAP server") + if err := bridge.imapServer.Close(ctx); err != nil { return fmt.Errorf("failed to close IMAP server: %w", err) } @@ -86,6 +92,8 @@ func (bridge *Bridge) closeIMAP(ctx context.Context) error { // addIMAPUser connects the given user to gluon. func (bridge *Bridge) addIMAPUser(ctx context.Context, user *user.User) error { + logrus.WithField("userID", user.ID()).Info("Adding IMAP user") + imapConn, err := user.NewIMAPConnectors() if err != nil { return fmt.Errorf("failed to create IMAP connectors: %w", err) @@ -172,6 +180,13 @@ func newIMAPServer( eventCh chan<- imapEvents.Event, tasks *xsync.Group, ) (*gluon.Server, error) { + logrus.WithFields(logrus.Fields{ + "gluonDir": gluonDir, + "version": version, + "logClient": logClient, + "logServer": logServer, + }).Info("Creating IMAP server") + if logClient || logServer { log := logrus.WithField("protocol", "IMAP") log.Warning("================================================") diff --git a/internal/bridge/smtp.go b/internal/bridge/smtp.go index 9e2f0507..d5dde962 100644 --- a/internal/bridge/smtp.go +++ b/internal/bridge/smtp.go @@ -30,6 +30,8 @@ import ( ) func (bridge *Bridge) serveSMTP() error { + logrus.Info("Starting SMTP server") + smtpListener, err := newListener(bridge.vault.GetSMTPPort(), bridge.vault.GetSMTPSSL(), bridge.tlsConfig) if err != nil { return fmt.Errorf("failed to create SMTP listener: %w", err) @@ -37,9 +39,9 @@ func (bridge *Bridge) serveSMTP() error { bridge.smtpListener = smtpListener - bridge.tasks.Once(func(ctx context.Context) { + bridge.tasks.Once(func(context.Context) { if err := bridge.smtpServer.Serve(smtpListener); err != nil { - logrus.WithError(err).Debug("SMTP server stopped") + logrus.WithError(err).Info("SMTP server stopped") } }) @@ -51,6 +53,8 @@ func (bridge *Bridge) serveSMTP() error { } func (bridge *Bridge) restartSMTP() error { + logrus.Info("Restarting SMTP server") + if err := bridge.closeSMTP(); err != nil { return fmt.Errorf("failed to close SMTP: %w", err) } @@ -65,6 +69,8 @@ func (bridge *Bridge) restartSMTP() error { // after we've already closed the server. However, go-smtp has a bug; it blocks on the listener // even after the server has been closed. So we close the listener ourselves to unblock it. func (bridge *Bridge) closeSMTP() error { + logrus.Info("Closing SMTP server") + if bridge.smtpListener != nil { if err := bridge.smtpListener.Close(); err != nil { return fmt.Errorf("failed to close SMTP listener: %w", err) @@ -72,13 +78,15 @@ func (bridge *Bridge) closeSMTP() error { } if err := bridge.smtpServer.Close(); err != nil { - logrus.WithError(err).Debug("Failed to close SMTP server") + logrus.WithError(err).Debug("Failed to close SMTP server (expected -- we close the listener ourselves)") } return nil } -func newSMTPServer(bridge *Bridge, tlsConfig *tls.Config, shouldLog bool) *smtp.Server { +func newSMTPServer(bridge *Bridge, tlsConfig *tls.Config, logSMTP bool) *smtp.Server { + logrus.WithField("logSMTP", logSMTP).Info("Creating SMTP server") + smtpServer := smtp.NewServer(&smtpBackend{Bridge: bridge}) smtpServer.TLSConfig = tlsConfig @@ -87,7 +95,7 @@ func newSMTPServer(bridge *Bridge, tlsConfig *tls.Config, shouldLog bool) *smtp. smtpServer.MaxLineLength = 1 << 16 smtpServer.ErrorLog = logging.NewSMTPLogger() - if shouldLog { + if logSMTP { log := logrus.WithField("protocol", "SMTP") log.Warning("================================================") log.Warning("THIS LOG WILL CONTAIN **DECRYPTED** MESSAGE DATA") diff --git a/internal/bridge/user.go b/internal/bridge/user.go index 67baf602..0286f0a5 100644 --- a/internal/bridge/user.go +++ b/internal/bridge/user.go @@ -19,13 +19,12 @@ package bridge import ( "context" - "crypto/sha256" - "encoding/hex" "fmt" "github.com/ProtonMail/gluon/imap" "github.com/ProtonMail/proton-bridge/v2/internal/async" "github.com/ProtonMail/proton-bridge/v2/internal/events" + "github.com/ProtonMail/proton-bridge/v2/internal/logging" "github.com/ProtonMail/proton-bridge/v2/internal/safe" "github.com/ProtonMail/proton-bridge/v2/internal/try" "github.com/ProtonMail/proton-bridge/v2/internal/user" @@ -100,7 +99,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) (*liteapi.Client, liteapi.Auth, error) { - logrus.WithField("username", hash(username)).Debug("Authorizing user for login") + logrus.WithField("username", logging.Sensitive(username)).Info("Authorizing user for login") client, auth, err := bridge.api.NewClientWithLogin(ctx, username, password) if err != nil { @@ -127,7 +126,7 @@ func (bridge *Bridge) LoginUser( auth liteapi.Auth, keyPass []byte, ) (string, error) { - logrus.WithField("userID", auth.UserID).Debug("Logging in authorized user") + logrus.WithField("userID", auth.UserID).Info("Logging in authorized user") userID, err := try.CatchVal( func() (string, error) { @@ -158,7 +157,7 @@ func (bridge *Bridge) LoginFull( getTOTP func() (string, error), getKeyPass func() ([]byte, error), ) (string, error) { - logrus.WithField("username", hash(username)).Debug("Performing full user login") + logrus.WithField("username", logging.Sensitive(username)).Info("Performing full user login") client, auth, err := bridge.LoginAuth(ctx, username, password) if err != nil { @@ -166,7 +165,7 @@ func (bridge *Bridge) LoginFull( } if auth.TwoFA.Enabled == liteapi.TOTPEnabled { - logrus.WithField("userID", auth.UserID).Debug("Requesting TOTP") + logrus.WithField("userID", auth.UserID).Info("Requesting TOTP") totp, err := getTOTP() if err != nil { @@ -181,7 +180,7 @@ func (bridge *Bridge) LoginFull( var keyPass []byte if auth.PasswordMode == liteapi.TwoPasswordMode { - logrus.WithField("userID", auth.UserID).Debug("Requesting mailbox password") + logrus.WithField("userID", auth.UserID).Info("Requesting mailbox password") userKeyPass, err := getKeyPass() if err != nil { @@ -198,7 +197,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).Debug("Logging out user") + logrus.WithField("userID", userID).Info("Logging out user") return safe.LockRet(func() error { user, ok := bridge.users[userID] @@ -220,7 +219,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).Debug("Deleting user") + logrus.WithField("userID", userID).Info("Deleting user") return safe.LockRet(func() error { if !bridge.vault.HasUser(userID) { @@ -246,7 +245,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).Debug("Setting address mode") + logrus.WithField("userID", userID).WithField("mode", mode).Info("Setting address mode") return safe.RLockRet(func() error { user, ok := bridge.users[userID] @@ -319,7 +318,7 @@ func (bridge *Bridge) loadUsers(ctx context.Context) error { return nil } - logrus.WithField("userID", user.UserID()).Debug("Loading connected user") + logrus.WithField("userID", user.UserID()).Info("Loading connected user") bridge.publish(events.UserLoading{ UserID: user.UserID(), @@ -330,9 +329,10 @@ func (bridge *Bridge) loadUsers(ctx context.Context) error { bridge.publish(events.UserLoadFail{ UserID: user.UserID(), + Error: err, }) } else { - logrus.WithField("userID", user.UserID()).Debug("Loaded user") + logrus.WithField("userID", user.UserID()).Info("Successfully loaded user") bridge.publish(events.UserLoadSuccess{ UserID: user.UserID(), @@ -414,11 +414,11 @@ func (bridge *Bridge) addUserWithVault( ctx context.Context, client *liteapi.Client, apiUser liteapi.User, - vaultUser *vault.User, + vault *vault.User, ) error { user, err := user.New( ctx, - vaultUser, + vault, client, apiUser, bridge.vault.SyncWorkers(), @@ -438,6 +438,11 @@ 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{ + "userID": apiUser.ID, + "event": event, + }).Debug("Received user event") + if err := bridge.handleUserEvent(ctx, user, event); err != nil { logrus.WithError(err).Error("Failed to handle user event") } else { @@ -448,8 +453,8 @@ func (bridge *Bridge) addUserWithVault( // Gluon will set the IMAP ID in the context, if known, before making requests on behalf of this user. // As such, if we find this ID in the context, we should use it to update our user agent. - client.AddPreRequestHook(func(ctx context.Context, req *resty.Request) error { - if imapID, ok := imap.GetIMAPIDFromContext(ctx); ok { + client.AddPreRequestHook(func(_ *resty.Client, r *resty.Request) error { + if imapID, ok := imap.GetIMAPIDFromContext(r.Context()); ok { bridge.identifier.SetClient(imapID.Name, imapID.Version) } @@ -536,13 +541,3 @@ func mapHas[Key comparable, Val any](m map[Key]Val, key Key) bool { _, ok := m[key] return ok } - -func hash(s string) string { - h := sha256.New() - - if _, err := h.Write([]byte(s)); err != nil { - panic(err) - } - - return hex.EncodeToString(h.Sum(nil)) -} diff --git a/internal/events/address.go b/internal/events/address.go index 73658624..f9ee75f4 100644 --- a/internal/events/address.go +++ b/internal/events/address.go @@ -17,6 +17,12 @@ package events +import ( + "fmt" + + "github.com/ProtonMail/proton-bridge/v2/internal/logging" +) + type UserAddressCreated struct { eventBase @@ -25,6 +31,10 @@ type UserAddressCreated struct { Email string } +func (event UserAddressCreated) String() string { + return fmt.Sprintf("UserAddressCreated: UserID: %s, AddressID: %s, Email: %s", event.UserID, event.AddressID, logging.Sensitive(event.Email)) +} + type UserAddressUpdated struct { eventBase @@ -33,6 +43,10 @@ type UserAddressUpdated struct { Email string } +func (event UserAddressUpdated) String() string { + return fmt.Sprintf("UserAddressUpdated: UserID: %s, AddressID: %s, Email: %s", event.UserID, event.AddressID, logging.Sensitive(event.Email)) +} + type UserAddressDeleted struct { eventBase @@ -40,3 +54,7 @@ type UserAddressDeleted struct { AddressID string Email string } + +func (event UserAddressDeleted) String() string { + return fmt.Sprintf("UserAddressDeleted: UserID: %s, AddressID: %s, Email: %s", event.UserID, event.AddressID, logging.Sensitive(event.Email)) +} diff --git a/internal/events/connection.go b/internal/events/connection.go index 53c3f540..817c0bfe 100644 --- a/internal/events/connection.go +++ b/internal/events/connection.go @@ -21,10 +21,22 @@ type TLSIssue struct { eventBase } +func (event TLSIssue) String() string { + return "TLSIssue" +} + type ConnStatusUp struct { eventBase } +func (event ConnStatusUp) String() string { + return "ConnStatusUp" +} + type ConnStatusDown struct { eventBase } + +func (event ConnStatusDown) String() string { + return "ConnStatusDown" +} diff --git a/internal/events/error.go b/internal/events/error.go index 372190e3..7cdd7478 100644 --- a/internal/events/error.go +++ b/internal/events/error.go @@ -17,8 +17,14 @@ package events +import "fmt" + type Error struct { eventBase Error error } + +func (event Error) String() string { + return fmt.Sprintf("Error: %s", event.Error) +} diff --git a/internal/events/label.go b/internal/events/label.go index c4710161..a2074f41 100644 --- a/internal/events/label.go +++ b/internal/events/label.go @@ -17,6 +17,12 @@ package events +import ( + "fmt" + + "github.com/ProtonMail/proton-bridge/v2/internal/logging" +) + type UserLabelCreated struct { eventBase @@ -25,6 +31,10 @@ type UserLabelCreated struct { Name string } +func (event UserLabelCreated) String() string { + return fmt.Sprintf("UserLabelCreated: UserID: %s, LabelID: %s, Name: %s", event.UserID, event.LabelID, logging.Sensitive(event.Name)) +} + type UserLabelUpdated struct { eventBase @@ -33,6 +43,10 @@ type UserLabelUpdated struct { Name string } +func (event UserLabelUpdated) String() string { + return fmt.Sprintf("UserLabelUpdated: UserID: %s, LabelID: %s, Name: %s", event.UserID, event.LabelID, logging.Sensitive(event.Name)) +} + type UserLabelDeleted struct { eventBase @@ -40,3 +54,7 @@ type UserLabelDeleted struct { LabelID string Name string } + +func (event UserLabelDeleted) String() string { + return fmt.Sprintf("UserLabelDeleted: UserID: %s, LabelID: %s, Name: %s", event.UserID, event.LabelID, logging.Sensitive(event.Name)) +} diff --git a/internal/events/raise.go b/internal/events/raise.go index 7b113019..8e4d90bc 100644 --- a/internal/events/raise.go +++ b/internal/events/raise.go @@ -20,3 +20,7 @@ package events type Raise struct { eventBase } + +func (event Raise) String() string { + return "Raise" +} diff --git a/internal/events/sync.go b/internal/events/sync.go index 26feaa4e..5ffd61d6 100644 --- a/internal/events/sync.go +++ b/internal/events/sync.go @@ -17,7 +17,10 @@ package events -import "time" +import ( + "fmt" + "time" +) type SyncStarted struct { eventBase @@ -25,6 +28,10 @@ type SyncStarted struct { UserID string } +func (event SyncStarted) String() string { + return fmt.Sprintf("SyncStarted: UserID: %s", event.UserID) +} + type SyncProgress struct { eventBase @@ -34,15 +41,33 @@ type SyncProgress struct { Remaining time.Duration } +func (event SyncProgress) String() string { + return fmt.Sprintf( + "SyncProgress: UserID: %s, Progress: %f, Elapsed: %0.1fs, Remaining: %0.1fs", + event.UserID, + event.Progress, + event.Elapsed.Seconds(), + event.Remaining.Seconds(), + ) +} + type SyncFinished struct { eventBase UserID string } +func (event SyncFinished) String() string { + return fmt.Sprintf("SyncFinished: UserID: %s", event.UserID) +} + type SyncFailed struct { eventBase UserID string - Err error + Error error +} + +func (event SyncFailed) String() string { + return fmt.Sprintf("SyncFailed: UserID: %s, Err: %s", event.UserID, event.Error) } diff --git a/internal/events/update.go b/internal/events/update.go index 7015b664..d1291a14 100644 --- a/internal/events/update.go +++ b/internal/events/update.go @@ -17,7 +17,11 @@ package events -import "github.com/ProtonMail/proton-bridge/v2/internal/updater" +import ( + "fmt" + + "github.com/ProtonMail/proton-bridge/v2/internal/updater" +) type UpdateAvailable struct { eventBase @@ -27,16 +31,32 @@ type UpdateAvailable struct { CanInstall bool } +func (event UpdateAvailable) String() string { + return fmt.Sprintf("UpdateAvailable: Version %s, CanInstall %t", event.Version.Version, event.CanInstall) +} + type UpdateNotAvailable struct { eventBase } +func (event UpdateNotAvailable) String() string { + return "UpdateNotAvailable" +} + type UpdateInstalled struct { eventBase Version updater.VersionInfo } +func (event UpdateInstalled) String() string { + return fmt.Sprintf("UpdateInstalled: Version %s", event.Version.Version) +} + type UpdateForced struct { eventBase } + +func (event UpdateForced) String() string { + return "UpdateForced" +} diff --git a/internal/events/user.go b/internal/events/user.go index 4c9e982e..2dc0f98f 100644 --- a/internal/events/user.go +++ b/internal/events/user.go @@ -17,28 +17,49 @@ package events -import "github.com/ProtonMail/proton-bridge/v2/internal/vault" +import ( + "fmt" + + "github.com/ProtonMail/proton-bridge/v2/internal/vault" +) type AllUsersLoaded struct { eventBase } +func (event AllUsersLoaded) String() string { + return "AllUsersLoaded" +} + type UserLoading struct { eventBase UserID string } +func (event UserLoading) String() string { + return fmt.Sprintf("UserLoading: UserID: %s", event.UserID) +} + type UserLoadSuccess struct { eventBase UserID string } +func (event UserLoadSuccess) String() string { + return fmt.Sprintf("UserLoadSuccess: UserID: %s", event.UserID) +} + type UserLoadFail struct { eventBase UserID string + Error error +} + +func (event UserLoadFail) String() string { + return fmt.Sprintf("UserLoadFail: UserID: %s, Error: %s", event.UserID, event.Error) } type UserLoggedIn struct { @@ -47,33 +68,58 @@ type UserLoggedIn struct { UserID string } +func (event UserLoggedIn) String() string { + return fmt.Sprintf("UserLoggedIn: UserID: %s", event.UserID) +} + type UserLoggedOut struct { eventBase UserID string } +func (event UserLoggedOut) String() string { + return fmt.Sprintf("UserLoggedOut: UserID: %s", event.UserID) +} + type UserDeauth struct { eventBase UserID string } +func (event UserDeauth) String() string { + return fmt.Sprintf("UserDeauth: UserID: %s", event.UserID) +} + type UserDeleted struct { eventBase UserID string } +func (event UserDeleted) String() string { + return fmt.Sprintf("UserDeleted: UserID: %s", event.UserID) +} + type UserChanged struct { eventBase UserID string } +func (event UserChanged) String() string { + return fmt.Sprintf("UserChanged: UserID: %s", event.UserID) +} + type AddressModeChanged struct { eventBase - UserID string + UserID string + AddressMode vault.AddressMode } + +func (event AddressModeChanged) String() string { + return fmt.Sprintf("AddressModeChanged: UserID: %s, AddressMode: %s", event.UserID, event.AddressMode) +} diff --git a/internal/frontend/cli/accounts.go b/internal/frontend/cli/accounts.go index 29b0ed69..b5e2fd5a 100644 --- a/internal/frontend/cli/accounts.go +++ b/internal/frontend/cli/accounts.go @@ -40,11 +40,7 @@ func (f *frontendCLI) listAccounts(c *ishell.Context) { if user.Connected { connected = "connected" } - mode := "split" - if user.AddressMode == vault.CombinedMode { - mode = "combined" - } - f.Printf(spacing, idx, user.Username, connected, mode) + f.Printf(spacing, idx, user.Username, connected, user.AddressMode) } f.Println() } @@ -265,16 +261,7 @@ func (f *frontendCLI) changeMode(c *ishell.Context) { targetMode = vault.CombinedMode } - var targetModeName string - - switch targetMode { - case vault.CombinedMode: - targetModeName = "combined" - case vault.SplitMode: - targetModeName = "split" - } - - if !f.yesNoQuestion("Are you sure you want to change the mode for account " + bold(user.Username) + " to " + bold(targetModeName)) { + if !f.yesNoQuestion("Are you sure you want to change the mode for account " + bold(user.Username) + " to " + bold(targetMode.String())) { return } @@ -282,7 +269,7 @@ func (f *frontendCLI) changeMode(c *ishell.Context) { f.printAndLogError("Cannot switch address mode:", err) } - f.Printf("Address mode for account %s changed to %s\n", user.Username, targetModeName) + f.Printf("Address mode for account %s changed to %s\n", user.Username, targetMode) } func (f *frontendCLI) configureAppleMail(c *ishell.Context) { diff --git a/internal/frontend/grpc/service_methods.go b/internal/frontend/grpc/service_methods.go index bf4055e8..2244ee45 100644 --- a/internal/frontend/grpc/service_methods.go +++ b/internal/frontend/grpc/service_methods.go @@ -368,17 +368,20 @@ func (s *Service) Login(ctx context.Context, login *LoginRequest) (*emptypb.Empt if err != nil { defer s.loginClean() - switch { - case errors.Is(err, bridge.ErrUserAlreadyLoggedIn): + if errors.Is(err, bridge.ErrUserAlreadyLoggedIn) { _ = s.SendEvent(NewLoginAlreadyLoggedInEvent(auth.UserID)) + } else if apiErr := new(liteapi.Error); errors.As(err, &apiErr) { + switch apiErr.Code { // nolint:exhaustive + case liteapi.PasswordWrong: + _ = s.SendEvent(NewLoginError(LoginErrorType_USERNAME_PASSWORD_ERROR, "")) - case errors.Is(err, liteapi.ErrIncorrectLoginCredentials): - _ = s.SendEvent(NewLoginError(LoginErrorType_USERNAME_PASSWORD_ERROR, "")) + case liteapi.PaidPlanRequired: + _ = s.SendEvent(NewLoginError(LoginErrorType_FREE_USER, "")) - case errors.Is(err, liteapi.ErrPaidPlanRequired): - _ = s.SendEvent(NewLoginError(LoginErrorType_FREE_USER, "")) - - default: + default: + _ = s.SendEvent(NewLoginError(LoginErrorType_USERNAME_PASSWORD_ERROR, err.Error())) + } + } else { _ = s.SendEvent(NewLoginError(LoginErrorType_USERNAME_PASSWORD_ERROR, err.Error())) } @@ -426,12 +429,10 @@ func (s *Service) Login2FA(ctx context.Context, login *LoginRequest) (*emptypb.E } if err := s.authClient.Auth2FA(context.Background(), liteapi.Auth2FAReq{TwoFactorCode: string(twoFA)}); err != nil { - switch { - case errors.Is(err, liteapi.ErrBad2FACode): + if apiErr := new(liteapi.Error); errors.As(err, &apiErr) && apiErr.Code == liteapi.PasswordWrong { s.log.Warn("Login 2FA: retry 2fa") _ = s.SendEvent(NewLoginError(LoginErrorType_TFA_ERROR, "")) - - default: + } else { s.log.WithError(err).Warn("Login 2FA: failed") _ = s.SendEvent(NewLoginError(LoginErrorType_TFA_ABORT, err.Error())) s.loginClean() diff --git a/internal/logging/sensitive_default.go b/internal/logging/sensitive_default.go new file mode 100644 index 00000000..935baecc --- /dev/null +++ b/internal/logging/sensitive_default.go @@ -0,0 +1,40 @@ +// Copyright (c) 2022 Proton AG +// +// This file is part of Proton Mail Bridge. +// +// Proton Mail Bridge is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// Proton Mail Bridge is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with Proton Mail Bridge. If not, see . + +//go:build !sensitive + +package logging + +import ( + "crypto/sha256" + "encoding/hex" + "fmt" +) + +func Sensitive(s string) string { + return fmt.Sprintf("******** (%s)", hash(s)) +} + +func hash(s string) string { + h := sha256.New() + + if _, err := h.Write([]byte(s)); err != nil { + panic(err) + } + + return hex.EncodeToString(h.Sum(nil))[0:8] +} diff --git a/internal/logging/sensitive_sensitive.go b/internal/logging/sensitive_sensitive.go new file mode 100644 index 00000000..9641fcf9 --- /dev/null +++ b/internal/logging/sensitive_sensitive.go @@ -0,0 +1,24 @@ +// Copyright (c) 2022 Proton AG +// +// This file is part of Proton Mail Bridge. +// +// Proton Mail Bridge is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// Proton Mail Bridge is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with Proton Mail Bridge. If not, see . + +//go:build sensitive + +package logging + +func Sensitive(s string) string { + return s +} diff --git a/internal/user/events.go b/internal/user/events.go index 6cd05ce4..087ae4ee 100644 --- a/internal/user/events.go +++ b/internal/user/events.go @@ -25,9 +25,11 @@ import ( "github.com/ProtonMail/gluon/queue" "github.com/ProtonMail/gopenpgp/v2/crypto" "github.com/ProtonMail/proton-bridge/v2/internal/events" + "github.com/ProtonMail/proton-bridge/v2/internal/logging" "github.com/ProtonMail/proton-bridge/v2/internal/safe" "github.com/ProtonMail/proton-bridge/v2/internal/vault" "github.com/bradenaw/juniper/xslices" + "github.com/sirupsen/logrus" "gitlab.protontech.ch/go/liteapi" ) @@ -63,6 +65,11 @@ func (user *User) handleAPIEvent(ctx context.Context, event liteapi.Event) error // handleUserEvent handles the given user event. func (user *User) handleUserEvent(_ context.Context, userEvent liteapi.User) error { return safe.LockRet(func() error { + user.log.WithFields(logrus.Fields{ + "userID": userEvent.ID, + "username": logging.Sensitive(userEvent.Name), + }).Info("Handling user event") + user.apiUser = userEvent user.eventCh.Enqueue(events.UserChanged{ @@ -100,6 +107,11 @@ func (user *User) handleAddressEvents(ctx context.Context, addressEvents []litea func (user *User) handleCreateAddressEvent(ctx context.Context, event liteapi.AddressEvent) error { if err := safe.LockRet(func() error { + user.log.WithFields(logrus.Fields{ + "addressID": event.ID, + "email": logging.Sensitive(event.Address.Email), + }).Info("Handling address created event") + if _, ok := user.apiAddrs[event.Address.ID]; ok { return fmt.Errorf("address %q already exists", event.ID) } @@ -143,6 +155,11 @@ func (user *User) handleCreateAddressEvent(ctx context.Context, event liteapi.Ad func (user *User) handleUpdateAddressEvent(_ context.Context, event liteapi.AddressEvent) error { //nolint:unparam return safe.LockRet(func() error { + user.log.WithFields(logrus.Fields{ + "addressID": event.ID, + "email": logging.Sensitive(event.Address.Email), + }).Info("Handling address updated event") + if _, ok := user.apiAddrs[event.Address.ID]; !ok { return fmt.Errorf("address %q does not exist", event.Address.ID) } @@ -161,6 +178,8 @@ func (user *User) handleUpdateAddressEvent(_ context.Context, event liteapi.Addr func (user *User) handleDeleteAddressEvent(_ context.Context, event liteapi.AddressEvent) error { return safe.LockRet(func() error { + user.log.WithField("addressID", event.ID).Info("Handling address deleted event") + addr, ok := user.apiAddrs[event.ID] if !ok { return fmt.Errorf("address %q does not exist", event.ID) @@ -209,6 +228,11 @@ func (user *User) handleLabelEvents(ctx context.Context, labelEvents []liteapi.L func (user *User) handleCreateLabelEvent(_ context.Context, event liteapi.LabelEvent) error { //nolint:unparam return safe.LockRet(func() error { + user.log.WithFields(logrus.Fields{ + "labelID": event.ID, + "name": logging.Sensitive(event.Label.Name), + }).Info("Handling label created event") + if _, ok := user.apiLabels[event.Label.ID]; ok { return fmt.Errorf("label %q already exists", event.ID) } @@ -231,6 +255,11 @@ func (user *User) handleCreateLabelEvent(_ context.Context, event liteapi.LabelE func (user *User) handleUpdateLabelEvent(_ context.Context, event liteapi.LabelEvent) error { //nolint:unparam return safe.LockRet(func() error { + user.log.WithFields(logrus.Fields{ + "labelID": event.ID, + "name": logging.Sensitive(event.Label.Name), + }).Info("Handling label updated event") + if _, ok := user.apiLabels[event.Label.ID]; !ok { return fmt.Errorf("label %q does not exist", event.ID) } @@ -253,6 +282,8 @@ func (user *User) handleUpdateLabelEvent(_ context.Context, event liteapi.LabelE func (user *User) handleDeleteLabelEvent(_ context.Context, event liteapi.LabelEvent) error { //nolint:unparam return safe.LockRet(func() error { + user.log.WithField("labelID", event.ID).Info("Handling label deleted event") + label, ok := user.apiLabels[event.ID] if !ok { return fmt.Errorf("label %q does not exist", event.ID) @@ -305,6 +336,11 @@ func (user *User) handleCreateMessageEvent(ctx context.Context, event liteapi.Me } return safe.RLockRet(func() error { + user.log.WithFields(logrus.Fields{ + "messageID": event.ID, + "subject": logging.Sensitive(event.Message.Subject), + }).Info("Handling message created event") + return withAddrKR(user.apiUser, user.apiAddrs[event.Message.AddressID], user.vault.KeyPass(), func(_, addrKR *crypto.KeyRing) error { buildRes, err := buildRFC822(full, addrKR) if err != nil { @@ -320,6 +356,11 @@ func (user *User) handleCreateMessageEvent(ctx context.Context, event liteapi.Me func (user *User) handleUpdateMessageEvent(_ context.Context, event liteapi.MessageEvent) error { //nolint:unparam return safe.RLockRet(func() error { + user.log.WithFields(logrus.Fields{ + "messageID": event.ID, + "subject": logging.Sensitive(event.Message.Subject), + }).Info("Handling message updated event") + update := imap.NewMessageMailboxesUpdated( imap.MessageID(event.ID), mapTo[string, imap.MailboxID](xslices.Filter(event.Message.LabelIDs, wantLabelID)), @@ -335,6 +376,8 @@ func (user *User) handleUpdateMessageEvent(_ context.Context, event liteapi.Mess func (user *User) handleDeleteMessageEvent(_ context.Context, event liteapi.MessageEvent) error { //nolint:unparam return safe.RLockRet(func() error { + user.log.WithField("messageID", event.ID).Info("Handling message deleted event") + for _, updateCh := range user.updateCh { update := imap.NewMessagesDeleted( imap.MessageID(event.ID), diff --git a/internal/user/imap.go b/internal/user/imap.go index c0d5445d..b0d68fd0 100644 --- a/internal/user/imap.go +++ b/internal/user/imap.go @@ -257,7 +257,7 @@ func (conn *imapConnector) CreateMessage( if messageID, ok, err := conn.sendHash.hasEntryWait(ctx, hash, time.Now().Add(90*time.Second)); err != nil { return imap.Message{}, nil, fmt.Errorf("failed to check send hash: %w", err) } else if ok { - conn.log.WithField("messageID", messageID).Debug("Message already sent") + conn.log.WithField("messageID", messageID).Warn("Message already sent") message, err := conn.client.GetMessage(ctx, messageID) if err != nil { diff --git a/internal/user/sync.go b/internal/user/sync.go index dd9e0a37..c5f63531 100644 --- a/internal/user/sync.go +++ b/internal/user/sync.go @@ -46,24 +46,26 @@ const ( // It sends a SyncStarted event and then either SyncFinished or SyncFailed // depending on whether the sync was successful. func (user *User) doSync(ctx context.Context) error { - user.log.Debug("Beginning user sync") + start := time.Now() + + user.log.WithField("start", start).Info("Beginning user sync") user.eventCh.Enqueue(events.SyncStarted{ UserID: user.ID(), }) if err := user.sync(ctx); err != nil { - user.log.WithError(err).Debug("Failed to sync user") + user.log.WithError(err).Warn("Failed to sync user") user.eventCh.Enqueue(events.SyncFailed{ UserID: user.ID(), - Err: err, + Error: err, }) return fmt.Errorf("failed to sync: %w", err) } - user.log.Debug("Finished user sync") + user.log.WithField("duration", time.Since(start)).Info("Finished user sync") user.eventCh.Enqueue(events.SyncFinished{ UserID: user.ID(), @@ -76,7 +78,7 @@ func (user *User) sync(ctx context.Context) error { return safe.RLockRet(func() error { return withAddrKRs(user.apiUser, user.apiAddrs, user.vault.KeyPass(), func(_ *crypto.KeyRing, addrKRs map[string]*crypto.KeyRing) error { if !user.vault.SyncStatus().HasLabels { - user.log.Debug("Syncing labels") + user.log.Info("Syncing labels") if err := syncLabels(ctx, user.client, xslices.Unique(maps.Values(user.updateCh))...); err != nil { return fmt.Errorf("failed to sync labels: %w", err) @@ -86,13 +88,13 @@ func (user *User) sync(ctx context.Context) error { return fmt.Errorf("failed to set has labels: %w", err) } - user.log.Debug("Synced labels") + user.log.Info("Synced labels") } else { - user.log.Debug("Labels are already synced, skipping") + user.log.Info("Labels are already synced, skipping") } if !user.vault.SyncStatus().HasMessages { - user.log.Debug("Syncing messages") + user.log.Info("Syncing messages") if err := syncMessages( ctx, @@ -112,9 +114,9 @@ func (user *User) sync(ctx context.Context) error { return fmt.Errorf("failed to set has messages: %w", err) } - user.log.Debug("Synced messages") + user.log.Info("Synced messages") } else { - user.log.Debug("Messages are already synced, skipping") + user.log.Info("Messages are already synced, skipping") } return nil diff --git a/internal/user/user.go b/internal/user/user.go index 08c4ff12..eca7570d 100644 --- a/internal/user/user.go +++ b/internal/user/user.go @@ -39,6 +39,7 @@ import ( "github.com/ProtonMail/proton-bridge/v2/pkg/message/parser" "github.com/bradenaw/juniper/xslices" "github.com/bradenaw/juniper/xsync" + "github.com/go-resty/resty/v2" "github.com/sirupsen/logrus" "gitlab.protontech.ch/go/liteapi" "golang.org/x/exp/maps" @@ -91,7 +92,7 @@ func New( syncWorkers, syncBuffer int, showAllMail bool, ) (*User, error) { //nolint:funlen - logrus.WithField("userID", apiUser.ID).Debug("Creating new user") + logrus.WithField("userID", apiUser.ID).Info("Creating new user") // Get the user's API addresses. apiAddrs, err := client.GetAddresses(ctx) @@ -183,6 +184,12 @@ func New( }) }) + // 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) + return nil + }) + // Stream events from the API, logging any errors that occur. // This does nothing until the sync has been marked as complete. // When we receive an API event, we attempt to handle it. @@ -204,6 +211,8 @@ func New( return } + user.log.WithField("event", event).Info("Received event") + if err := user.handleAPIEvent(ctx, event); err != nil { user.log.WithError(err).Error("Failed to handle API event") return @@ -219,11 +228,15 @@ func New( // When triggered, attempt to sync the user. user.goSync = user.tasks.Trigger(func(ctx context.Context) { + user.log.Debug("Sync triggered") + user.abortable.Do(ctx, func(ctx context.Context) { if !user.vault.SyncStatus().IsComplete() { if err := user.doSync(ctx); err != nil { return } + } else { + user.log.Debug("Sync is already complete, skipping") } }) }) diff --git a/internal/vault/types.go b/internal/vault/types.go index 4456f88f..3971ac82 100644 --- a/internal/vault/types.go +++ b/internal/vault/types.go @@ -120,6 +120,19 @@ const ( SplitMode ) +func (mode AddressMode) String() string { + switch mode { + case CombinedMode: + return "combined" + + case SplitMode: + return "split" + + default: + return "unknown" + } +} + type SyncStatus struct { HasLabels bool HasMessages bool