diff --git a/internal/app/app.go b/internal/app/app.go index 223d06e7..da9eaad8 100644 --- a/internal/app/app.go +++ b/internal/app/app.go @@ -199,6 +199,8 @@ func run(c *cli.Context) error { //nolint:funlen // If there's another instance already running, try to raise it and exit. func withSingleInstance(locations *locations.Locations, version *semver.Version, fn func() error) error { + logrus.Debug("Checking for other instances") + lock, err := checkSingleInstance(locations.GetLockFile(), version) if err != nil { logrus.Info("Another instance is already running; raising it") @@ -229,6 +231,8 @@ func withLogging(c *cli.Context, crashHandler *crash.Handler, locations *locatio return fmt.Errorf("could not provide logs path: %w", err) } + logrus.WithField("path", logsPath).Debug("Initializing logging") + // Initialize logging. if err := logging.Init(logsPath, c.String(flagLogLevel)); err != nil { return fmt.Errorf("could not initialize logging: %w", err) @@ -251,6 +255,8 @@ func withLogging(c *cli.Context, crashHandler *crash.Handler, locations *locatio // WithLocations provides access to locations where we store our files. func WithLocations(fn func(*locations.Locations) error) error { + logrus.Debug("Creating locations") + // Create a locations provider to determine where to store our files. provider, err := locations.NewDefaultProvider(filepath.Join(constants.VendorName, constants.ConfigName)) if err != nil { @@ -271,10 +277,12 @@ func WithLocations(fn func(*locations.Locations) error) error { // Start profiling if requested. func withProfiler(c *cli.Context, fn func() error) error { if c.Bool(flagCPUProfile) { + logrus.Debug("Running with CPU profiling") defer profile.Start(profile.CPUProfile, profile.ProfilePath(".")).Stop() } if c.Bool(flagMemProfile) { + logrus.Debug("Running with memory profiling") defer profile.Start(profile.MemProfile, profile.MemProfileAllocs, profile.ProfilePath(".")).Stop() } @@ -283,6 +291,8 @@ func withProfiler(c *cli.Context, fn func() error) error { // Restart the app if necessary. func withRestarter(exe string, fn func(*restarter.Restarter) error) error { + logrus.Debug("Creating restarter") + restarter := restarter.New(exe) defer restarter.Restart() @@ -291,6 +301,8 @@ func withRestarter(exe string, fn func(*restarter.Restarter) error) error { // Handle crashes if they occur. func withCrashHandler(restarter *restarter.Restarter, reporter *sentry.Reporter, fn func(*crash.Handler) error) error { + logrus.Debug("Creating crash handler") + crashHandler := crash.NewHandler(crash.ShowErrorNotification(constants.FullAppName)) defer crashHandler.HandlePanic() @@ -301,13 +313,15 @@ func withCrashHandler(restarter *restarter.Restarter, reporter *sentry.Reporter, crashHandler.AddRecoveryAction(crash.ShowErrorNotification(constants.FullAppName)) // On crash, restart the app. - crashHandler.AddRecoveryAction(func(r any) error { restarter.Set(true, true); return nil }) + crashHandler.AddRecoveryAction(func(any) error { restarter.Set(true, true); return nil }) return fn(crashHandler) } // Use a custom cookie jar to persist values across runs. func withCookieJar(vault *vault.Vault, fn func(http.CookieJar) error) error { + logrus.Debug("Creating cookie jar") + // Create the underlying cookie jar. jar, err := cookiejar.New(nil) if err != nil { @@ -322,6 +336,8 @@ func withCookieJar(vault *vault.Vault, fn func(http.CookieJar) error) error { // Persist the cookies to the vault when we close. defer func() { + logrus.Debug("Persisting cookies") + if err := persister.PersistCookies(); err != nil { logrus.WithError(err).Error("Failed to persist cookies") } diff --git a/internal/app/bridge.go b/internal/app/bridge.go index 9a911ffb..0ce02fa8 100644 --- a/internal/app/bridge.go +++ b/internal/app/bridge.go @@ -56,8 +56,12 @@ func withBridge( //nolint:funlen cookieJar http.CookieJar, fn func(*bridge.Bridge, <-chan events.Event) error, ) error { + logrus.Debug("Creating bridge") + // Delete old go-imap cache files if deleteOldGoIMAPFiles { + logrus.Debug("Deleting old go-imap cache files") + if err := locations.CleanGoIMAPCache(); err != nil { logrus.WithError(err).Error("Failed to remove old go-imap cache") } @@ -116,6 +120,8 @@ func withBridge( //nolint:funlen } func newAutostarter(exe string) *autostart.App { + logrus.Debug("Creating autostarter") + return &autostart.App{ Name: constants.FullAppName, DisplayName: constants.FullAppName, @@ -129,6 +135,8 @@ func newUpdater(locations *locations.Locations) (*updater.Updater, error) { return nil, fmt.Errorf("could not provide updates path: %w", err) } + logrus.WithField("updates", updatesDir).Debug("Creating updater") + key, err := crypto.NewKeyFromArmored(updater.DefaultPublicKey) if err != nil { return nil, fmt.Errorf("could not create key from armored: %w", err) diff --git a/internal/app/vault.go b/internal/app/vault.go index 7a27b9d5..c2bf58ed 100644 --- a/internal/app/vault.go +++ b/internal/app/vault.go @@ -32,14 +32,23 @@ import ( ) func WithVault(locations *locations.Locations, fn func(*vault.Vault, bool, bool) error) error { + logrus.Debug("Creating vault") + // Create the encVault. encVault, insecure, corrupt, err := newVault(locations) if err != nil { return fmt.Errorf("could not create vault: %w", err) } + logrus.WithFields(logrus.Fields{ + "insecure": insecure, + "corrupt": corrupt, + }).Debug("Vault created") + // Install the certificates if needed. if installed := encVault.GetCertsInstalled(); !installed { + logrus.Debug("Installing certificates") + if err := certs.NewInstaller().InstallCert(encVault.GetBridgeTLSCert()); err != nil { return fmt.Errorf("failed to install certs: %w", err) } @@ -47,6 +56,8 @@ func WithVault(locations *locations.Locations, fn func(*vault.Vault, bool, bool) if err := encVault.SetCertsInstalled(true); err != nil { return fmt.Errorf("failed to set certs installed: %w", err) } + + logrus.Debug("Certificates successfully installed") } // GODT-1950: Add teardown actions (e.g. to close the vault). diff --git a/internal/bridge/user.go b/internal/bridge/user.go index cea53de1..379ab5f0 100644 --- a/internal/bridge/user.go +++ b/internal/bridge/user.go @@ -19,6 +19,8 @@ package bridge import ( "context" + "crypto/sha256" + "encoding/hex" "fmt" "github.com/ProtonMail/gluon/imap" @@ -98,14 +100,16 @@ 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") + client, auth, err := bridge.api.NewClientWithLogin(ctx, username, password) if err != nil { return nil, liteapi.Auth{}, fmt.Errorf("failed to create new API client: %w", err) } - if ok := safe.RLockRet(func() bool { - return mapHas(bridge.users, auth.UID) - }, bridge.usersLock); ok { + if ok := safe.RLockRet(func() bool { return mapHas(bridge.users, auth.UID) }, bridge.usersLock); ok { + logrus.WithField("userID", auth.UserID).Warn("User already logged in") + if err := client.AuthDelete(ctx); err != nil { logrus.WithError(err).Warn("Failed to delete auth") } @@ -123,6 +127,8 @@ func (bridge *Bridge) LoginUser( auth liteapi.Auth, keyPass []byte, ) (string, error) { + logrus.WithField("userID", auth.UserID).Debug("Logging in authorized user") + userID, err := try.CatchVal( func() (string, error) { return bridge.loginUser(ctx, client, auth.UID, auth.RefreshToken, keyPass) @@ -152,12 +158,16 @@ func (bridge *Bridge) LoginFull( getTOTP func() (string, error), getKeyPass func() ([]byte, error), ) (string, error) { + logrus.WithField("username", hash(username)).Debug("Performing full user login") + client, auth, err := bridge.LoginAuth(ctx, username, password) if err != nil { return "", fmt.Errorf("failed to begin login process: %w", err) } if auth.TwoFA.Enabled == liteapi.TOTPEnabled { + logrus.WithField("userID", auth.UserID).Debug("Requesting TOTP") + totp, err := getTOTP() if err != nil { return "", fmt.Errorf("failed to get TOTP: %w", err) @@ -171,6 +181,8 @@ func (bridge *Bridge) LoginFull( var keyPass []byte if auth.PasswordMode == liteapi.TwoPasswordMode { + logrus.WithField("userID", auth.UserID).Debug("Requesting mailbox password") + userKeyPass, err := getKeyPass() if err != nil { return "", fmt.Errorf("failed to get key password: %w", err) @@ -186,6 +198,8 @@ 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") + return safe.LockRet(func() error { user, ok := bridge.users[userID] if !ok { @@ -206,6 +220,8 @@ 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") + return safe.LockRet(func() error { if !bridge.vault.HasUser(userID) { return ErrNoSuchUser @@ -230,6 +246,8 @@ 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") + return safe.RLockRet(func() error { user, ok := bridge.users[userID] if !ok { @@ -293,6 +311,8 @@ func (bridge *Bridge) loadUsers(ctx context.Context) error { return nil } + logrus.WithField("userID", user.UserID()).Debug("Loading user") + if safe.RLockRet(func() bool { return mapHas(bridge.users, user.UserID()) }, bridge.usersLock) { @@ -504,3 +524,13 @@ 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/vault/vault.go b/internal/vault/vault.go index e49b4acb..0379a49e 100644 --- a/internal/vault/vault.go +++ b/internal/vault/vault.go @@ -31,6 +31,7 @@ import ( "github.com/ProtonMail/proton-bridge/v2/internal/certs" "github.com/bradenaw/juniper/xslices" + "github.com/sirupsen/logrus" "github.com/vmihailenco/msgpack/v5" ) @@ -184,6 +185,8 @@ func (vault *Vault) attachUser(userID string) *User { vault.refLock.Lock() defer vault.refLock.Unlock() + logrus.WithField("userID", userID).Trace("Attaching vault user") + vault.ref[userID]++ return &User{ @@ -196,6 +199,8 @@ func (vault *Vault) detachUser(userID string) error { vault.refLock.Lock() defer vault.refLock.Unlock() + logrus.WithField("userID", userID).Trace("Detaching vault user") + if _, ok := vault.ref[userID]; !ok { return fmt.Errorf("user %s is not attached", userID) }