Other: Add some more debug logs

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

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)

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

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 {
+	if ok := safe.RLockRet(func() bool { return mapHas(bridge.users, auth.UID) }, bridge.usersLock); ok {
-		return mapHas(bridge.users, auth.UID)
+		logrus.WithField("userID", auth.UserID).Warn("User already logged in")
-	}, bridge.usersLock); ok {
+
 		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))
+}

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