Files
silo-server/internal/notifications/webhook_sender.go
203a18ae83 feat(observability): OpenTelemetry logs+traces with secret redaction and slog standardization (#290)
* feat(observability): OpenTelemetry logs+traces with secret redaction

Part of #265. Adds opt-in OpenTelemetry (logs + traces) alongside the existing
stderr + opslog pipeline, plus secret redaction on all sinks. Default-off: with
no OTEL_* / SILO_OTEL_ENABLED config, behavior is unchanged.

Bootstrap (internal/telemetry):
- Setup() builds one shared resource, a TracerProvider (parent-based trace-id
  ratio sampler), a LoggerProvider, and the W3C TraceContext+Baggage propagator
  from env. It installs NO MeterProvider — metrics stay on Prometheus, and the
  built-in no-op global MeterProvider keeps the trace instrumentation libs from
  double-emitting. Shutdown is deferred with a flush timeout.
- Logs are bridged via otelslog fan-out (slog.MultiHandler), level-gated by the
  shared LevelVar and best-effort so a failing collector can't break the console
  or DB branches. stderr + opslog stay untouched.

Secret redaction (internal/logredact):
- A slog.Handler masks secret-keyed attributes (password, token, api_key,
  authorization, cookie, ...) — including .With-bound attrs, nested groups,
  secret-keyed group subtrees, and values behind a LogValuer — on the console
  and OTLP sinks, with a no-op fast path when a record has no secret keys.
  opslog.shouldRedact delegates to logredact.SecretKey so all sinks share one
  marker list.

Rotation is infra-managed (no custom file sink): container runtime for stderr,
collector/backend for OTLP, opslog partition-pruning for the DB. Documented in
docs/architecture/observability.md.

Verification: go build ./..., go vet, gofmt -l — clean; go test
./internal/telemetry/ ./internal/logredact/ -race pass.

AI-use disclosure: implemented with AI assistance (Claude Code), including
adversarial reviews that hardened the bootstrap and fixed two redaction leak
paths; reviewed by the author.

* refactor(observability): slog context+component sweep, sloglint gate (phase 3)

Part of #265. Builds on the OTel bootstrap + redaction commit.

Standardizes every log call site onto the context-carrying slog variants so
records correlate with the active OpenTelemetry trace, and locks the standard
in with a machine gate so future code (human- or AI-authored) can't drift back.

- Call-site sweep: converted the remaining slog.<Level>(...) calls to the
  slog.<Level>Context(ctx, ...) form wherever a context.Context is in scope
  (background/init calls with no ctx are left as-is), across 183 files. Applied
  via a type-aware AST codemod. Log levels and message strings are preserved
  verbatim; a component attr (canonical per-package name) is added to direct
  package-level slog calls. Bound-logger calls keep their existing .With
  bindings. The main.go and telemetry package conversions rode with their file
  in the previous commit to keep each file within a single commit.
- Enforcement (.golangci.yml): enable sloglint with context=scope, static-msg,
  key-naming-case=snake, no-mixed-args. After the sweep all four report zero
  violations repo-wide (tests included), so make lint / CI now blocks any
  regression to the non-context form. The gate ships with the sweep because it
  cannot be green until the legacy sites are converted.

Metrics remain on Prometheus; no behavior change to /metrics or Grafana.

Verification: go build ./..., go vet ./..., gofmt -l — clean; sloglint (all 4
rules) 0 violations repo-wide; log levels verified unchanged.

AI-use disclosure: implemented with AI assistance (Claude Code), including the
codemod; reviewed by the author.

* fix(observability): honor per-signal OTLP protocol and secret WithGroup names

Two Codex review findings on PR #290:

- telemetry: OTEL_EXPORTER_OTLP_{TRACES,LOGS}_PROTOCOL now override the
  generic OTEL_EXPORTER_OTLP_PROTOCOL per signal, so mixed collector
  setups (e.g. HTTP logs + gRPC traces) build the right exporter.
- logredact: entering a group whose name is secret-bearing (e.g.
  WithGroup("authorization")) now masks every leaf in that subtree,
  matching how slog.Group("authorization", ...) is masked as a whole.

* fix(observability): address review feedback on telemetry bootstrap

- Telemetry setup failure no longer kills boot: Setup returns usable
  no-op providers alongside the error and main logs and continues with
  telemetry disabled, honoring the best-effort contract.
- Honor OTEL_TRACES_SAMPLER (always_on/off, traceidratio, parentbased_*
  variants); unsupported values fall back to parentbased_traceidratio.
- Attach node identity as semconv service.instance.id instead of the
  non-semconv node.name.
- Rename opslog retention-scope log attrs to target_component/target_level
  so they no longer collide with the canonical component routing key, and
  tag those lines with component=opslog.
- Fix stale levelGated comment casing; use WarnContext in the telemetry
  shutdown defer; document the LogValuer double-resolve on the redaction
  slow path.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

---------

Co-authored-by: Quick <31828688+Quick104@users.noreply.github.com>
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
2026-07-09 08:53:52 -04:00

332 lines
11 KiB
Go

package notifications
import (
"context"
"encoding/json"
"fmt"
"log/slog"
"net/http"
"sync"
"time"
"github.com/Silo-Server/silo-server/internal/secret"
"github.com/oklog/ulid/v2"
)
// webhookRetrySchedule holds the cumulative delay since the first attempt
// (docs/superpowers/plans/notifications/04, "Retry schedule"). Index N is the
// delay before attempt N+1; after the last attempt fails, the webhook is
// auto-disabled.
var webhookRetrySchedule = []time.Duration{
0,
30 * time.Second,
2 * time.Minute,
10 * time.Minute,
30 * time.Minute,
2 * time.Hour,
6 * time.Hour,
12 * time.Hour,
18 * time.Hour,
24 * time.Hour,
}
const webhookMaxAttempts = 10
// webhookRetryDelay returns how long to wait after a retryable failure of
// attempt N (1-based) before the next attempt, or ok=false when the schedule
// is exhausted.
func webhookRetryDelay(completedAttempt int) (time.Duration, bool) {
if completedAttempt < 1 || completedAttempt >= webhookMaxAttempts {
return 0, false
}
return webhookRetrySchedule[completedAttempt] - webhookRetrySchedule[completedAttempt-1], true
}
// retryableHTTPStatus reports whether an HTTP failure status is worth
// retrying. Non-retryable 4xx responses are deterministic destination-side
// rejections; 408/425/429 are the transient exceptions.
func retryableHTTPStatus(status int) bool {
if status == 0 || status >= 500 {
return true
}
switch status {
case http.StatusRequestTimeout, http.StatusTooEarly, http.StatusTooManyRequests:
return true
default:
return status < 400
}
}
const autoDisableConsecutive4xx = 3
// webhookSender owns the actual delivery of claimed attempts. It is shared
// by the post-commit dispatcher and the retry worker so both paths apply the
// same retry, auto-disable, and notification rules.
type webhookSender struct {
webhooks *WebhookRepository
deliveries *DeliveryRepository
cipher *secret.Cipher
settings *Settings
client *http.Client
// operational posts the auto-disable notice through the system's shared
// durable dispatch path. Wired by NewSystem after construction.
operational func(ctx context.Context, delivery Delivery, opts OperationalDispatch) (*InsertedDelivery, error)
// posterURL picks the artwork URL Discord embeds may carry (admin poster
// mode + provider-CDN/presign resolution). Wired by NewSystem after
// construction; nil renders embeds without images.
posterURL func(ctx context.Context, posterPath, posterSourcePath string) string
logger *slog.Logger
}
func newWebhookSender(
webhooks *WebhookRepository,
deliveries *DeliveryRepository,
cipher *secret.Cipher,
settings *Settings,
) *webhookSender {
sender := &webhookSender{
webhooks: webhooks,
deliveries: deliveries,
cipher: cipher,
settings: settings,
logger: slog.Default().With("component", "notifications.webhooks"),
}
sender.client = newWebhookHTTPClient(func() bool {
return settings.WebhooksAllowPrivateDestinations(context.Background())
})
return sender
}
func webhookURLAAD(id string) string { return "notification_webhook:" + id + ":url" }
func webhookSecretAAD(id string) string { return "notification_webhook:" + id + ":signing_secret" }
func (s *webhookSender) decryptURL(hook *Webhook) (string, error) {
return s.cipher.Decrypt(hook.URLCiphertext, webhookURLAAD(hook.ID))
}
func (s *webhookSender) decryptSecret(hook *Webhook) (string, error) {
if hook.SigningSecretCiphertext == nil {
return "", fmt.Errorf("webhook has no signing secret")
}
return s.cipher.Decrypt(*hook.SigningSecretCiphertext, webhookSecretAAD(hook.ID))
}
// buildPayload renders the type-specific request body and headers.
func (s *webhookSender) buildPayload(hook *Webhook, row DeliveryRow, test bool) (body []byte, headers map[string]string, err error) {
switch hook.Type {
case WebhookTypeDiscord:
body, err = BuildDiscordWebhookPayload(row, test)
return body, nil, err
case WebhookTypeGeneric:
body, err = BuildGenericWebhookPayload(row, hook.ID, test)
if err != nil {
return nil, nil, err
}
signingSecret, err := s.decryptSecret(hook)
if err != nil {
return nil, nil, err
}
return body, genericWebhookHeaders(hook.ID, row.ID, signingSecret, time.Now(), body), nil
default:
return nil, nil, fmt.Errorf("unknown webhook type %q", hook.Type)
}
}
// send POSTs one payload to the webhook's destination.
func (s *webhookSender) send(ctx context.Context, hook *Webhook, row DeliveryRow, test bool) webhookSendResult {
url, err := s.decryptURL(hook)
if err != nil {
return webhookSendResult{Message: "webhook URL could not be decrypted"}
}
if hook.Type == WebhookTypeDiscord && s.posterURL != nil {
row.PosterURL = s.posterURL(ctx, row.PosterPath, row.PosterSourcePath)
}
body, headers, err := s.buildPayload(hook, row, test)
if err != nil {
return webhookSendResult{Message: "payload build failed"}
}
return sendWebhook(ctx, s.client, url, body, headers)
}
// processAttempt delivers one claimed attempt and records the outcome:
// delivered, retrying with backoff, failed (non-retryable 4xx or exhausted
// schedule), and the auto-disable transitions.
func (s *webhookSender) processAttempt(ctx context.Context, attempt DeliveryAttempt) {
hook, err := s.webhooks.getByIDUnscoped(ctx, attempt.TargetID)
if err != nil || hook == nil {
// Webhook deleted between enqueue and dispatch: the cascade removes
// attempts; nothing to do beyond closing this one out if it survived.
if err == nil {
_ = s.webhooks.FinalizeAttempt(ctx, attempt.ID, WebhookOutcomeFailed,
attempt.AttemptNumber+1, nil, "webhook deleted", nil)
}
return
}
if !hook.Enabled || !s.settings.WebhooksEnabled(ctx) {
_ = s.webhooks.FinalizeAttempt(ctx, attempt.ID, WebhookOutcomeFailed,
attempt.AttemptNumber+1, nil, "webhook disabled", nil)
return
}
row, err := s.deliveries.GetRowByID(ctx, attempt.NotificationDeliveryID)
if err != nil {
// Transient lookup failure: leave the claimed attempt alone so the
// lease expires and the retry worker reclaims it, instead of
// permanently failing the delivery over a database blip.
if ctx.Err() == nil {
s.logger.WarnContext(ctx, "webhook delivery lookup failed",
"attempt_id", attempt.ID,
"delivery_id", attempt.NotificationDeliveryID,
"error", err)
}
return
}
if row == nil {
_ = s.webhooks.FinalizeAttempt(ctx, attempt.ID, WebhookOutcomeFailed,
attempt.AttemptNumber+1, nil, "delivery row missing", nil)
return
}
result := s.send(ctx, hook, *row, false)
attemptNumber := attempt.AttemptNumber + 1
if result.OK {
_ = s.webhooks.FinalizeAttempt(ctx, attempt.ID, WebhookOutcomeDelivered,
attemptNumber, &result.HTTPStatus, "", nil)
if err := s.webhooks.RecordSuccess(ctx, hook.ID); err != nil {
s.logger.WarnContext(ctx, "webhook success bookkeeping failed", "webhook_id", hook.ID, "error", err)
}
return
}
var status *int
if result.HTTPStatus > 0 {
status = &result.HTTPStatus
}
if err := s.webhooks.RecordFailure(ctx, hook.ID, status, result.Message); err != nil {
s.logger.WarnContext(ctx, "webhook failure bookkeeping failed", "webhook_id", hook.ID, "error", err)
}
if result.HTTPStatus > 0 && !retryableHTTPStatus(result.HTTPStatus) {
// Deterministic destination-side rejection: fail this delivery now.
_ = s.webhooks.FinalizeAttempt(ctx, attempt.ID, WebhookOutcomeFailed,
attemptNumber, status, result.Message, nil)
s.maybeDisableAfter4xx(ctx, hook, result)
return
}
delay, more := webhookRetryDelay(attemptNumber)
if result.RetryAfter > 0 {
delay = result.RetryAfter
}
if more {
nextRetry := time.Now().Add(delay)
_ = s.webhooks.FinalizeAttempt(ctx, attempt.ID, WebhookOutcomeRetrying,
attemptNumber, status, result.Message, &nextRetry)
return
}
// Retry schedule exhausted (~24h of consecutive failures).
_ = s.webhooks.FinalizeAttempt(ctx, attempt.ID, WebhookOutcomeAutoDisabled,
attemptNumber, status, result.Message, nil)
s.disableWebhook(ctx, hook, result, "Deliveries failed for 24 hours")
}
// maybeDisableAfter4xx applies the 3-consecutive-non-retryable-4xx rule. A
// single 4xx is not proof the webhook is dead (CDN/WAF blips), but three
// consecutive deterministic rejections are.
func (s *webhookSender) maybeDisableAfter4xx(ctx context.Context, hook *Webhook, result webhookSendResult) {
recent, err := s.webhooks.RecentFinalOutcomes(ctx, hook.ID, autoDisableConsecutive4xx)
if err != nil {
s.logger.WarnContext(ctx, "webhook 4xx history lookup failed", "webhook_id", hook.ID, "error", err)
return
}
if len(recent) < autoDisableConsecutive4xx {
return
}
for _, attempt := range recent {
if attempt.Outcome != WebhookOutcomeFailed ||
attempt.HTTPStatus == nil || retryableHTTPStatus(*attempt.HTTPStatus) {
return
}
}
s.disableWebhook(ctx, hook, result,
fmt.Sprintf("%d consecutive deliveries rejected by the destination", autoDisableConsecutive4xx))
}
// disableWebhook auto-disables the webhook and posts the in-app notice so the
// failure is not silent. The notice type is on the webhook deny list, so it
// can never loop back into another webhook attempt.
func (s *webhookSender) disableWebhook(ctx context.Context, hook *Webhook, result webhookSendResult, reason string) {
fullReason := reason
if result.Message != "" {
fullReason = fmt.Sprintf("%s (last error: %s)", reason, result.Message)
}
if err := s.webhooks.Disable(ctx, hook.ID, fullReason); err != nil {
s.logger.ErrorContext(ctx, "webhook auto-disable failed", "webhook_id", hook.ID, "error", err)
return
}
s.logger.WarnContext(ctx, "webhook auto-disabled",
"webhook_id", hook.ID, "url_host", hook.URLHost, "reason", fullReason)
noticeFlags, err := json.Marshal(map[string]any{
"webhook_id": hook.ID,
"webhook_name": hook.Name,
"last_failure_status": result.HTTPStatus,
})
if err != nil {
return
}
notice := Delivery{
ID: ulid.Make().String(),
UserID: hook.UserID,
ProfileID: hook.ProfileID,
Type: DeliveryTypeWebhookAutoDisabled,
ReasonFlags: noticeFlags,
}
if s.operational == nil {
return
}
// Nil WebhookFilter: the notice must never re-dispatch as a webhook, or a
// broken webhook would loop forever.
if _, err := s.operational(ctx, notice, OperationalDispatch{}); err != nil {
s.logger.WarnContext(ctx, "webhook auto-disable notice dispatch failed", "webhook_id", hook.ID, "error", err)
}
}
// profileRateLimiter is a per-profile sliding-window counter bounding webhook
// deliveries per minute. Over-limit notifications stay in the inbox; webhook
// attempts simply are not enqueued. Per-node state: fanout claims are
// node-exclusive (SKIP LOCKED), so one node owns a given event's enqueue.
type profileRateLimiter struct {
mu sync.Mutex
windows map[string][]time.Time
}
func newProfileRateLimiter() *profileRateLimiter {
return &profileRateLimiter{windows: make(map[string][]time.Time)}
}
// Allow reports whether the profile is under the per-minute limit and counts
// the delivery when it is.
func (l *profileRateLimiter) Allow(profileID string, limit int) bool {
now := time.Now()
cutoff := now.Add(-time.Minute)
l.mu.Lock()
defer l.mu.Unlock()
window := l.windows[profileID]
kept := window[:0]
for _, ts := range window {
if ts.After(cutoff) {
kept = append(kept, ts)
}
}
if len(kept) >= limit {
l.windows[profileID] = kept
return false
}
l.windows[profileID] = append(kept, now)
return true
}