Log redacted email provider errors and diagnose sender configuration (#57)

backend/notifications/service/worker.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"time"
 
+	"git.sendico.io/tech/sxchnge/notifications/email"
 	"git.sendico.io/tech/sxchnge/notifications/model"
 	merrors "git.sendico.io/tech/sxchnge/shared/errors"
 	"go.uber.org/zap"
@@ -23,6 +24,7 @@ func (s *Service) Dispatch(ctx context.Context, id string) (bool, error) {
 	if err != nil {
 		return false, err
 	}
+	var outcome email.Outcome
 	switch {
 	case !n.ExpiresAt.After(now):
 		n.State = model.Expired
@@ -36,7 +38,7 @@ func (s *Service) Dispatch(ctx context.Context, id string) (bool, error) {
 			deadline = n.ExpiresAt
 		}
 		sendCtx, cancel := context.WithDeadline(ctx, deadline)
-		outcome := s.sender.Send(sendCtx, n.ID.Hex(), n.Email)
+		outcome = s.sender.Send(sendCtx, n.ID.Hex(), n.Email)
 		cancel()
 		n.State = outcome.State
 		n.FailureCode = outcome.Code
@@ -62,14 +64,24 @@ func (s *Service) Dispatch(ctx context.Context, id string) (bool, error) {
 	// Persist the result even when shutdown canceled the provider request.
 	finishCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), 5*time.Second)
 	defer cancel()
-	if err = s.repo.Finish(finishCtx, n); err != nil {
-		return true, err
-	}
 	fields := []zap.Field{zap.String("notification_id", n.ID.Hex()), zap.String("driver", n.Driver), zap.String("state", string(n.State)), zap.Uint32("attempts", n.Attempts), zap.String("failure_code", n.FailureCode)}
+	if outcome.HTTPStatus != 0 {
+		fields = append(fields, zap.Int("provider_status", outcome.HTTPStatus))
+	}
+	if outcome.ProviderError != "" {
+		fields = append(fields, zap.String("provider_error", outcome.ProviderError))
+	}
+	if outcome.ProviderMessage != "" {
+		fields = append(fields, zap.String("provider_message", outcome.ProviderMessage))
+	}
+	// Keep the provider outcome observable even if its local result write fails.
 	if n.State == model.Accepted {
 		s.logger.Info("Email accepted by provider", fields...)
 	} else {
 		s.logger.Warn("Email delivery attempt finished", fields...)
 	}
+	if err = s.repo.Finish(finishCtx, n); err != nil {
+		return true, err
+	}
 	return true, nil
 }

backend/notifications/service/worker_test.go

@@ -2,18 +2,23 @@ package service
 
 import (
 	"context"
+	"errors"
+	"fmt"
 	"testing"
 	"time"
 
 	"git.sendico.io/tech/sxchnge/notifications/email"
 	"git.sendico.io/tech/sxchnge/notifications/model"
+	merrors "git.sendico.io/tech/sxchnge/shared/errors"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest/observer"
 )
 
 type workerRepo struct {
 	Repository
-	job   model.Notification
-	saved *model.Notification
+	job       model.Notification
+	saved     *model.Notification
+	finishErr error
 }
 
 func (r *workerRepo) Recover(context.Context, time.Time) error { return nil }
@@ -21,7 +26,10 @@ func (r *workerRepo) Claim(context.Context, string, time.Time) (*model.Notificat
 	n := r.job
 	return &n, nil
 }
-func (r *workerRepo) Finish(_ context.Context, n *model.Notification) error { r.saved = n; return nil }
+func (r *workerRepo) Finish(_ context.Context, n *model.Notification) error {
+	r.saved = n
+	return r.finishErr
+}
 
 type workerSender struct {
 	calls   int
@@ -62,3 +70,36 @@ func TestWorkerTerminalAndRetryOutcomes(t *testing.T) {
 		})
 	}
 }
+
+func TestWorkerLogsProviderFailureOnce(t *testing.T) {
+	for _, failPersistence := range []bool{false, true} {
+		t.Run(fmt.Sprint(failPersistence), func(t *testing.T) {
+			core, logs := observer.New(zap.WarnLevel)
+			repo := &workerRepo{job: model.Notification{Driver: "resend", ExpiresAt: time.Now().Add(time.Hour), Attempts: 1, Email: model.Email{Address: "private@example.com", Subject: "Private subject", Text: "Private text"}}}
+			if failPersistence {
+				repo.finishErr = merrors.ServiceUnavailable("storage offline")
+			}
+			sender := &workerSender{outcome: email.Outcome{State: model.Failed, Code: "provider_authentication_failed", HTTPStatus: 403, ProviderError: "validation_error", ProviderMessage: "The sxchnge.com domain is not verified"}}
+			svc := New(repo, nil, sender, "resend", zap.New(core))
+			if _, err := svc.Dispatch(context.Background(), "id"); !errors.Is(err, repo.finishErr) {
+				t.Fatal("unexpected persistence error", err)
+			}
+			entries := logs.All()
+			if len(entries) != 1 || entries[0].Message != "Email delivery attempt finished" {
+				t.Fatal("expected one provider outcome log", entries)
+			}
+			fields := entries[0].ContextMap()
+			if fields["provider_status"] != int64(403) || fields["provider_error"] != "validation_error" || fields["provider_message"] != "The sxchnge.com domain is not verified" {
+				t.Fatal("provider diagnostic missing", fields)
+			}
+			if repo.saved.FailureCode != "provider_authentication_failed" {
+				t.Fatal("public failure code changed", repo.saved.FailureCode)
+			}
+			for _, field := range []string{"address", "email", "subject", "text", "html", "parameters"} {
+				if _, ok := fields[field]; ok {
+					t.Fatalf("private notification field %s logged", field)
+				}
+			}
+		})
+	}
+}