feat(BRIDGE-340): additional logging for label operations & bad events

go.mod

@@ -7,7 +7,7 @@ toolchain go1.24.0
 require (
 	github.com/0xAX/notificator v0.0.0-20220220101646-ee9b8921e557
 	github.com/Masterminds/semver/v3 v3.2.0
-	github.com/ProtonMail/gluon v0.17.1-0.20250116113909-2ebd96ec0bc2
+	github.com/ProtonMail/gluon v0.17.1-0.20250324123053-2abce471ad71
 	github.com/ProtonMail/go-autostart v0.0.0-20210130080809-00ed301c8e9a
 	github.com/ProtonMail/go-proton-api v0.4.1-0.20250217140732-2e531f21de4c
 	github.com/ProtonMail/gopenpgp/v2 v2.8.2-proton

go.sum

@@ -34,8 +34,10 @@ github.com/OneOfOne/xxhash v1.2.2/go.mod h1:HSdplMjZKSmBqAxg5vPj2TmRDmfkzw+cTzAE
 github.com/ProtonMail/bcrypt v0.0.0-20210511135022-227b4adcab57/go.mod h1:HecWFHognK8GfRDGnFQbW/LiV7A3MX3gZVs45vk5h8I=
 github.com/ProtonMail/bcrypt v0.0.0-20211005172633-e235017c1baf h1:yc9daCCYUefEs69zUkSzubzjBbL+cmOXgnmt9Fyd9ug=
 github.com/ProtonMail/bcrypt v0.0.0-20211005172633-e235017c1baf/go.mod h1:o0ESU9p83twszAU8LBeJKFAAMX14tISa0yk4Oo5TOqo=
-github.com/ProtonMail/gluon v0.17.1-0.20250116113909-2ebd96ec0bc2 h1:lDgMidI/9j2eedavcy7YICv8+F73ooVTUoUGBE4dO0s=
+github.com/ProtonMail/gluon v0.17.1-0.20250321152707-5c8c683d58c8 h1:jC8lJcX/tCjXWrM3aJ9IN5fKeefOoNZI+Zh0bfjaj44=
-github.com/ProtonMail/gluon v0.17.1-0.20250116113909-2ebd96ec0bc2/go.mod h1:0/c03TzZPNiSgY5UDJK1iRDkjlDPwWugxTT6et2qDu8=
+github.com/ProtonMail/gluon v0.17.1-0.20250321152707-5c8c683d58c8/go.mod h1:0/c03TzZPNiSgY5UDJK1iRDkjlDPwWugxTT6et2qDu8=
+github.com/ProtonMail/gluon v0.17.1-0.20250324123053-2abce471ad71 h1:UC8SLrS6QbBeOUM8FJugyNoeV5gRGoQCwNePAMxuM20=
+github.com/ProtonMail/gluon v0.17.1-0.20250324123053-2abce471ad71/go.mod h1:0/c03TzZPNiSgY5UDJK1iRDkjlDPwWugxTT6et2qDu8=
 github.com/ProtonMail/go-autostart v0.0.0-20210130080809-00ed301c8e9a h1:D+aZah+k14Gn6kmL7eKxoo/4Dr/lK3ChBcwce2+SQP4=
 github.com/ProtonMail/go-autostart v0.0.0-20210130080809-00ed301c8e9a/go.mod h1:oTGdE7/DlWIr23G0IKW3OXK9wZ5Hw1GGiaJFccTvZi4=
 github.com/ProtonMail/go-crypto v0.0.0-20230321155629-9a39f2531310/go.mod h1:8TI4H3IbrackdNgv+92dI+rhpCaLqM0IfpgCgenFvRE=
@@ -45,8 +47,6 @@ github.com/ProtonMail/go-message v0.13.1-0.20240919135104-3bc88e6a9423 h1:p8nBDx
 github.com/ProtonMail/go-message v0.13.1-0.20240919135104-3bc88e6a9423/go.mod h1:NBAn21zgCJ/52WLDyed18YvYFm5tEoeDauubFqLokM4=
 github.com/ProtonMail/go-mime v0.0.0-20230322103455-7d82a3887f2f h1:tCbYj7/299ekTTXpdwKYF8eBlsYsDVoggDAuAjoK66k=
 github.com/ProtonMail/go-mime v0.0.0-20230322103455-7d82a3887f2f/go.mod h1:gcr0kNtGBqin9zDW9GOHcVntrwnjrK+qdJ06mWYBybw=
-github.com/ProtonMail/go-proton-api v0.4.1-0.20250121114701-67bd01ad0bc3 h1:YYnLBVcg7WrEbYVmF1PBr4AEQlob9rCphsMHAmF4CAo=
-github.com/ProtonMail/go-proton-api v0.4.1-0.20250121114701-67bd01ad0bc3/go.mod h1:RYgagBFkA3zFrSt7/vviFFwjZxBo6pGzcTwFsLwsnyc=
 github.com/ProtonMail/go-proton-api v0.4.1-0.20250217140732-2e531f21de4c h1:dxnbB+ov77BDj1LC35fKZ14hLoTpU6OTpZySwxarVx0=
 github.com/ProtonMail/go-proton-api v0.4.1-0.20250217140732-2e531f21de4c/go.mod h1:RYgagBFkA3zFrSt7/vviFFwjZxBo6pGzcTwFsLwsnyc=
 github.com/ProtonMail/go-smtp v0.0.0-20231109081432-2b3d50599865 h1:EP1gnxLL5Z7xBSymE9nSTM27nRYINuvssAtDmG0suD8=

internal/services/imapservice/connector.go

@@ -257,7 +257,7 @@ func (s *Connector) DeleteMailbox(ctx context.Context, _ connector.IMAPStateWrit
 	wLabels := s.labels.Write()
 	defer wLabels.Close()
 
-	wLabels.Delete(string(mboxID))
+	wLabels.Delete(string(mboxID), "connectorDeleteMailbox")
 
 	return nil
 }
@@ -555,7 +555,7 @@ func (s *Connector) createLabel(ctx context.Context, name []string) (imap.Mailbo
 	wLabels := s.labels.Write()
 	defer wLabels.Close()
 
-	wLabels.SetLabel(label.ID, label)
+	wLabels.SetLabel(label.ID, label, "connectorCreateLabel")
 
 	return toIMAPMailbox(label, s.flags, s.permFlags, s.attrs), nil
 }
@@ -593,7 +593,7 @@ func (s *Connector) createFolder(ctx context.Context, name []string) (imap.Mailb
 	}
 
 	// Add label to list so subsequent sub folder create requests work correct.
-	wLabels.SetLabel(label.ID, label)
+	wLabels.SetLabel(label.ID, label, "connectorCreateFolder")
 
 	return toIMAPMailbox(label, s.flags, s.permFlags, s.attrs), nil
 }
@@ -619,7 +619,7 @@ func (s *Connector) updateLabel(ctx context.Context, labelID imap.MailboxID, nam
 	wLabels := s.labels.Write()
 	defer wLabels.Close()
 
-	wLabels.SetLabel(label.ID, update)
+	wLabels.SetLabel(label.ID, update, "connectorUpdateLabel")
 
 	return nil
 }
@@ -660,7 +660,7 @@ func (s *Connector) updateFolder(ctx context.Context, labelID imap.MailboxID, na
 		return err
 	}
 
-	wLabels.SetLabel(label.ID, update)
+	wLabels.SetLabel(label.ID, update, "connectorUpdateFolder")
 
 	return nil
 }

internal/services/imapservice/connector_test.go

@@ -43,7 +43,7 @@ func TestFixGODT3003Labels(t *testing.T) {
 		Path:     []string{"bar", "Foo"},
 		Color:    "",
 		Type:     proton.LabelTypeFolder,
-	})
+	}, "")
 
 	wr.SetLabel("0", proton.Label{
 		ID:       "0",
@@ -52,7 +52,7 @@ func TestFixGODT3003Labels(t *testing.T) {
 		Path:     []string{"Inbox"},
 		Color:    "",
 		Type:     proton.LabelTypeSystem,
-	})
+	}, "")
 
 	wr.SetLabel("bar", proton.Label{
 		ID:       "bar",
@@ -61,7 +61,7 @@ func TestFixGODT3003Labels(t *testing.T) {
 		Path:     []string{"bar"},
 		Color:    "",
 		Type:     proton.LabelTypeFolder,
-	})
+	}, "")
 
 	wr.SetLabel("my_label", proton.Label{
 		ID:       "my_label",
@@ -70,7 +70,7 @@ func TestFixGODT3003Labels(t *testing.T) {
 		Path:     []string{"MyLabel"},
 		Color:    "",
 		Type:     proton.LabelTypeLabel,
-	})
+	}, "")
 
 	wr.SetLabel("my_label2", proton.Label{
 		ID:       "my_label2",
@@ -79,7 +79,7 @@ func TestFixGODT3003Labels(t *testing.T) {
 		Path:     []string{labelPrefix, "MyLabel2"},
 		Color:    "",
 		Type:     proton.LabelTypeLabel,
-	})
+	}, "")
 	wr.Close()
 
 	mboxs := []imap.MailboxNoAttrib{
@@ -133,7 +133,7 @@ func TestFixGODT3003Labels_Noop(t *testing.T) {
 		Path:     []string{folderPrefix, "bar", "Foo"},
 		Color:    "",
 		Type:     proton.LabelTypeFolder,
-	})
+	}, "")
 
 	wr.SetLabel("0", proton.Label{
 		ID:       "0",
@@ -142,7 +142,7 @@ func TestFixGODT3003Labels_Noop(t *testing.T) {
 		Path:     []string{"Inbox"},
 		Color:    "",
 		Type:     proton.LabelTypeSystem,
-	})
+	}, "")
 
 	wr.SetLabel("bar", proton.Label{
 		ID:       "bar",
@@ -151,7 +151,7 @@ func TestFixGODT3003Labels_Noop(t *testing.T) {
 		Path:     []string{folderPrefix, "bar"},
 		Color:    "",
 		Type:     proton.LabelTypeFolder,
-	})
+	}, "")
 
 	wr.SetLabel("my_label", proton.Label{
 		ID:       "my_label",
@@ -160,7 +160,7 @@ func TestFixGODT3003Labels_Noop(t *testing.T) {
 		Path:     []string{labelPrefix, "MyLabel"},
 		Color:    "",
 		Type:     proton.LabelTypeLabel,
-	})
+	}, "")
 
 	wr.SetLabel("my_label2", proton.Label{
 		ID:       "my_label2",
@@ -169,7 +169,7 @@ func TestFixGODT3003Labels_Noop(t *testing.T) {
 		Path:     []string{labelPrefix, "MyLabel2"},
 		Color:    "",
 		Type:     proton.LabelTypeLabel,
-	})
+	}, "")
 	wr.Close()
 
 	mboxs := []imap.MailboxNoAttrib{

internal/services/imapservice/server_manager.go

@@ -34,6 +34,8 @@ type IMAPServerManager interface {
 	) error
 
 	RemoveIMAPUser(ctx context.Context, deleteData bool, provider GluonIDProvider, addrID ...string) error
+
+	LogRemoteLabelIDs(ctx context.Context, provider GluonIDProvider, addrID ...string) error
 }
 
 type NullIMAPServerManager struct{}
@@ -57,6 +59,14 @@ func (n NullIMAPServerManager) RemoveIMAPUser(
 	return nil
 }
 
+func (n NullIMAPServerManager) LogRemoteLabelIDs(
+	_ context.Context,
+	_ GluonIDProvider,
+	_ ...string,
+) error {
+	return nil
+}
+
 func NewNullIMAPServerManager() *NullIMAPServerManager {
 	return &NullIMAPServerManager{}
 }

internal/services/imapservice/service.go

@@ -355,6 +355,12 @@ func (s *Service) run(ctx context.Context) { //nolint gocyclo
 
 			case *onBadEventReq:
 				s.log.Debug("Bad Event Request")
+				// // Log remote label IDs stored in the local labelMap.
+				s.labels.LogLabels()
+				// Log the remote label IDs store in Gluon.
+				if err := s.logRemoteMailboxIDsFromServer(ctx, s.connectors); err != nil {
+					s.log.Warnf("Could not obtain remote mailbox IDs from server: %v", err)
+				}
 				err := s.removeConnectorsFromServer(ctx, s.connectors, false)
 				req.Reply(ctx, nil, err)
 
@@ -572,6 +578,16 @@ func (s *Service) addConnectorsToServer(ctx context.Context, connectors map[stri
 	return nil
 }
 
+func (s *Service) logRemoteMailboxIDsFromServer(ctx context.Context, connectors map[string]*Connector) error {
+	addrIDs := make([]string, 0, len(connectors))
+
+	for _, c := range connectors {
+		addrIDs = append(addrIDs, c.addrID)
+	}
+
+	return s.serverManager.LogRemoteLabelIDs(ctx, s.gluonIDProvider, addrIDs...)
+}
+
 func (s *Service) removeConnectorsFromServer(ctx context.Context, connectors map[string]*Connector, deleteData bool) error {
 	addrIDs := make([]string, 0, len(connectors))
 

internal/services/imapservice/service_label_events.go

@@ -85,7 +85,7 @@ func onLabelCreated(ctx context.Context, s *Service, event proton.LabelEvent) []
 	wr := s.labels.Write()
 	defer wr.Close()
 
-	wr.SetLabel(event.Label.ID, event.Label)
+	wr.SetLabel(event.Label.ID, event.Label, "onLabelCreated")
 
 	for _, updateCh := range maps.Values(s.connectors) {
 		update := newMailboxCreatedUpdate(imap.MailboxID(event.ID), GetMailboxName(event.Label))
@@ -121,7 +121,7 @@ func onLabelUpdated(ctx context.Context, s *Service, event proton.LabelEvent) ([
 
 		// Only update the label if it exists; we don't want to create it as a client may have just deleted it.
 		if _, ok := wr.GetLabel(label.ID); ok {
-			wr.SetLabel(label.ID, event.Label)
+			wr.SetLabel(label.ID, event.Label, "onLabelUpdatedLabelEventID")
 		}
 
 		// API doesn't notify us that the path has changed. We need to fetch it again.
@@ -134,7 +134,7 @@ func onLabelUpdated(ctx context.Context, s *Service, event proton.LabelEvent) ([
 		}
 
 		// Update the label in the map.
-		wr.SetLabel(apiLabel.ID, apiLabel)
+		wr.SetLabel(apiLabel.ID, apiLabel, "onLabelUpdatedApiID")
 
 		// Notify the IMAP clients.
 		for _, updateCh := range maps.Values(s.connectors) {
@@ -176,7 +176,7 @@ func onLabelDeleted(ctx context.Context, s *Service, event proton.LabelEvent) []
 	wr := s.labels.Write()
 	wr.Close()
 
-	wr.Delete(event.ID)
+	wr.Delete(event.ID, "onLabelDeleted")
 
 	s.eventPublisher.PublishEvent(ctx, events.UserLabelDeleted{
 		UserID:  s.identityState.UserID(),

internal/services/imapservice/shared_labels.go

@@ -22,6 +22,8 @@ import (
 
 	"github.com/ProtonMail/go-proton-api"
 	"github.com/ProtonMail/proton-bridge/v3/internal/usertypes"
+	"github.com/bradenaw/juniper/xslices"
+	"github.com/sirupsen/logrus"
 	"golang.org/x/exp/maps"
 )
 
@@ -42,8 +44,8 @@ type labelsRead interface {
 
 type labelsWrite interface {
 	labelsRead
-	SetLabel(id string, label proton.Label)
+	SetLabel(id string, label proton.Label, actionSource string)
-	Delete(id string)
+	Delete(id string, actionSource string)
 }
 
 type rwLabels struct {
@@ -51,6 +53,22 @@ type rwLabels struct {
 	labels labelMap
 }
 
+func (r *rwLabels) LogLabels() {
+	r.lock.RLock()
+	defer r.lock.RUnlock()
+
+	remoteLabelIDs := make([]string, len(r.labels))
+	i := 0
+	for labelID := range r.labels {
+		remoteLabelIDs[i] = labelID
+		i++
+	}
+
+	logrus.WithFields(logrus.Fields{
+		"remoteLabelIDs": remoteLabelIDs,
+	}).Debug("Logging remote label IDs stored in labelMap")
+}
+
 func (r *rwLabels) Read() labelsRead {
 	r.lock.RLock()
 	return &rwLabelsRead{rw: r}
@@ -75,6 +93,15 @@ func (r *rwLabels) SetLabels(labels []proton.Label) {
 	r.lock.Lock()
 	defer r.lock.Unlock()
 
+	labelIDs := xslices.Map(labels, func(label proton.Label) string {
+		return label.ID
+	})
+
+	logrus.WithFields(logrus.Fields{
+		"pkg":      "rwLabels",
+		"labelIDs": labelIDs,
+	}).Info("Setting labels")
+
 	r.labels = usertypes.GroupBy(labels, func(label proton.Label) string { return label.ID })
 }
 
@@ -123,10 +150,20 @@ func (r rwLabelsWrite) GetLabels() []proton.Label {
 	return r.rw.getLabelsUnsafe()
 }
 
-func (r rwLabelsWrite) SetLabel(id string, label proton.Label) {
+func (r rwLabelsWrite) SetLabel(id string, label proton.Label, actionSource string) {
+	logAction("SetLabel", actionSource, label.ID)
 	r.rw.labels[id] = label
 }
 
-func (r rwLabelsWrite) Delete(id string) {
+func (r rwLabelsWrite) Delete(id string, actionSource string) {
+	logAction("Delete", actionSource, id)
 	delete(r.rw.labels, id)
 }
+
+func logAction(actionType, actionSource, labelID string) {
+	logrus.WithFields(logrus.Fields{
+		"pkg":          "rwLabelsWrite",
+		"actionSource": actionSource,
+		"labelID":      labelID,
+	}).Debug(actionType)
+}

internal/services/imapsmtpserver/service.go

@@ -170,6 +170,14 @@ func (sm *Service) SetGluonDir(ctx context.Context, gluonDir string) error {
 	return err
 }
 
+func (sm *Service) LogRemoteLabelIDs(ctx context.Context, provider imapservice.GluonIDProvider, addrID ...string) error {
+	_, err := sm.requests.Send(ctx, &smRequestLogRemoteMailboxIDs{
+		addrID:     addrID,
+		idProvider: provider,
+	})
+	return err
+}
+
 func (sm *Service) RemoveIMAPUser(ctx context.Context, deleteData bool, provider imapservice.GluonIDProvider, addrID ...string) error {
 	_, err := sm.requests.Send(ctx, &smRequestRemoveIMAPUser{
 		withData:   deleteData,
@@ -244,6 +252,10 @@ func (sm *Service) run(ctx context.Context, subscription events.Subscription) {
 					sm.handleLoadedUserCountChange(ctx)
 				}
 
+			case *smRequestLogRemoteMailboxIDs:
+				err := sm.logRemoteLabelIDsFromServer(ctx, r.addrID, r.idProvider)
+				request.Reply(ctx, nil, err)
+
 			case *smRequestRemoveIMAPUser:
 				err := sm.handleRemoveIMAPUser(ctx, r.withData, r.idProvider, r.addrID...)
 				request.Reply(ctx, nil, err)
@@ -311,6 +323,35 @@ func (sm *Service) handleAddIMAPUser(ctx context.Context,
 	return sm.handleAddIMAPUserImpl(ctx, connector, addrID, idProvider, syncStateProvider)
 }
 
+func (sm *Service) logRemoteLabelIDsFromServer(ctx context.Context, addrIDs []string, idProvider imapservice.GluonIDProvider) error {
+	if sm.imapServer == nil {
+		return fmt.Errorf("no imap server instance running")
+	}
+
+	for _, addrID := range addrIDs {
+		gluonID, ok := idProvider.GetGluonID(addrID)
+		if !ok {
+			sm.log.Warnf("Could not find Gluon ID for addrID %v", addrID)
+			continue
+		}
+
+		log := sm.log.WithFields(logrus.Fields{
+			"addrID":  addrID,
+			"gluonID": gluonID,
+		})
+
+		remoteLabelIDs, err := sm.imapServer.GetAllMailboxRemoteIDsForUser(ctx, gluonID)
+		if err != nil {
+			log.WithError(err).Error("Could not obtain remote label IDs for user")
+			continue
+		}
+
+		log.WithField("remoteLabelIDs", remoteLabelIDs).Debug("Logging Gluon remote Label IDs")
+	}
+
+	return nil
+}
+
 func (sm *Service) handleAddIMAPUserImpl(ctx context.Context,
 	connector connector.Connector,
 	addrID string,
@@ -723,3 +764,8 @@ type smRequestAddSMTPAccount struct {
 type smRequestRemoveSMTPAccount struct {
 	account *bridgesmtp.Service
 }
+
+type smRequestLogRemoteMailboxIDs struct {
+	addrID     []string
+	idProvider imapservice.GluonIDProvider
+}