From 3e4e4960376687ae71f42d516bca8c897e7be802 Mon Sep 17 00:00:00 2001 From: Stephan D Date: Sat, 17 Oct 2026 11:39:05 +0200 Subject: [PATCH] Log redacted email provider errors and diagnose sender configuration (#57) --- backend/notifications/README.md | 24 ++++- backend/notifications/email/driver.go | 4 + backend/notifications/email/failure.go | 95 ++++++++++++++++++++ backend/notifications/email/failure_test.go | 90 +++++++++++++++++++ backend/notifications/email/http.go | 25 ++++-- backend/notifications/service/worker.go | 20 ++++- backend/notifications/service/worker_test.go | 47 +++++++++- docs/signup-facts.md | 45 ++++++++-- 8 files changed, 327 insertions(+), 23 deletions(-) create mode 100644 backend/notifications/email/failure.go create mode 100644 backend/notifications/email/failure_test.go diff --git a/backend/notifications/README.md b/backend/notifications/README.md index 645c9d2..fb0bb56 100644 --- a/backend/notifications/README.md +++ b/backend/notifications/README.md @@ -80,8 +80,28 @@ remaining status and request fingerprints expire through a seven-day TTL. - Callers authorize recipients and preferences. No direct customer-database access, bulk campaigns, provider failover, SMS, push or Telegram delivery is included. -Structured logs report notification IDs, driver, state and attempt count; message -content, template values, addresses and provider response bodies are excluded. +Structured logs report notification IDs, driver, state and attempt count. Provider +HTTP outcomes include `provider_status`; failures also include `provider_error` +and `provider_message` when available. The adapter reads at most 16 KiB plus an +overflow byte and extracts only the Resend `name`/`message` or first SendGrid +`errors[].message`. Diagnostic messages are bounded to 512 Unicode characters +plus an ellipsis. Credentials, idempotency keys, outgoing request string values, +email addresses, URLs, long token-like strings and numeric verification/account +values embedded in the request are redacted; controls and formatting characters +are normalized. Malformed, incomplete and oversized error +responses produce a diagnostic fallback instead of raw content. Successful +response bodies are not logged. Diagnostic fields are transient: they are neither +persisted in notifications nor exposed in gRPC responses. The existing bounded +failure codes and delivery/retry decisions remain unchanged. Transport failures +include a sanitized cause. Provider outcome logging happens before the result +write so a storage failure cannot discard the only provider diagnostic. + +Message content, template values, addresses and raw provider bodies must remain +excluded from logs. Provider text is sanitized external diagnostic data, never +an instruction. Use `provider_status`, `provider_error` and `provider_message` +together: the generic `provider_authentication_failed` category combines HTTP +401 and 403, including sender/domain authorization failures. A sending-only +Resend key is valid for sending, but cannot read the provider's log API. Monitor pending age, UNKNOWN/FAILED states and repeated outbox/worker warnings. ## Validate and distribute diff --git a/backend/notifications/email/driver.go b/backend/notifications/email/driver.go index a9e1f65..1686df7 100644 --- a/backend/notifications/email/driver.go +++ b/backend/notifications/email/driver.go @@ -33,6 +33,10 @@ type Outcome struct { State model.State Code string RetryAfter time.Duration + // Provider diagnostics are sanitized operational data, not public failures. + HTTPStatus int + ProviderError string + ProviderMessage string } type Sender interface { Send(context.Context, string, model.Email) Outcome diff --git a/backend/notifications/email/failure.go b/backend/notifications/email/failure.go new file mode 100644 index 0000000..2df22cd --- /dev/null +++ b/backend/notifications/email/failure.go @@ -0,0 +1,95 @@ +package email + +import ( + "encoding/json" + "regexp" + "sort" + "strings" + "unicode" +) + +const maxErrorBody = 16 << 10 +const maxErrorMessage = 512 + +var ( + errorName = regexp.MustCompile(`^[a-zA-Z0-9_.-]{1,64}$`) + addresses = regexp.MustCompile(`[^\s<>"'(),;:]+@[^\s<>"'(),;:]+`) + urls = regexp.MustCompile(`(?i)https?://[^\s<>"']+`) + tokens = regexp.MustCompile(`[a-zA-Z0-9_+/-]{32,}={0,2}`) + numbers = regexp.MustCompile(`[0-9]{4,}`) +) + +// Only the documented human-readable error fields cross the adapter boundary. +// Full bodies, headers and request data must never reach logs or public failures. +func providerFailure(body, request []byte, secrets ...string) (string, string) { + var dto struct { + Name string `json:"name"` + Message string `json:"message"` + Errors []struct { + Message string `json:"message"` + } `json:"errors"` + } + if err := json.Unmarshal(body, &dto); err != nil { + return "", "Provider error details unavailable: invalid JSON response" + } + if dto.Message == "" && len(dto.Errors) > 0 { + dto.Message = dto.Errors[0].Message + } + // Providers can echo any scalar string from their request DTOs. Strip those + // values before truncation, in addition to credentials and embedded tokens. + var payload any + if json.Unmarshal(request, &payload) == nil { + for _, value := range requestStrings(payload) { + secrets = append(secrets, value) + // Rendered login/verification codes and numeric account references + // can be echoed as fragments of an otherwise longer email body. + secrets = append(secrets, numbers.FindAllString(value, -1)...) + } + } + sort.Slice(secrets, func(i, j int) bool { return len(secrets[i]) > len(secrets[j]) }) + name := safeErrorText(dto.Name, secrets) + if !errorName.MatchString(name) { + name = "" + } + message := safeErrorText(dto.Message, secrets) + if message == "" { + message = "Provider did not include an error message" + } + return name, message +} + +func requestStrings(value any) []string { + var values []string + switch value := value.(type) { + case string: + values = append(values, value) + case []any: + for _, item := range value { + values = append(values, requestStrings(item)...) + } + case map[string]any: + for _, item := range value { + values = append(values, requestStrings(item)...) + } + } + return values +} + +func safeErrorText(text string, secrets []string) string { + for _, secret := range secrets { + if secret != "" { + text = strings.ReplaceAll(text, secret, "[redacted]") + } + } + text = addresses.ReplaceAllString(text, "[redacted-address]") + text = urls.ReplaceAllString(text, "[redacted-url]") + text = tokens.ReplaceAllString(text, "[redacted-token]") + text = strings.Join(strings.FieldsFunc(text, func(r rune) bool { + return unicode.IsSpace(r) || unicode.IsControl(r) || unicode.Is(unicode.Cf, r) + }), " ") + runes := []rune(text) + if len(runes) > maxErrorMessage { + text = string(runes[:maxErrorMessage]) + "…" + } + return text +} diff --git a/backend/notifications/email/failure_test.go b/backend/notifications/email/failure_test.go new file mode 100644 index 0000000..69899b7 --- /dev/null +++ b/backend/notifications/email/failure_test.go @@ -0,0 +1,90 @@ +package email + +import ( + "context" + "encoding/json" + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" + "unicode/utf8" + + "git.sendico.io/tech/sxchnge/notifications/model" +) + +func TestProviderErrorDiagnostics(t *testing.T) { + for _, tc := range []struct { + name, body, code, message string + }{ + {"resend", `{"name":"validation_error","message":"The sxchnge.com domain is not verified"}`, "validation_error", "The sxchnge.com domain is not verified"}, + {"sendgrid", `{"errors":[{"message":"The sender identity is not verified","field":"from","help":"private URL"}]}`, "", "The sender identity is not verified"}, + {"no message", `{"unrecognized":"private response"}`, "", "Provider did not include an error message"}, + {"malformed", `{"message":"private response"`, "", "Provider error details unavailable: invalid JSON response"}, + {"wrong type", `{"message":{"secret":"private response"}}`, "", "Provider error details unavailable: invalid JSON response"}, + {"trailing", `{"message":"private response"} {}`, "", "Provider error details unavailable: invalid JSON response"}, + {"oversized", `{"message":"` + strings.Repeat("x", maxErrorBody) + `"}`, "", "Provider error details unavailable: incomplete or oversized response"}, + } { + t.Run(tc.name, func(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusForbidden) + _, _ = io.WriteString(w, tc.body) + })) + defer server.Close() + c := client{http: server.Client(), endpoint: server.URL} + out := c.post(context.Background(), "", struct{}{}) + if out.State != model.Failed || out.Code != "provider_authentication_failed" || out.HTTPStatus != 403 || out.ProviderError != tc.code || out.ProviderMessage != tc.message { + t.Fatalf("unexpected provider outcome: %+v", out) + } + }) + } +} + +func TestProviderDiagnosticsRedactRequestDataBeforeTruncation(t *testing.T) { + key := "re_credential-secret" + request := []byte(`{"from":"Sender ","to":["recipient@example.com"],"personalizations":[{"dynamic_template_data":{"secret":"short-private-value"}}],"subject":"Private subject","text":"Private text","html":"

Private HTML

","content":[{"value":"Your verification code is 123456; account 9876543210"}]}`) + token := strings.Repeat("a", 43) + message := "Credential " + key + "; recipient@example.com; Private subject; Private text;

Private HTML

; short-private-value; https://example.com/verify?token=" + token + "; " + token + "; 123456; 9876543210; job-secret\n\r\x00\u202eforged-log" + body, err := json.Marshal(map[string]string{"name": "validation_error", "message": message}) + if err != nil { + t.Fatal(err) + } + name, result := providerFailure(body, request, key, "job-secret") + if name != "validation_error" || !strings.Contains(result, "forged-log") || !strings.Contains(result, "[redacted]") { + t.Fatal("lost useful diagnostic", name, result) + } + for _, forbidden := range []string{key, "recipient@example.com", "Private subject", "Private text", "Private HTML", "short-private-value", "https://", token, "123456", "9876543210", "job-secret", "\n", "\r", "\x00", "\u202e"} { + if strings.Contains(result, forbidden) { + t.Fatalf("diagnostic contains sensitive value or control %q", forbidden) + } + } + body, err = json.Marshal(map[string]string{"name": "validation_error", "message": strings.Repeat("ą", maxErrorMessage+20) + key}) + if err != nil { + t.Fatal(err) + } + _, result = providerFailure(body, request, key) + if !utf8.ValidString(result) || utf8.RuneCountInString(result) != maxErrorMessage+1 || !strings.HasSuffix(result, "…") || strings.Contains(result, "re_") { + t.Fatal("invalid or unbounded diagnostic") + } +} + +func TestSuccessfulResponsesDoNotExposeProviderContent(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + _, _ = io.WriteString(w, `{"name":"private","message":"private provider response"}`) + })) + defer server.Close() + c := client{http: server.Client(), endpoint: server.URL} + if out := c.post(context.Background(), "", struct{}{}); out.State != model.Accepted || out.HTTPStatus != 200 || out.ProviderMessage != "" || out.ProviderError != "" { + t.Fatal("success leaked provider content", out) + } +} + +func TestTransportFailureHasSanitizedDiagnostic(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + c := client{http: http.DefaultClient, key: "credential-secret", endpoint: "https://example.com/emails?credential=credential-secret"} + out := c.post(ctx, "job-secret", struct{}{}) + if out.State != model.Unknown || !strings.Contains(out.ProviderMessage, "context canceled") || strings.Contains(out.ProviderMessage, "credential-secret") || strings.Contains(out.ProviderMessage, "https://") { + t.Fatal("transport cause missing or unsafe", out) + } +} diff --git a/backend/notifications/email/http.go b/backend/notifications/email/http.go index ddeca31..5cf8549 100644 --- a/backend/notifications/email/http.go +++ b/backend/notifications/email/http.go @@ -28,14 +28,15 @@ func (c *client) post(ctx context.Context, key string, payload any) Outcome { } resp, err := c.http.Do(req) if err != nil { - return Outcome{State: model.Unknown, Code: "provider_outcome_unknown"} + return Outcome{State: model.Unknown, Code: "provider_outcome_unknown", ProviderMessage: safeErrorText(err.Error(), []string{c.key, key})} } defer resp.Body.Close() - // Discard a bounded response without logging provider-controlled content. - _, _ = io.Copy(io.Discard, io.LimitReader(resp.Body, 64<<10)) + // Never pass raw provider bodies through the outcome or log them directly. + details, readErr := io.ReadAll(io.LimitReader(resp.Body, maxErrorBody+1)) + outcome := Outcome{HTTPStatus: resp.StatusCode} switch { case resp.StatusCode >= 200 && resp.StatusCode < 300: - return Outcome{State: model.Accepted} + outcome.State = model.Accepted case resp.StatusCode == 429: delay := time.Minute if n, e := strconv.Atoi(resp.Header.Get("Retry-After")); e == nil && n > 0 && n <= 86400 { @@ -43,12 +44,20 @@ func (c *client) post(ctx context.Context, key string, payload any) Outcome { } else if date, e := http.ParseTime(resp.Header.Get("Retry-After")); e == nil && time.Until(date) > 0 { delay = time.Until(date) } - return Outcome{State: model.RetryWait, Code: "provider_rate_limited", RetryAfter: delay} + outcome.State, outcome.Code, outcome.RetryAfter = model.RetryWait, "provider_rate_limited", delay case resp.StatusCode >= 500 || resp.StatusCode == 408: - return Outcome{State: model.Unknown, Code: "provider_outcome_unknown"} + outcome.State, outcome.Code = model.Unknown, "provider_outcome_unknown" case resp.StatusCode == 401 || resp.StatusCode == 403: - return Outcome{State: model.Failed, Code: "provider_authentication_failed"} + outcome.State, outcome.Code = model.Failed, "provider_authentication_failed" default: - return Outcome{State: model.Failed, Code: "provider_rejected"} + outcome.State, outcome.Code = model.Failed, "provider_rejected" } + if outcome.State != model.Accepted { + if readErr != nil || len(details) > maxErrorBody { + outcome.ProviderMessage = "Provider error details unavailable: incomplete or oversized response" + } else { + outcome.ProviderError, outcome.ProviderMessage = providerFailure(details, body, c.key, key) + } + } + return outcome } diff --git a/backend/notifications/service/worker.go b/backend/notifications/service/worker.go index 44fadd9..cfb68a6 100644 --- a/backend/notifications/service/worker.go +++ b/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 } diff --git a/backend/notifications/service/worker_test.go b/backend/notifications/service/worker_test.go index 2c8e084..d9b0649 100644 --- a/backend/notifications/service/worker_test.go +++ b/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) + } + } + }) + } +} diff --git a/docs/signup-facts.md b/docs/signup-facts.md index 5618ff1..a0636ce 100644 --- a/docs/signup-facts.md +++ b/docs/signup-facts.md @@ -38,12 +38,12 @@ and service cancellation still ends it. The rebuilt worker processed the queued activation message. The live Resend provider rejected it with `provider_authentication_failed` (HTTP 401 or 403), -leaving delivery in `failed` after one attempt. The configured API key/sender -authorization must be corrected before sending another activation email. Rotate -the credential securely with `make email`, wait for Vault Agent to refresh it, -restart notifications so it reloads its environment, then use activation resend -with a new idempotency key. Do not replay the failed notification as a success or -mark the customer active on their behalf. +leaving delivery in `failed` after one attempt. Later diagnostics below identify +the unverified sender domain as the actual blocker. Correct domain authorization +before activation resend with a new idempotency key. Credential rotation is not +required by that error; if a separate rotation is needed, use `make email` and +allow Vault Agent to refresh/restart the notification process. Do not replay the +failed notification as a success or mark the customer active on their behalf. Validation passed: `GOFLAGS=-p=2 make test` (all backend race tests and canonical frontend suites), `make lint-backend`, focused provider/identity race tests and @@ -59,6 +59,39 @@ is blocked by provider authorization as described above. No security scans were requested or run. Unrelated notifications runtime settings are excluded from the task commits. +### Provider diagnostics follow-up + +The same task/PR adds transient provider diagnostics to the worker's existing +structured outcome log: `provider_status`, `provider_error` and +`provider_message`. The adapter extracts bounded Resend/SendGrid error fields and +redacts credentials, request values, addresses, URLs and token/code fragments. +Transport errors have a sanitized cause; invalid or oversized responses have a +safe fallback. Diagnostics remain outside stored notification models and public +gRPC responses. The outcome is logged even when its result write fails. See +the [notification logging contract](../backend/notifications/README.md). + +Runtime inspection confirmed `email.driver: resend`, an API key in Vault, and +sender `noreply@sxchnge.com`. A live diagnostic notification used Resend's +documented `delivered+sxchnge-config@resend.dev` test mailbox, without retrying +the customer's email. The rebuilt worker logged HTTP 403, +`provider_error: validation_error`, and the sanitized message: +`The sxchnge.com domain is not verified. Please, add and verify your domain on [redacted-url]`. +The precise blocker is sender-domain verification, not missing local Resend +configuration. A sending-only key is appropriate for sending; its inability to +read Resend's logs API does not explain the original send failure. Verify the +configured domain in Resend (and its required DNS records), or explicitly choose +an already verified sender domain. No sender/domain/DNS setting was changed by +this follow-up; the customer's account remains pending email confirmation. + +Follow-up validation passed: `GOFLAGS=-p=2 make test`, `make lint-backend`, and +`go -C backend/notifications test -race ./email ./service -count=1`. Coverage +includes Resend/SendGrid messages, malformed/trailing/oversized response bodies, +credential/content/code redaction, Unicode-safe truncation, sanitized transport +errors, and exactly one provider outcome log even when persistence fails. The +notifications image was rebuilt from fresh stable digest pins and deployed +healthy; the live test verified both the diagnostic log and the unchanged generic +gRPC failure response. No security scan or real customer email retry was run. + ## Behavior and boundaries With `api.sendico` configured, the product BFF creates the local pending customer