yesBad/proton-bridge
1
0
Fork 0
Code Actions Activity

feat(GODT-3199): add package log field.

Browse Source
This commit is contained in:
Jakub
2024-02-26 14:16:50 +01:00
parent bf3c90b8e9
commit c9b6cc162b
17 changed files with 129 additions and 118 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
internal/bridge/api.go
View File

@ -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),
}
}

34
internal/bridge/bridge.go
View File

@ -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
}

2
internal/bridge/configure.go
View File

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

8
internal/bridge/debug.go
View File

@ -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
}

4
internal/bridge/heartbeat.go
View File

@ -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
}

8
internal/bridge/imap.go
View File

@ -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",

17
internal/bridge/settings.go
View File

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

62
internal/bridge/user.go
View File

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

4
internal/bridge/user_events.go
View File

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