yesBad/proton-bridge
1
0
Fork 0
forked from Silverfish/proton-bridge
Code Actions Activity

Other: Add more extensive logging

Browse Source
This commit is contained in:
James Houlahan
2022-11-03 23:02:34 +01:00
parent 8bb60afabd
commit c548ba85fe
24 changed files with 405 additions and 81 deletions
Download Patch File Download Diff File Expand all files Collapse all files

31
internal/bridge/bridge.go
View File

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

7
internal/bridge/configure.go
View File

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

15
internal/bridge/imap.go
View File

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

18
internal/bridge/smtp.go
View File

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

47
internal/bridge/user.go
View File

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