* 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>
212 lines
7.1 KiB
Go
212 lines
7.1 KiB
Go
package worker
|
|
|
|
import (
|
|
"context"
|
|
"fmt"
|
|
"log/slog"
|
|
"sync"
|
|
"time"
|
|
|
|
"github.com/jackc/pgx/v5/pgxpool"
|
|
|
|
"github.com/Silo-Server/silo-server/internal/cache"
|
|
evt "github.com/Silo-Server/silo-server/internal/events"
|
|
)
|
|
|
|
const (
|
|
// nodeDeadTimeout is how long a node can go without a heartbeat before
|
|
// its sessions are purged.
|
|
nodeDeadTimeout = 45 * time.Second
|
|
|
|
// nodeHeartbeatCleanup is how long before stale heartbeat rows
|
|
// themselves are deleted (longer than nodeDeadTimeout to avoid flapping).
|
|
nodeHeartbeatCleanup = 5 * time.Minute
|
|
|
|
// activeSessionGrace is the staleness threshold for active (not paused)
|
|
// sessions based on last_sync_at.
|
|
activeSessionGrace = 45 * time.Second
|
|
|
|
// pausedSessionGrace is the staleness threshold for paused sessions.
|
|
// Must comfortably cover an intentional pause: reaping kills the
|
|
// transcode with no revival path (issue #243). Keep in sync with
|
|
// playback.DefaultPausedSessionGrace.
|
|
pausedSessionGrace = 30 * time.Minute
|
|
|
|
// cleanupInterval is how often the cleanup ticker fires.
|
|
cleanupInterval = 15 * time.Second
|
|
|
|
// absStaleOpenSessionGrace closes audiobook playback sessions that stopped
|
|
// syncing without an explicit /close (abandoned playback) so they don't
|
|
// linger as "open" forever and inflate listening-stats aggregation.
|
|
absStaleOpenSessionGrace = 24 * time.Hour
|
|
|
|
// absSessionPruneInterval throttles the abandoned-session sweep: it's a slow-moving
|
|
// concern, so it runs hourly rather than on every 15s cleanup tick.
|
|
absSessionPruneInterval = time.Hour
|
|
)
|
|
|
|
// SessionCleaner removes stale playback sessions and dead node records.
|
|
type SessionCleaner struct {
|
|
pool *pgxpool.Pool
|
|
EventBus cache.EventBus
|
|
EventsHub *evt.Hub
|
|
stop chan struct{}
|
|
|
|
// lastABSSessionPrune gates the hourly abs_playback_sessions retention
|
|
// sweep. Guarded by absPruneMu because CleanStale is also invoked from the
|
|
// shutdown path while the ticker goroutine is still running.
|
|
absPruneMu sync.Mutex
|
|
lastABSSessionPrune time.Time
|
|
}
|
|
|
|
// NewSessionCleaner creates a SessionCleaner. The graceSeconds parameter is
|
|
// accepted for backwards compatibility but ignored — grace periods are now
|
|
// fixed at 45s (active) and 2m (paused).
|
|
func NewSessionCleaner(pool *pgxpool.Pool, graceSeconds int) *SessionCleaner {
|
|
return &SessionCleaner{
|
|
pool: pool,
|
|
stop: make(chan struct{}),
|
|
}
|
|
}
|
|
|
|
// Start begins the background cleanup loop, firing every 15 seconds.
|
|
func (c *SessionCleaner) Start() {
|
|
go func() {
|
|
ticker := time.NewTicker(cleanupInterval)
|
|
defer ticker.Stop()
|
|
|
|
for {
|
|
select {
|
|
case <-c.stop:
|
|
return
|
|
case <-ticker.C:
|
|
ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
|
|
if deleted, err := c.CleanStale(ctx); err != nil {
|
|
slog.Error("session cleanup error", "error", err)
|
|
} else if deleted > 0 {
|
|
slog.Debug("cleaned stale sessions", "count", deleted)
|
|
}
|
|
cancel()
|
|
}
|
|
}
|
|
}()
|
|
}
|
|
|
|
// Stop signals the cleanup loop to stop.
|
|
func (c *SessionCleaner) Stop() {
|
|
close(c.stop)
|
|
}
|
|
|
|
// CleanStale performs a full cleanup pass:
|
|
// 1. Purge sessions from dead nodes (heartbeat stale > 45s)
|
|
// 2. Remove stale heartbeat rows (> 5 minutes)
|
|
// 3. Remove stale active sessions (last_sync_at > 45s)
|
|
// 4. Remove stale paused sessions (last_sync_at > 2 minutes)
|
|
func (c *SessionCleaner) CleanStale(ctx context.Context) (int, error) {
|
|
var totalDeleted int64
|
|
|
|
// 1. Purge sessions belonging to dead nodes.
|
|
tag, err := c.pool.Exec(ctx, `
|
|
DELETE FROM playback_sessions_sync
|
|
WHERE reporting_node IN (
|
|
SELECT node_id FROM node_heartbeats
|
|
WHERE updated_at < NOW() - make_interval(secs => $1::double precision)
|
|
)
|
|
`, nodeDeadTimeout.Seconds())
|
|
if err != nil {
|
|
return 0, fmt.Errorf("purging dead node sessions: %w", err)
|
|
}
|
|
totalDeleted += tag.RowsAffected()
|
|
|
|
// 2. Clean up stale heartbeat rows.
|
|
if _, err := c.pool.Exec(ctx, `
|
|
DELETE FROM node_heartbeats
|
|
WHERE updated_at < NOW() - make_interval(secs => $1::double precision)
|
|
`, nodeHeartbeatCleanup.Seconds()); err != nil {
|
|
return int(totalDeleted), fmt.Errorf("cleaning stale heartbeats: %w", err)
|
|
}
|
|
|
|
// 3. Active sessions: 45s grace on last_sync_at.
|
|
tag, err = c.pool.Exec(ctx, `
|
|
DELETE FROM playback_sessions_sync
|
|
WHERE is_paused = FALSE
|
|
AND last_sync_at < NOW() - make_interval(secs => $1::double precision)
|
|
`, activeSessionGrace.Seconds())
|
|
if err != nil {
|
|
return int(totalDeleted), fmt.Errorf("cleaning stale active sessions: %w", err)
|
|
}
|
|
totalDeleted += tag.RowsAffected()
|
|
|
|
// 4. Paused sessions: 2 minute grace on last_sync_at.
|
|
tag, err = c.pool.Exec(ctx, `
|
|
DELETE FROM playback_sessions_sync
|
|
WHERE is_paused = TRUE
|
|
AND last_sync_at < NOW() - make_interval(secs => $1::double precision)
|
|
`, pausedSessionGrace.Seconds())
|
|
if err != nil {
|
|
return int(totalDeleted), fmt.Errorf("cleaning stale paused sessions: %w", err)
|
|
}
|
|
totalDeleted += tag.RowsAffected()
|
|
|
|
// 5. Audiobook session cleanup (hourly): close abandoned open sessions.
|
|
// Closed rows are retained because the ABS stats endpoint currently has
|
|
// all-time semantics and aggregates directly from abs_playback_sessions.
|
|
// Kept off totalDeleted so it doesn't trigger the live-session
|
|
// invalidation event. The due-check is mutex-guarded so the shutdown-path
|
|
// CleanStale and the ticker can't race or double-run it.
|
|
c.absPruneMu.Lock()
|
|
pruneStartedAt := time.Now()
|
|
previousABSSessionPrune := c.lastABSSessionPrune
|
|
abndPruneDue := pruneStartedAt.Sub(c.lastABSSessionPrune) >= absSessionPruneInterval
|
|
if abndPruneDue {
|
|
c.lastABSSessionPrune = pruneStartedAt
|
|
}
|
|
c.absPruneMu.Unlock()
|
|
if abndPruneDue {
|
|
if err := c.closeAbandonedABSSessions(ctx); err != nil {
|
|
slog.WarnContext(ctx, "abs session cleanup failed", "component", "worker", "error", err)
|
|
c.absPruneMu.Lock()
|
|
if c.lastABSSessionPrune.Equal(pruneStartedAt) {
|
|
c.lastABSSessionPrune = previousABSSessionPrune
|
|
}
|
|
c.absPruneMu.Unlock()
|
|
}
|
|
}
|
|
|
|
if totalDeleted > 0 && c.EventsHub != nil {
|
|
if err := c.EventsHub.PublishJSON(
|
|
ctx,
|
|
evt.ChannelSessions,
|
|
"sessions.replaced",
|
|
nil,
|
|
evt.PublishOptions{AdminOnly: true},
|
|
); err != nil {
|
|
return int(totalDeleted), fmt.Errorf("publishing playback cleanup invalidation: %w", err)
|
|
}
|
|
} else if c.EventBus != nil && totalDeleted > 0 {
|
|
if err := c.EventBus.Publish(ctx, cache.ChannelPlayback, cache.Event{
|
|
Type: cache.EventPlaybackSessionsChanged,
|
|
Payload: "cleanup",
|
|
}); err != nil {
|
|
return int(totalDeleted), fmt.Errorf("publishing playback cleanup invalidation: %w", err)
|
|
}
|
|
}
|
|
|
|
return int(totalDeleted), nil
|
|
}
|
|
|
|
// closeAbandonedABSSessions closes abandoned audiobook playback sessions (no
|
|
// explicit /close, stopped syncing). It intentionally does not delete closed
|
|
// sessions: AggregateStats currently uses this table for all-time totals.
|
|
func (c *SessionCleaner) closeAbandonedABSSessions(ctx context.Context) error {
|
|
if _, err := c.pool.Exec(ctx, `
|
|
UPDATE abs_playback_sessions
|
|
SET closed_at = now()
|
|
WHERE closed_at IS NULL
|
|
AND COALESCE(last_sync_at, started_at) < NOW() - make_interval(secs => $1::double precision)
|
|
`, absStaleOpenSessionGrace.Seconds()); err != nil {
|
|
return fmt.Errorf("closing abandoned abs sessions: %w", err)
|
|
}
|
|
return nil
|
|
}
|