diff --git a/docs/plans/2026-08-24-1025-otel-tracing.md b/docs/plans/2026-08-24-1025-otel-tracing.md new file mode 100644 index 0000000..19834ae --- /dev/null +++ b/docs/plans/2026-08-24-1025-otel-tracing.md @@ -0,0 +1,107 @@ +# Plan: OpenTelemetry tracing integrated with the existing logr/zap logging +**Created:** 2026-08-24 10:25 + +## Context + +The operator has structured logging (controller-runtime zap → logr, `logf.FromContext(ctx)` everywhere) and Prometheus metrics, but no tracing. A single reconcile fans out into k8s API calls, provider calls (GCP VMs / squid Pods), and status patches; the discovery API serves lease requests; GC and health engines run on tickers. Today correlating one operation across those hops means grepping for `reconcileID` or `providerID`. Goal: proper OTel traces — a new trace per unit of work (reconcile, HTTP request, GC sweep, optionally health probe), child spans for k8s/provider/HTTP calls — **and every log line inside a traced operation enriched with the trace context**, without disturbing the existing logr/zap system. + +User decisions (confirmed): +- **Enablement:** auto from standard `OTEL_*` env vars — no collector configured ⇒ tracing fully off, zero new flags for the common case. +- **Health probes:** not traced by default; new `--trace-health-probes` flag enables one root span per probe. +- **Backend:** none exists yet — verification uses the console exporter and a throwaway Jaeger all-in-one in kind; manifests ship commented-out OTLP env examples. + +## Key design facts (verified, non-obvious) + +- **logr can't read ctx:** `logr.LogSink` never sees `context.Context`, so trace IDs cannot be added inside the zap sink. They must be attached as `WithValues` at span-creation points via `logf.IntoContext`. zap does **not** dedupe repeated keys, so enrichment must happen exactly once per ctx chain (see `tracing.Start` below). +- Log keys: **`traceID` / `spanID`** (lowerCamel matches `reconcileID`/`providerID` house style; note in docs that Grafana/Loki derived-field regexes must match `traceID`, not the `trace_id` default). +- **GCP calls trace themselves:** `google.golang.org/api/transport/http` already wraps its transport in `otelhttp.NewTransport` — once a global TracerProvider is set, every Compute call emits an HTTP client span. Do not add HTTP-level spans in the gcp provider; the `provider.*` decorator span becomes their parent. +- **kube-apiserver ignores incoming `traceparent`** by design; our k8s-API client spans are leaves. Don't promise cross-process traces into the apiserver. +- The Go SDK does **not** implement `OTEL_SDK_DISABLED` — handle it ourselves. +- `contrib/exporters/autoexport` drags in metric/log/prometheus exporters (binary + deps on a 128Mi pod) — hand-roll trace-exporter selection (~40 lines) instead. +- Span events are deprecated (OTel spec, Mar 2026): use `span.SetStatus` + `error.type`-style attributes, not `RecordError`/`AddEvent`. +- `rest.Config.Wrap` puts our transport innermost (after auth), so spans see the final request — correct; but informer list/watch + leader election run outside any span ⇒ the transport must **filter out requests with no parent span** or every watch becomes a long-lived root span. +- Manager runnables receive no logger in ctx (only HTTP servers do) — `logf.FromContext` falls back to the global logger there, which is fine; the discovery server must keep seeding from `s.log`. + +## Steps + +### Step 1 — Dependencies + +`go get` (aligning the existing indirect skew: otel core v1.44 / otlptrace v1.40): +`go.opentelemetry.io/otel@v1.45.0`, `otel/sdk@v1.45.0`, `otel/trace@v1.45.0`, +`otel/exporters/otlp/otlptrace/otlptracegrpc@v1.45.0`, `.../otlptracehttp@v1.45.0`, +`otel/exporters/stdout/stdouttrace@v1.45.0`, +`go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp@v0.70.0`, plus the +`semconv` version matching the SDK's `resource.Default()` (treat `ErrSchemaURLConflict` from `resource.New` as non-fatal if versions drift). +`go mod tidy`; full build + `make test` to confirm `google.golang.org/api v0.292.0` / k8s v0.36 tolerate the bump (MVS picks the higher otelhttp). + +### Step 2 — New package `internal/tracing` + +- **`tracing.go` — `Setup(ctx, log logr.Logger, service, version string) (shutdown func(context.Context) error, err error)`** + - Disabled (returns no-op shutdown, installs nothing) when `OTEL_SDK_DISABLED=true`, or when neither `OTEL_TRACES_EXPORTER` nor `OTEL_EXPORTER_OTLP_ENDPOINT`/`OTEL_EXPORTER_OTLP_TRACES_ENDPOINT` is set, or `OTEL_TRACES_EXPORTER=none`. One startup Info line either way stating the effective state/exporter. + - Exporter selection (hand-rolled, no autoexport): `OTEL_TRACES_EXPORTER` ∈ `otlp` (default) | `console`; for otlp, `OTEL_EXPORTER_OTLP_(TRACES_)PROTOCOL` ∈ `http/protobuf` (default) | `grpc` → `otlptracehttp` / `otlptracegrpc` (endpoint/TLS/headers via their native env handling). + - `sdktrace.NewTracerProvider` with batch processor (`WithMaxQueueSize(512)` — bounded on the 128Mi pod; sampler stays the SDK default so `OTEL_TRACES_SAMPLER(_ARG)` works), resource = `resource.New(WithAttributes(service.name, service.version=commit), WithFromEnv())` with env last so it wins. + - Globals: `otel.SetTracerProvider`, `otel.SetTextMapPropagator(TraceContext+Baggage)`, `otel.SetLogger(log.WithName("otel"))`, `otel.SetErrorHandler` → logr at `V(1)` (an unreachable collector errors every few seconds; Error level would spam). +- **`logger.go` — the one logger-enrichment mechanism** (used by everything; prevents duplicate `traceID` keys): + - private ctx key holding the *base* (pre-enrichment) logr.Logger. + - `Start(ctx, spanName, opts...) (context.Context, trace.Span)`: starts a span from the global tracer; if the resulting span context is valid, capture base = stored base or `logf.FromContext(ctx)` on first call, then `logf.IntoContext(ctx, base.WithValues("traceID", ..., "spanID", ...))`. Nested `Start` re-derives from base — never stacks. Documented trade-off: `WithValues` pushed via `logf.IntoContext` *between* two `Start` calls is dropped (nothing first-party does that; controller-runtime's `reconcileID` logger is the base and survives). + - `ContextWithLogger(ctx, base)` seeds the base explicitly (discovery middleware). +- **`reconciler.go` — `NewReconciler(kind string, inner reconcile.Reconciler, opts...) reconcile.Reconciler`**: root span `Reconcile ` (SpanKind Internal) via `Start`; attrs `k8s.namespace.name`, `k8s.object.name`, `reconcile.id` (`controller.ReconcileIDFromContext`); on return records `reconcile.requeue_after`, sets Error status from err. `WithTracerProvider` option for tests. +- **`transport.go` — `RestConfigWrapper() transport.WrapperFunc`**: `otelhttp.NewTransport` with `WithFilter` requiring `trace.SpanContextFromContext(r.Context()).IsValid()` — k8s API spans only under an existing trace (excludes informers, leader election, metrics authn). +- **`http.go` — `HTTPMiddleware(operation string, base logr.Logger) func(http.Handler) http.Handler`**: `otelhttp.NewHandler` (filter `/healthz`; otelhttp renames the span from `r.Pattern` after routing — no custom naming needed) + inner layer calling `ContextWithLogger`-then-enrich so handler logs carry `traceID`. Accepts incoming `traceparent` (clients continue their traces). + +Tests (all with `sdktrace` + `tracetest.NewSpanRecorder` via the `WithTracerProvider` options, parallel; `Setup` env tests use `t.Setenv`, not parallel): +- `Start`: nested spans → child span recorded; **funcr-captured log line contains `traceID` exactly once** (pattern: `internal/provider/gcp/gcp_test.go:277`); disabled tracer → no `traceID` in logs. +- `Setup`: table over env combinations (unset→disabled, `none`→disabled, endpoint set→otlp, `console`, `OTEL_SDK_DISABLED`). +- Reconciler decorator: fake inner returns result/err → span name/attrs/status. +- Transport filter: request without parent span produces no span. +- Middleware: `httptest` request → server span named from route pattern; `/healthz` unspanned; handler logger carries `traceID`. + +### Step 3 — `provider.WithTracing` decorator + +`internal/provider/tracing.go`, mirroring `metrics.go`: `WithTracing(name string, p Provider, opts...) Provider` — one Client span per call (`provider.create|get|delete|list`), attrs `provider.name`, `provider.id` (where present), result class attr from `resultLabel(err)`; status Error only for quota/permanent/transient — `ErrNotFound` stays Ok (expected during deletion polling). Returns the inner error **unmodified**. Uses `tracing.Start` so provider-internal logs (gcp `p.logger(ctx)`) inherit `traceID`. Tests in `internal/provider/tracing_test.go` reusing `staticProvider` from `metrics_test.go:19`. + +Wiring in `cmd/main.go:174-177` — tracing outermost: `provider.WithTracing(name, provider.WithMetrics(name, p, m))`. + +### Step 4 — `cmd/main.go` wiring + +- `tracing.Setup(...)` immediately after `ctrl.SetLogger` (cmd/main.go:148); on error: log + `os.Exit(1)`. +- Explicit `shutdown(context.WithTimeout(context.Background(), 10*time.Second))` (fresh ctx — signal ctx is already cancelled) after `mgr.Start` returns, on **both** the error path before `os.Exit(1)` and the clean path. Earlier `os.Exit` sites have nothing to flush. +- `cfg := ctrl.GetConfigOrDie(); cfg.Wrap(tracing.RestConfigWrapper())` before `ctrl.NewManager` (cmd/main.go:239). +- kubernetes provider: add `kubernetes.NewWithTransportWrapper(ctx, cfg, wrap transport.WrapperFunc)` beside `New` (internal/provider/kubernetes/kubernetes.go:42) and register a closure in main's constructor map (same pattern as gcp at cmd/main.go:166) passing `tracing.RestConfigWrapper()` — keeps `internal/tracing` out of provider packages and `newWithClient` tests untouched. +- New flag `--trace-health-probes` (default false) → `engine.TraceProbes`. + +### Step 5 — Reconciler spans + +- `SetupWithManager` (proxy_controller.go:412): `b.Complete(tracing.NewReconciler("Proxy", r))`. +- Sub-spans via `tracing.Start`: `reconcile.managed` (:116), `reconcile.replaceInstance` (:226), `reconcile.delete` (:254), and `status.patch` opened **inside the deferred flush closure** (:98-104, runs within the root span; its error already folds into `err`). `reconcileExternal` stays unspanned — no I/O, pure noise. +- Useful attrs where cheap: phase transitions, `providerID`. + +### Step 6 — Discovery server + +- `handler()` (internal/discovery/server.go:151-156): chain becomes recover → `tracing.HTTPMiddleware("discovery", s.log)` → log → maxBytes → auth (otelhttp must stay outside `maxBytesMiddleware`). +- Handlers and `logMiddleware`/`recoverMiddleware` switch `s.log` → `logf.FromContext(r.Context())` (handlers.go:85, :141, :234; server.go:163, :191) so request logs carry `traceID`. `s.log` remains for startup lines. +- k8s `List` calls in handlers already use `r.Context()` → child spans appear via the wrapped rest transport. + +### Step 7 — GC + health + +- `gc.Sweeper.sweep` (internal/gc/gc.go:83): wrap in root span `gc.sweep` via `tracing.Start` (before the `.WithName("orphan-gc")` derivation so it inherits), attrs: providers swept, orphans deleted. Provider/k8s child spans come free from Steps 3/4. +- `health.Engine`: new field `TraceProbes bool`. In the worker loop (engine.go:158) when enabled: root span `health.probe` (SpanKind Client) around `probeFn`, attrs proxy key/ok/latency/error class, ended before `record` (which stays ctx-free). No transport wrap and no propagation — never inject `traceparent` toward external targets through the proxies. Probe→reconcile span links are **out of scope**: `GenericEvent` (engine.go:330) carries no ctx and the workqueue coalesces events; documented in architecture Decisions. +- Lease store sweep: not traced (in-memory only). + +### Step 8 — GCP wire-log enrichment + +`wireFilterHandler.Handle` (internal/provider/gcp/wirelog.go:46) receives the real request ctx from the SDK's slog calls: append `traceID`/`spanID` attrs when `trace.SpanContextFromContext(ctx)` is valid — V(5) wire logs become correlatable with the `provider.*` span. Add `wirelog_test.go` case. + +### Step 9 — Manifests + docs + +- `config/manager/manager.yaml` env (after `DISCOVERY_TOKEN`): `POD_NAME`/`POD_NAMESPACE` via downward API **first**, then `OTEL_SERVICE_NAME`, `OTEL_RESOURCE_ATTRIBUTES: k8s.pod.name=$(POD_NAME),k8s.namespace.name=$(POD_NAMESPACE)` ($(VAR) expansion only sees earlier vars); commented-out `OTEL_EXPORTER_OTLP_ENDPOINT` + `OTEL_TRACES_SAMPLER` examples with a "tracing is off until an endpoint is set" comment. Note `--trace-health-probes` beside the args list. +- `docs/architecture.md`: new "### 10. Tracing" section after Metrics (:281) — span topology, enablement, `traceID` log-key choice; Decisions entries (:303): env-gated enablement, probes off by default, no probe→reconcile links (why), `traceID` naming vs Grafana defaults, no traceparent into apiserver. +- README ops note; CHANGELOG entry (dated via `date`) once the user confirms it works. +- Run `make lint` (CI has no lint step; `lll`/`revive` will hit new files). + +## Verification + +1. `make test` (unit, includes all new `tracetest` assertions) and `make lint`. +2. Console smoke: `OTEL_TRACES_EXPORTER=console go run ./cmd --providers-config hack/providers-dev.yaml ...` against kind — create a Proxy, confirm (a) `Reconcile Proxy` span JSON on stdout with nested `provider.create` + k8s PATCH spans, (b) the reconcile log lines carry the same `traceID` as the span, (c) no spans from informer watches or leader election. +3. End-to-end in kind: deploy Jaeger all-in-one (`jaegertracing/all-in-one`, OTLP 4318), set `OTEL_EXPORTER_OTLP_ENDPOINT=http://jaeger:4318` on the manager Deployment; exercise a reconcile + a `POST /v1/leases` (with and without a client `traceparent`) + wait one GC interval; in the Jaeger UI: reconcile trace shows provider+k8s children; lease trace shows route-named server span with k8s child; grep manager logs for a `traceID` and resolve it in Jaeger. +4. Negative: run with no `OTEL_*` env — startup line says tracing disabled, no export-error spam, logs unchanged (no `traceID` keys).