Files
silo-server/internal/policy/system_test.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

205 lines
5.8 KiB
Go

package policy
import (
"context"
"log/slog"
"sync"
"testing"
"time"
"github.com/jackc/pgx/v5/pgxpool"
"github.com/Silo-Server/silo-server/internal/cache"
)
func TestSystemCrossNodeConvergenceEventAndPoll(t *testing.T) {
ctx := context.Background()
pool, storeA := newPolicyStoreTest(t, ctx)
storeB := NewPolicyStore(pool)
eventBus := newPolicyTestEventBus()
systemA := newStartedPolicySystem(t, ctx, storeA, eventBus, time.Hour)
systemB := newStartedPolicySystem(t, ctx, storeB, eventBus, time.Hour)
documentID, generation := activatePolicyVersion(t, ctx, storeA, 0, "sha-event")
if err := systemA.NotifyChanged(ctx); err != nil {
t.Fatalf("NotifyChanged(event) error: %v", err)
}
waitForPolicyRevision(t, systemB, generation)
systemA.Stop()
systemB.Stop()
droppingBus := newPolicyTestEventBus()
droppingBus.SetDrop(true)
pollSystemA := newStartedPolicySystem(t, ctx, storeA, droppingBus, 20*time.Millisecond)
pollSystemB := newStartedPolicySystem(t, ctx, storeB, droppingBus, 20*time.Millisecond)
defer pollSystemA.Stop()
defer pollSystemB.Stop()
_, generation = activatePolicyVersion(t, ctx, storeA, documentID, "sha-poll")
if err := pollSystemA.NotifyChanged(ctx); err != nil {
t.Fatalf("NotifyChanged(poll) error: %v", err)
}
waitForPolicyRevision(t, pollSystemB, generation)
}
func TestSystemDegradedBootUsesVendorPolicy(t *testing.T) {
ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
defer cancel()
pool, err := pgxpool.New(ctx, "postgres://silo:silo@127.0.0.1:1/silo?connect_timeout=1")
if err != nil {
t.Fatalf("create unreachable pool: %v", err)
}
defer pool.Close()
system := NewSystem(NewPolicyStore(pool), nil, policyTestLogger(), WithSystemPollInterval(time.Hour))
if err := system.Start(ctx); err != nil {
t.Fatalf("Start() error: %v", err)
}
defer system.Stop()
assertVendorScopeDecision(t, system)
degraded := system.DegradedState()
if !degraded.Degraded || degraded.Reason != DegradedReasonStoreUnavailable {
t.Fatalf("DegradedState() = %#v, want degraded with reason %q", degraded, DegradedReasonStoreUnavailable)
}
}
func TestSystemReloadFailureKeepsLastKnownGood(t *testing.T) {
ctx := context.Background()
pool, store := newPolicyStoreTest(t, ctx)
system := newStartedPolicySystem(t, ctx, store, &cache.NoopEventBus{}, time.Hour)
defer system.Stop()
_, generation := activatePolicyVersion(t, ctx, store, 0, "sha-good")
if err := system.NotifyChanged(ctx); err != nil {
t.Fatalf("NotifyChanged(good) error: %v", err)
}
waitForPolicyRevision(t, system, generation)
pool.Close()
if err := system.NotifyChanged(ctx); err == nil {
t.Fatal("NotifyChanged() error = nil, want closed pool error")
}
if got := system.engine.Revision(); got != generation {
t.Fatalf("revision after failed reload = %d, want %d", got, generation)
}
assertVendorScopeDecision(t, system)
}
type policyTestEventBus struct {
mu sync.Mutex
drop bool
handlers map[string][]cache.EventHandler
}
func newPolicyTestEventBus() *policyTestEventBus {
return &policyTestEventBus{handlers: make(map[string][]cache.EventHandler)}
}
func (b *policyTestEventBus) Publish(_ context.Context, channel string, event cache.Event) error {
b.mu.Lock()
drop := b.drop
handlers := append([]cache.EventHandler(nil), b.handlers[channel]...)
b.mu.Unlock()
if drop {
return nil
}
for _, handler := range handlers {
handler(event)
}
return nil
}
func (b *policyTestEventBus) Subscribe(_ context.Context, channel string, handler cache.EventHandler) error {
b.mu.Lock()
b.handlers[channel] = append(b.handlers[channel], handler)
b.mu.Unlock()
return nil
}
func (b *policyTestEventBus) Close() error { return nil }
func (b *policyTestEventBus) SetDrop(drop bool) {
b.mu.Lock()
b.drop = drop
b.mu.Unlock()
}
func newStartedPolicySystem(t *testing.T, ctx context.Context, store *PolicyStore, bus cache.EventBus, pollInterval time.Duration) *System {
t.Helper()
system := NewSystem(store, bus, policyTestLogger(), WithSystemPollInterval(pollInterval))
if err := system.Start(ctx); err != nil {
t.Fatalf("Start() error: %v", err)
}
return system
}
func policyTestLogger() *slog.Logger {
return slog.New(slog.DiscardHandler)
}
func activatePolicyVersion(t *testing.T, ctx context.Context, store *PolicyStore, documentID int64, sha string) (int64, int64) {
t.Helper()
if documentID == 0 {
document, err := store.CreateDocument(ctx, DomainScope, "household scope")
if err != nil {
t.Fatalf("CreateDocument() error: %v", err)
}
documentID = document.ID
}
version, err := store.CreateVersion(ctx, documentID, validStorePolicySource(), sha, true, nil, nil, "")
if err != nil {
t.Fatalf("CreateVersion() error: %v", err)
}
generation, err := store.Activate(ctx, documentID, version.ID)
if err != nil {
t.Fatalf("Activate() error: %v", err)
}
return documentID, generation
}
func waitForPolicyRevision(t *testing.T, system *System, generation int64) {
t.Helper()
deadline := time.After(3 * time.Second)
ticker := time.NewTicker(10 * time.Millisecond)
defer ticker.Stop()
for {
select {
case <-deadline:
t.Fatalf("policy revision = %d, want %d", system.engine.Revision(), generation)
case <-ticker.C:
if system.engine.Revision() == generation {
return
}
}
}
}
func assertVendorScopeDecision(t *testing.T, system *System) {
t.Helper()
pdp := system.PDP()
if pdp == nil {
t.Fatal("PDP() = nil")
}
decision, _, err := pdp.ResolveViewerScope(context.Background(), ScopeInput{
SchemaVersion: 1,
UserID: 42,
SessionID: "sess-1",
AccountRestricted: false,
AccessPolicyRevision: 9,
ProfileVerified: true,
RequestTime: "2026-07-02T12:00:00Z",
})
if err != nil {
t.Fatalf("ResolveViewerScope() error: %v", err)
}
if !decision.Unrestricted {
t.Fatalf("Unrestricted = false, want vendor-only unrestricted decision: %#v", decision)
}
}