Files
silo-server/internal/catalog/semantic_coverage.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

382 lines
13 KiB
Go

package catalog
import (
"context"
"fmt"
"log/slog"
"sync"
"sync/atomic"
"time"
"github.com/jackc/pgx/v5"
)
const (
// semanticCoverageEnableRatio is the per-type vector-coverage fraction at or
// above which semantic search becomes eligible for that type.
semanticCoverageEnableRatio = 0.90
// semanticCoverageDisableRatio is the per-type fraction below which semantic
// search is disabled for that type. The gap to the enable ratio is the
// hysteresis band that prevents flapping near the threshold.
semanticCoverageDisableRatio = 0.80
// semanticCoverageRefreshInterval is how often the background tracker
// recomputes the coverage snapshot.
semanticCoverageRefreshInterval = 2 * time.Minute
)
// coverageQuerier is the read surface the semantic-coverage counts need from a
// database handle. *pgxpool.Pool satisfies it, so the existing callers continue
// to pass their pool unchanged. A later task layers a cached snapshot tracker on
// top of these queries in this same file.
type coverageQuerier interface {
QueryRow(ctx context.Context, sql string, args ...any) pgx.Row
Query(ctx context.Context, sql string, args ...any) (pgx.Rows, error)
}
// catalogTypeCoverage is the per-media-type semantic vector coverage: how many
// embed-eligible items exist (Eligible) and how many of those carry a
// current-model embedding (Vectorized). By construction Vectorized <= Eligible
// for every row.
//
// Ratio and Ready are populated by computeCoverageSnapshot, not by the raw
// catalogSemanticCoverageByType count query (which leaves them zero): Ratio is
// Vectorized/Eligible, and Ready is the hysteresis-latched readiness decision
// for the type. Carrying them on the same struct lets a published snapshot store
// counts and the derived gate state together.
type catalogTypeCoverage struct {
Type string
Eligible int
Vectorized int
Ratio float64
Ready bool
}
// semanticCoverageEligibleByTypeSQL counts embed-eligible items per media type
// (the coverage denominator). The eligibility predicate is shared with the
// recommendations population via embeddingvectors.ItemEligibilityWhereClause;
// it is inlined here as a literal so the count stays a single round trip.
const semanticCoverageEligibleByTypeSQL = `
SELECT mi.type, COUNT(*) AS eligible
FROM media_items mi
WHERE ` + catalogSearchExcludeMangaChaptersSQL + `
AND ($1::text[] IS NULL OR mi.type = ANY($1))
AND (mi.status = 'matched' OR mi.type IN ('audiobook','ebook'))
GROUP BY mi.type`
// semanticCoverageVectorizedByTypeSQL counts embed-eligible items that already
// carry a current-model embedding per media type (the coverage numerator).
// Applying the same eligibility predicate as the denominator guarantees the
// numerator is a subset of the denominator, so a stale embedding left on a
// now-unmatched item can never push a per-type ratio above 1.
const semanticCoverageVectorizedByTypeSQL = `
SELECT mi.type, COUNT(*) AS vectorized
FROM media_item_embeddings e
JOIN media_items mi ON mi.content_id = e.media_item_id
WHERE ` + catalogSearchExcludeMangaChaptersSQL + `
AND ($1::text[] IS NULL OR mi.type = ANY($1))
AND (mi.status = 'matched' OR mi.type IN ('audiobook','ebook'))
AND ($2 = '' OR e.model = $2)
GROUP BY mi.type`
// catalogSemanticCoverageByType returns per-type eligible and vectorized counts
// for the requested item types (nil/empty => all types) and embedding model
// ("" => count every model). The numerator and denominator share the
// embed-eligibility predicate, so every returned row satisfies
// Vectorized <= Eligible.
func catalogSemanticCoverageByType(ctx context.Context, q coverageQuerier, itemTypes []string, model string) ([]catalogTypeCoverage, error) {
if q == nil {
return nil, nil
}
typeFilter := normalizeCatalogSearchItemTypes(itemTypes)
var typeArg any
if len(typeFilter) > 0 {
typeArg = typeFilter
}
coverage := make(map[string]*catalogTypeCoverage)
order := make([]string, 0)
upsert := func(mediaType string) *catalogTypeCoverage {
if row, ok := coverage[mediaType]; ok {
return row
}
row := &catalogTypeCoverage{Type: mediaType}
coverage[mediaType] = row
order = append(order, mediaType)
return row
}
eligibleRows, err := q.Query(ctx, semanticCoverageEligibleByTypeSQL, typeArg)
if err != nil {
return nil, fmt.Errorf("query semantic coverage eligible counts: %w", err)
}
func() {
defer eligibleRows.Close()
for eligibleRows.Next() {
var mediaType string
var eligible int
if err = eligibleRows.Scan(&mediaType, &eligible); err != nil {
return
}
upsert(mediaType).Eligible = eligible
}
err = eligibleRows.Err()
}()
if err != nil {
return nil, fmt.Errorf("scan semantic coverage eligible counts: %w", err)
}
vectorRows, err := q.Query(ctx, semanticCoverageVectorizedByTypeSQL, typeArg, model)
if err != nil {
return nil, fmt.Errorf("query semantic coverage vectorized counts: %w", err)
}
func() {
defer vectorRows.Close()
for vectorRows.Next() {
var mediaType string
var vectorized int
if err = vectorRows.Scan(&mediaType, &vectorized); err != nil {
return
}
upsert(mediaType).Vectorized = vectorized
}
err = vectorRows.Err()
}()
if err != nil {
return nil, fmt.Errorf("scan semantic coverage vectorized counts: %w", err)
}
out := make([]catalogTypeCoverage, 0, len(order))
for _, mediaType := range order {
out = append(out, *coverage[mediaType])
}
return out, nil
}
// semanticCoverageSnapshot is an immutable, point-in-time view of per-type
// vector coverage for a single embedding model. Every field, including the
// PerType map and its values, is built fresh by computeCoverageSnapshot and is
// never mutated after the snapshot is published via atomic.Pointer.Store, so
// concurrent readers on the search hot path observe it without locking.
type semanticCoverageSnapshot struct {
PerType map[string]catalogTypeCoverage
Overall float64
Model string
UpdatedAt time.Time
}
// computeCoverageSnapshot derives a fresh snapshot from raw per-type counts. It
// applies hysteresis per type: at or above the enable ratio a type is ready;
// below the disable ratio it is not; inside the band it holds the previous
// snapshot's latch for that type (defaulting to not-ready when no prior latch
// exists). A type with no eligible items is never ready. Overall is the global
// vectorized/eligible fraction across the supplied types.
//
// prev supplies only the previous per-type Ready latches for band entries;
// callers pass nil to start fresh (e.g. immediately after a model collapse) so a
// stale latch can never carry into a new model.
func computeCoverageSnapshot(types []catalogTypeCoverage, model string, prev *semanticCoverageSnapshot, now time.Time) *semanticCoverageSnapshot {
per := make(map[string]catalogTypeCoverage, len(types))
sumEligible, sumVectorized := 0, 0
for _, c := range types {
ratio := 0.0
if c.Eligible > 0 {
ratio = float64(c.Vectorized) / float64(c.Eligible)
}
ready := false
switch {
case c.Eligible == 0:
ready = false // no data to gate on
case ratio >= semanticCoverageEnableRatio:
ready = true
case ratio < semanticCoverageDisableRatio:
ready = false
default:
// Hysteresis band [disable, enable): hold the previous latch.
if prev != nil {
if pc, ok := prev.PerType[c.Type]; ok {
ready = pc.Ready
}
}
}
per[c.Type] = catalogTypeCoverage{
Type: c.Type,
Eligible: c.Eligible,
Vectorized: c.Vectorized,
Ratio: ratio,
Ready: ready,
}
sumEligible += c.Eligible
sumVectorized += c.Vectorized
}
overall := 0.0
if sumEligible > 0 {
overall = float64(sumVectorized) / float64(sumEligible)
}
return &semanticCoverageSnapshot{
PerType: per,
Overall: overall,
Model: model,
UpdatedAt: now,
}
}
// semanticCoverageTracker maintains the in-memory coverage snapshot consulted by
// the search hot path. Reads (CoverageReady/Snapshot) are lock-free via an
// atomic.Pointer; refreshes are single-flighted under mu and publish a freshly
// built, never-mutated snapshot. The fetch seam decouples Refresh from any
// concrete database handle so it is unit-testable without a real pool.
type semanticCoverageTracker struct {
fetch func(ctx context.Context, model string) ([]catalogTypeCoverage, error)
models CatalogSemanticModelProvider
mu sync.Mutex
snap atomic.Pointer[semanticCoverageSnapshot]
clock func() time.Time
}
// Compile-time assertion that the tracker satisfies the hot-path gate contract.
var _ SemanticCoverageGate = (*semanticCoverageTracker)(nil)
// newSemanticCoverageTracker wires the tracker to a real query surface. The
// fetch seam closes over q so production code counts coverage through
// catalogSemanticCoverageByType, while tests inject a canned fetch directly.
func newSemanticCoverageTracker(q coverageQuerier, indexTypes []string, models CatalogSemanticModelProvider) *semanticCoverageTracker {
return &semanticCoverageTracker{
fetch: func(ctx context.Context, model string) ([]catalogTypeCoverage, error) {
return catalogSemanticCoverageByType(ctx, q, indexTypes, model)
},
models: models,
clock: time.Now,
}
}
// now reads the configured clock, defaulting to time.Now when unset (e.g. a
// struct literal that omits clock).
func (t *semanticCoverageTracker) now() time.Time {
if t.clock != nil {
return t.clock()
}
return time.Now()
}
// Refresh recomputes and publishes the coverage snapshot. It is single-flighted
// under mu and fails safe: if the active model cannot be resolved or the count
// query errors, the last-good snapshot is retained (no zeroed snapshot is
// published). When the active model changes, the prior snapshot is collapsed to
// not-ready before recompute so stale per-type latches cannot leak across
// models.
func (t *semanticCoverageTracker) Refresh(ctx context.Context) error {
t.mu.Lock()
defer t.mu.Unlock()
model := ""
if t.models != nil {
m, err := t.models.ActiveEmbeddingModel(ctx)
if err != nil {
// Retain last-good: do not publish on a provider error.
slog.WarnContext(ctx, "catalog semantic coverage: active model lookup failed; retaining last snapshot", "component", "catalog", "err", err)
return err
}
model = m
}
if model == "" {
// No active embedding model (no lock or no provider): publish an empty
// not-ready snapshot so the gate reports not-ready deterministically.
t.snap.Store(&semanticCoverageSnapshot{
PerType: map[string]catalogTypeCoverage{},
Model: "",
UpdatedAt: t.now(),
})
return nil
}
prev := t.snap.Load()
if prev != nil && prev.Model != model {
// Model changed: collapse immediately and drop stale latches so the
// recompute below cannot inherit readiness from the previous model.
t.snap.Store(&semanticCoverageSnapshot{
PerType: map[string]catalogTypeCoverage{},
Model: model,
UpdatedAt: t.now(),
})
prev = nil
}
types, err := t.fetch(ctx, model)
if err != nil {
// Retain last-good: do not overwrite a healthy snapshot with zeros.
slog.WarnContext(ctx, "catalog semantic coverage: count query failed; retaining last snapshot", "component", "catalog", "err", err)
return err
}
t.snap.Store(computeCoverageSnapshot(types, model, prev, t.now()))
return nil
}
// CoverageReady reports whether semantic search may serve the requested item
// types. It is lock-free and fail-safe: a not-yet-computed (nil/empty) snapshot
// reports not-ready. An explicit scope is an AND over its types; the first
// not-ready type's reason is returned. An empty scope requires every snapshot
// type to be ready. Requested types absent from the snapshot (no eligible items)
// are not gated; a scope consisting only of such types reports not-ready.
func (t *semanticCoverageTracker) CoverageReady(itemTypes []string) (bool, string) {
s := t.snap.Load()
if s == nil || len(s.PerType) == 0 {
return false, "coverage not yet computed"
}
requested := normalizeCatalogSearchItemTypes(itemTypes)
if len(requested) == 0 {
requested = make([]string, 0, len(s.PerType))
for k := range s.PerType {
requested = append(requested, k)
}
}
anyPresent := false
for _, ty := range requested {
c, ok := s.PerType[ty]
if !ok {
// No eligible items of this type: nothing to gate.
continue
}
anyPresent = true
if !c.Ready {
return false, fmt.Sprintf("type %q coverage %.0f%% below threshold", ty, c.Ratio*100)
}
}
if !anyPresent {
return false, "no embeddable items in requested scope"
}
return true, ""
}
// Snapshot returns the current published snapshot, which may be nil before the
// first successful Refresh. Callers must nil-check.
func (t *semanticCoverageTracker) Snapshot() *semanticCoverageSnapshot {
return t.snap.Load()
}
// Run refreshes once immediately, then on a fixed ticker until ctx is done.
// Refresh errors are logged and swallowed so a transient failure does not stop
// the loop (the last-good snapshot is retained by Refresh).
func (t *semanticCoverageTracker) Run(ctx context.Context) {
if err := t.Refresh(ctx); err != nil {
slog.WarnContext(ctx, "catalog semantic coverage: initial refresh failed", "component", "catalog", "err", err)
}
ticker := time.NewTicker(semanticCoverageRefreshInterval)
defer ticker.Stop()
for {
select {
case <-ctx.Done():
return
case <-ticker.C:
if err := t.Refresh(ctx); err != nil {
slog.WarnContext(ctx, "catalog semantic coverage: refresh failed", "component", "catalog", "err", err)
}
}
}
}