From 328877e000664f085de9534c279eefb3c135facf Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 10:26:21 +0200 Subject: [PATCH 01/13] Add plan: OTel tracing integrated with logr/zap logging Co-Authored-By: Claude --- docs/plans/2026-08-24-1025-otel-tracing.md | 107 +++++++++++++++++++++ 1 file changed, 107 insertions(+) create mode 100644 docs/plans/2026-08-24-1025-otel-tracing.md 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). -- 2.49.1 From b1a16774bf15c52b7936f6df9148622eef86b240 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 10:41:06 +0200 Subject: [PATCH 02/13] Align OTel deps at v1.45.0 and add trace exporter modules Co-Authored-By: Claude --- .../2026-08-24-1025-otel-tracing.md | 42 ++++++++++++++ go.mod | 26 +++++---- go.sum | 56 ++++++++++--------- 3 files changed, 86 insertions(+), 38 deletions(-) create mode 100644 docs/plans-executions/2026-08-24-1025-otel-tracing.md diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md new file mode 100644 index 0000000..b36a61c --- /dev/null +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -0,0 +1,42 @@ +# Execution log: OpenTelemetry tracing integrated with logr/zap logging + +Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` + +- [x] Step 1 — Dependencies +- [ ] Step 2 — New package `internal/tracing` +- [ ] Step 3 — `provider.WithTracing` decorator +- [ ] Step 4 — `cmd/main.go` wiring +- [ ] Step 5 — Reconciler spans +- [ ] Step 6 — Discovery server +- [ ] Step 7 — GC + health +- [ ] Step 8 — GCP wire-log enrichment +- [ ] Step 9 — Manifests + docs + +## Step 1 — Dependencies + +Aligned the pre-existing indirect skew (otel core v1.44.0 vs otlptrace exporters +v1.40.0) and added the new direct deps in one shot: + +```bash +go get go.opentelemetry.io/otel@v1.45.0 \ + go.opentelemetry.io/otel/sdk@v1.45.0 \ + go.opentelemetry.io/otel/trace@v1.45.0 \ + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc@v1.45.0 \ + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp@v1.45.0 \ + go.opentelemetry.io/otel/exporters/stdout/stdouttrace@v1.45.0 \ + go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp@v0.70.0 +go mod tidy +``` + +MVS side-effects worth recording: `logr v1.4.3→v1.4.4`, `httpsnoop +v1.0.4→v1.1.0`, `grpc-gateway/v2 v2.27.7→v2.29.0`, `proto/otlp v1.9.0→v1.11.0`, +plus a `genproto/googleapis/api` pseudo-version bump. Full `make test` passed +against the bumped graph (`google.golang.org/api v0.292.0` and k8s v0.36 +tolerate otelhttp v0.70.0). + +Worth noting: the first `go mod tidy` ran *before* any first-party code +imported `otlptracehttp`/`stdouttrace`, so it silently dropped those two +modules again; the Step 2 tidy re-added them. The plan's semconv question +resolved to `semconv/v1.43.0` — that's what `sdk@v1.45.0/resource/builtin.go` +imports, so first-party code uses the same version to avoid +`ErrSchemaURLConflict` in the common path. diff --git a/go.mod b/go.mod index de4d5ef..48cfaa6 100644 --- a/go.mod +++ b/go.mod @@ -4,10 +4,17 @@ go 1.26.0 require ( cloud.google.com/go/compute v1.65.0 - github.com/go-logr/logr v1.4.3 + github.com/go-logr/logr v1.4.4 github.com/onsi/ginkgo/v2 v2.27.4 github.com/onsi/gomega v1.39.0 github.com/prometheus/client_golang v1.23.2 + go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0 + go.opentelemetry.io/otel v1.45.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.45.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.45.0 + go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.45.0 + go.opentelemetry.io/otel/sdk v1.45.0 + go.opentelemetry.io/otel/trace v1.45.0 google.golang.org/api v0.292.0 google.golang.org/protobuf v1.36.12-0.20260120151049-f2248ac996af k8s.io/api v0.36.0 @@ -31,7 +38,7 @@ require ( github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc // indirect github.com/emicklei/go-restful/v3 v3.13.0 // indirect github.com/evanphx/json-patch/v5 v5.9.11 // indirect - github.com/felixge/httpsnoop v1.0.4 // indirect + github.com/felixge/httpsnoop v1.1.0 // indirect github.com/fsnotify/fsnotify v1.9.0 // indirect github.com/fxamacker/cbor/v2 v2.9.0 // indirect github.com/go-logr/stdr v1.2.2 // indirect @@ -48,7 +55,7 @@ require ( github.com/google/uuid v1.6.0 // indirect github.com/googleapis/enterprise-certificate-proxy v0.3.19 // indirect github.com/googleapis/gax-go/v2 v2.23.0 // indirect - github.com/grpc-ecosystem/grpc-gateway/v2 v2.27.7 // indirect + github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0 // indirect github.com/inconshreveable/mousetrap v1.1.0 // indirect github.com/josharian/intern v1.0.0 // indirect github.com/json-iterator/go v1.1.12 // indirect @@ -66,14 +73,9 @@ require ( github.com/stoewer/go-strcase v1.3.0 // indirect github.com/x448/float16 v0.8.4 // indirect go.opentelemetry.io/auto/sdk v1.2.1 // indirect - go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.67.0 // indirect - go.opentelemetry.io/otel v1.44.0 // indirect - go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.40.0 // indirect - go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.40.0 // indirect - go.opentelemetry.io/otel/metric v1.44.0 // indirect - go.opentelemetry.io/otel/sdk v1.44.0 // indirect - go.opentelemetry.io/otel/trace v1.44.0 // indirect - go.opentelemetry.io/proto/otlp v1.9.0 // indirect + go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.45.0 // indirect + go.opentelemetry.io/otel/metric v1.45.0 // indirect + go.opentelemetry.io/proto/otlp v1.11.0 // indirect go.uber.org/multierr v1.11.0 // indirect go.uber.org/zap v1.27.1 // indirect go.yaml.in/yaml/v2 v2.4.3 // indirect @@ -91,7 +93,7 @@ require ( golang.org/x/tools v0.47.0 // indirect gomodules.xyz/jsonpatch/v2 v2.4.0 // indirect google.golang.org/genproto v0.0.0-20260319201613-d00831a3d3e7 // indirect - google.golang.org/genproto/googleapis/api v0.0.0-20260630182238-925bb5da69e7 // indirect + google.golang.org/genproto/googleapis/api v0.0.0-20260803160001-6ac0973c030d // indirect google.golang.org/genproto/googleapis/rpc v0.0.0-20260803160001-6ac0973c030d // indirect google.golang.org/grpc v1.83.0 // indirect gopkg.in/evanphx/json-patch.v4 v4.13.0 // indirect diff --git a/go.sum b/go.sum index ed91e89..152847c 100644 --- a/go.sum +++ b/go.sum @@ -34,8 +34,8 @@ github.com/evanphx/json-patch v0.5.2 h1:xVCHIVMUu1wtM/VkR9jVZ45N3FhZfYMMYGorLCR8 github.com/evanphx/json-patch v0.5.2/go.mod h1:ZWS5hhDbVDyob71nXKNL0+PWn6ToqBHMikGIFbs31qQ= github.com/evanphx/json-patch/v5 v5.9.11 h1:/8HVnzMq13/3x9TPvjG08wUGqBTmZBsCWzjTM0wiaDU= github.com/evanphx/json-patch/v5 v5.9.11/go.mod h1:3j+LviiESTElxA4p3EMKAB9HXj3/XEtnUf6OZxqIQTM= -github.com/felixge/httpsnoop v1.0.4 h1:NFTV2Zj1bL4mc9sqWACXbQFVBBg2W3GPvqp8/ESS2Wg= -github.com/felixge/httpsnoop v1.0.4/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U= +github.com/felixge/httpsnoop v1.1.0 h1:3YtUj32ZZkqZtt3sZZsClsymw/QDuVfpNhoA31zeORc= +github.com/felixge/httpsnoop v1.1.0/go.mod h1:Zqxgdd+1Rkcz8euOqdr7lqgCRJztwr5hp9vDSi5UZCE= github.com/fsnotify/fsnotify v1.9.0 h1:2Ml+OJNzbYCTzsxtv8vKSFD9PbJjmhYF14k/jKC7S9k= github.com/fsnotify/fsnotify v1.9.0/go.mod h1:8jBTzvmWwFyi3Pb8djgCCO5IBqzKJ/Jwo8TRcHyHii0= github.com/fxamacker/cbor/v2 v2.9.0 h1:NpKPmjDBgUfBms6tr6JZkTHtfFGcMKsw3eGcmD/sapM= @@ -47,8 +47,8 @@ github.com/gkampitakis/go-diff v1.3.2/go.mod h1:LLgOrpqleQe26cte8s36HTWcTmMEur6O github.com/gkampitakis/go-snaps v0.5.15 h1:amyJrvM1D33cPHwVrjo9jQxX8g/7E2wYdZ+01KS3zGE= github.com/gkampitakis/go-snaps v0.5.15/go.mod h1:HNpx/9GoKisdhw9AFOBT1N7DBs9DiHo/hGheFGBZ+mc= github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= -github.com/go-logr/logr v1.4.3 h1:CjnDlHq8ikf6E492q6eKboGOC0T8CDaOvkHCIg8idEI= -github.com/go-logr/logr v1.4.3/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= +github.com/go-logr/logr v1.4.4 h1:tG4xh9yMsRCAiodLVTxyrkzSZ9+o0L1Kg/+cPVcbP/8= +github.com/go-logr/logr v1.4.4/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= github.com/go-logr/zapr v1.3.0 h1:XGdV8XW8zdwFiwOA2Dryh1gj2KRQyOOoNmBy4EplIcQ= @@ -86,8 +86,8 @@ github.com/googleapis/enterprise-certificate-proxy v0.3.19 h1:mMOE7DN2+p76/EdIrm github.com/googleapis/enterprise-certificate-proxy v0.3.19/go.mod h1:rSEsBUemEBZEexP2y6jPp16LUmUbjmSbcPMQizR0o4k= github.com/googleapis/gax-go/v2 v2.23.0 h1:Tchl7qkvE7Ip3y+ztvNufYFvkfqTe7NfLTYGIdJRLuE= github.com/googleapis/gax-go/v2 v2.23.0/go.mod h1:rBQKOVJCdb8IFEzg+FCwlt1LP/xMDGuqUXhUG+XMXEg= -github.com/grpc-ecosystem/grpc-gateway/v2 v2.27.7 h1:X+2YciYSxvMQK0UZ7sg45ZVabVZBeBuvMkmuI2V3Fak= -github.com/grpc-ecosystem/grpc-gateway/v2 v2.27.7/go.mod h1:lW34nIZuQ8UDPdkon5fmfp2l3+ZkQ2me/+oecHYLOII= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0 h1:5VipnvEpbqr2gA2VbM+nYVbkIF28c5ZQfqCBQ5g2xfk= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0/go.mod h1:Hyl3n6Twe1hvtd9XUXDec4pTvgMSEixRuQKPTMH2bNs= github.com/inconshreveable/mousetrap v1.1.0 h1:wN+x4NVGpMsO7ErUn/mUI3vEoE6Jt13X2s0bqwp9tc8= github.com/inconshreveable/mousetrap v1.1.0/go.mod h1:vpF70FUmC8bwa3OWnCshd2FqLfsEA9PFc4w1p2J65bw= github.com/josharian/intern v1.0.0 h1:vlS4z54oSdjm0bgjRigI+G1HpF+tI+9rE5LLzOg8HmY= @@ -170,24 +170,28 @@ github.com/x448/float16 v0.8.4 h1:qLwI1I70+NjRFUR3zs1JPUCgaCXSh3SW62uAKT1mSBM= github.com/x448/float16 v0.8.4/go.mod h1:14CWIYCyZA/cWjXOioeEpHeN/83MdbZDRQHoFcYsOfg= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= -go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.67.0 h1:OyrsyzuttWTSur2qN/Lm0m2a8yqyIjUVBZcxFPuXq2o= -go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.67.0/go.mod h1:C2NGBr+kAB4bk3xtMXfZ94gqFDtg/GkI7e9zqGh5Beg= -go.opentelemetry.io/otel v1.44.0 h1:JjwHmHpA4iZ3wBxluu2fbbE7j4kqlE8jXyAyPXH7HqU= -go.opentelemetry.io/otel v1.44.0/go.mod h1:BMgjTHL9WPRlRjL2oZCBTL4whCGtXch2H4BhOPIAyYc= -go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.40.0 h1:QKdN8ly8zEMrByybbQgv8cWBcdAarwmIPZ6FThrWXJs= -go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.40.0/go.mod h1:bTdK1nhqF76qiPoCCdyFIV+N/sRHYXYCTQc+3VCi3MI= -go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.40.0 h1:DvJDOPmSWQHWywQS6lKL+pb8s3gBLOZUtw4N+mavW1I= -go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.40.0/go.mod h1:EtekO9DEJb4/jRyN4v4Qjc2yA7AtfCBuz2FynRUWTXs= -go.opentelemetry.io/otel/metric v1.44.0 h1:1w0gILTcHdr3YI+ixLyjemwrVnsMURbTZFrSYCdDdmc= -go.opentelemetry.io/otel/metric v1.44.0/go.mod h1:8O7hanEPBNgEMmybD3s2VBKcgWOCsA6tzHBPODAiquo= -go.opentelemetry.io/otel/sdk v1.44.0 h1:nHYwb9lK+fJPU/dnT6s7W7Z8itMWyqrnVfbheVYrZ58= -go.opentelemetry.io/otel/sdk v1.44.0/go.mod h1:Osuydd3Se74nqjAKxid74N5eC+jfEqfTegHRnq58oK0= -go.opentelemetry.io/otel/sdk/metric v1.44.0 h1:3LlKgI+VjbVsjNRFZJZAJ30WjXC5VkNRks6si09iEfI= -go.opentelemetry.io/otel/sdk/metric v1.44.0/go.mod h1:5B5pMARnXxKhltooO4xUuCBorl65a4EpnTalObqOigA= -go.opentelemetry.io/otel/trace v1.44.0 h1:jxF5CsGYCe74MCRx2X4g7WsY/VBKRqqpNvXlX/6gtIk= -go.opentelemetry.io/otel/trace v1.44.0/go.mod h1:oLl1jrMQAVo6v3GAggN+1VH9VIz9iUSvW53sW1Q8PIE= -go.opentelemetry.io/proto/otlp v1.9.0 h1:l706jCMITVouPOqEnii2fIAuO3IVGBRPV5ICjceRb/A= -go.opentelemetry.io/proto/otlp v1.9.0/go.mod h1:xE+Cx5E/eEHw+ISFkwPLwCZefwVjY+pqKg1qcK03+/4= +go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0 h1:LMuyCAyfalSjDyjdC65nK6N0zoTT63+E/u95X0JovZI= +go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0/go.mod h1:085m8qbm4hgc8rZWGDEa4vmyyo2c3nPxUslYUKUIU04= +go.opentelemetry.io/otel v1.45.0 h1:pdrWmLHofpubmArBv1LgFSv1Z0Ie/ppdZzu+kUN5EeU= +go.opentelemetry.io/otel v1.45.0/go.mod h1:XZxIqPapzEYnhNSScF5DIqXhm/rYi0FzCe2XddAwZfQ= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.45.0 h1:QRefszxJmfPdjXUUm3j6iDzY03mTPXMjqErFqQ67vUg= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.45.0/go.mod h1:Tiz03lTBVBrm7eWZBOidzEaYaJa8tjwGUGv6d8mlTyk= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.45.0 h1:fG5MCxGz8+2VtrN/WgqSpJFctVz24gpxj8CxkKmc8Ww= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.45.0/go.mod h1:BmAYTn+3ysbRe+IU2msxmf5Rx3g6DHvex+tWI3LdhYI= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.45.0 h1:QBajQ2SrwQijzHyZbQlPsuIzpl/ll8DY6wPWsajeGcI= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.45.0/go.mod h1:08ZQLjrPLQ6R4kAXvuOvODEer5Yh4CoFvll5qB2BCI8= +go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.45.0 h1:lsA/S1bxgdbyFGkTj+3meEdJ6ADVU7QoFstV6MXgE68= +go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.45.0/go.mod h1:L7u+MirGoB1bjeLH66+xDykF4RC8C3RN7lIFpBiewUo= +go.opentelemetry.io/otel/metric v1.45.0 h1:7Eg1uH7CJ5cXv9is6tnBe1FI6rj1nwUdbFypRm3br/M= +go.opentelemetry.io/otel/metric v1.45.0/go.mod h1:HAPbm1nd3p1PmFH7v2dR+6BjXxw+Lq4a2+pndMAm08s= +go.opentelemetry.io/otel/sdk v1.45.0 h1:4VVSMgQ83dUgW2aoX5f6JgLvHwIvzcuLnF9lUdCSpCw= +go.opentelemetry.io/otel/sdk v1.45.0/go.mod h1:Sr40LgXV7DsKMMJMKOhUWOgMWTfAaqvm2kF0g7ilwuA= +go.opentelemetry.io/otel/sdk/metric v1.45.0 h1:oVFszMfyj1Am6s24Vtc7wBb8BKLcwepJjNEYILuiE3o= +go.opentelemetry.io/otel/sdk/metric v1.45.0/go.mod h1:vUWUxDZvu1WVRj8JA8S0AdhsPrZoDpA2DdZauIh4mDA= +go.opentelemetry.io/otel/trace v1.45.0 h1:l/mP6Uv7oNO7/TblbhpbgMidxhq1uO/rPsikOyVhxag= +go.opentelemetry.io/otel/trace v1.45.0/go.mod h1:qoJJA2xNMnxRrdISU/kLtfUH2wNeQbiv+jhs/CxI8bc= +go.opentelemetry.io/proto/otlp v1.11.0 h1:5rrYs0Ykyj50sdU/JU0x8etU+LubXWb+gED6TbEdMIk= +go.opentelemetry.io/proto/otlp v1.11.0/go.mod h1:SmVizdCOAm3XBtG1g1NnOdhW6jtddT72hLMhv8VwA8E= go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0= @@ -228,8 +232,8 @@ google.golang.org/api v0.292.0 h1:Ewiwo/GTtiaPZSNAZQUcWLh8AYDEoPmIXyJfeoTSMHU= google.golang.org/api v0.292.0/go.mod h1:07kjmMnFGm2RQuCza2EZM/5N68G/fVvFb1xKjWqoFA0= google.golang.org/genproto v0.0.0-20260319201613-d00831a3d3e7 h1:XzmzkmB14QhVhgnawEVsOn6OFsnpyxNPRY9QV01dNB0= google.golang.org/genproto v0.0.0-20260319201613-d00831a3d3e7/go.mod h1:L43LFes82YgSonw6iTXTxXUX1OlULt4AQtkik4ULL/I= -google.golang.org/genproto/googleapis/api v0.0.0-20260630182238-925bb5da69e7 h1:jQ9p21COKWjP3VwuFrNRiiOTMh3mPpN45R7SLrH/HUU= -google.golang.org/genproto/googleapis/api v0.0.0-20260630182238-925bb5da69e7/go.mod h1:KqHwBx2upmfa1XSi1WuRvC+2VGCLtooKkfmyvRbUmqA= +google.golang.org/genproto/googleapis/api v0.0.0-20260803160001-6ac0973c030d h1:FarXi840EJWSHYTN3ERkADbPWjl307+FGrA22KAVjjc= +google.golang.org/genproto/googleapis/api v0.0.0-20260803160001-6ac0973c030d/go.mod h1:K/+WGbmBY7aNW1HDw1fJnKYo10i0DkAX6pows00dLig= google.golang.org/genproto/googleapis/rpc v0.0.0-20260803160001-6ac0973c030d h1:IL4hdHzcUv2l/gcg98/Rj3FbtE6axwqslOW8SW0C+S0= google.golang.org/genproto/googleapis/rpc v0.0.0-20260803160001-6ac0973c030d/go.mod h1:4Hqkh8ycfw05ld/3BWL7rJOSfebL2Q+DVDeRgYgxUU8= google.golang.org/grpc v1.83.0 h1:JeNZEKJFbQxArAMl+hiytHauacDNqJUllNfmIMmpqnQ= -- 2.49.1 From 6b34f68469cdf29f0fc2eaeed7ce28712777825d Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 10:43:55 +0200 Subject: [PATCH 03/13] Add internal/tracing: env-gated OTel setup, span/log helpers, decorators Co-Authored-By: Claude --- .../2026-08-24-1025-otel-tracing.md | 29 +++- internal/tracing/http.go | 41 +++++ internal/tracing/http_test.go | 82 ++++++++++ internal/tracing/logger.go | 63 ++++++++ internal/tracing/logger_test.go | 136 +++++++++++++++++ internal/tracing/options.go | 48 ++++++ internal/tracing/reconciler.go | 52 +++++++ internal/tracing/reconciler_test.go | 86 +++++++++++ internal/tracing/tracing.go | 140 ++++++++++++++++++ internal/tracing/tracing_test.go | 129 ++++++++++++++++ internal/tracing/transport.go | 51 +++++++ internal/tracing/transport_test.go | 73 +++++++++ 12 files changed, 929 insertions(+), 1 deletion(-) create mode 100644 internal/tracing/http.go create mode 100644 internal/tracing/http_test.go create mode 100644 internal/tracing/logger.go create mode 100644 internal/tracing/logger_test.go create mode 100644 internal/tracing/options.go create mode 100644 internal/tracing/reconciler.go create mode 100644 internal/tracing/reconciler_test.go create mode 100644 internal/tracing/tracing.go create mode 100644 internal/tracing/tracing_test.go create mode 100644 internal/tracing/transport.go create mode 100644 internal/tracing/transport_test.go diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index b36a61c..39021a4 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -3,7 +3,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 1 — Dependencies -- [ ] Step 2 — New package `internal/tracing` +- [x] Step 2 — New package `internal/tracing` - [ ] Step 3 — `provider.WithTracing` decorator - [ ] Step 4 — `cmd/main.go` wiring - [ ] Step 5 — Reconciler spans @@ -40,3 +40,30 @@ modules again; the Step 2 tidy re-added them. The plan's semconv question resolved to `semconv/v1.43.0` — that's what `sdk@v1.45.0/resource/builtin.go` imports, so first-party code uses the same version to avoid `ErrSchemaURLConflict` in the common path. + +## Step 2 — `internal/tracing` package + +Landed as planned: `tracing.go` (env-gated `Setup`, hand-rolled exporter +selection), `logger.go` (`Start`/`StartSpan`/`ContextWithLogger` with the +base-logger ctx key that prevents duplicate `traceID` zap fields on nested +spans), `reconciler.go`, `transport.go`, `http.go`, `options.go`; tests for +all of it (first use of `sdk/trace/tracetest` in the repo). + +Two deviations from the plan's letter: + +- **k8s transport gating is a custom RoundTripper, not `otelhttp.WithFilter`** + (`parentGatedTransport`): requests without a parent span bypass the otel + transport entirely, so the no-root-spans-from-informers guarantee doesn't + depend on otelhttp filter semantics for transports. +- **`HTTPMiddleware` must copy the route pattern back.** The logger-injecting + inner handler wraps the request via `WithContext` (a shallow copy), so the + mux records the matched pattern on the copy while otelhttp's post-routing + span rename reads the original. Found by the middleware test (span named + `"GET"` instead of `"GET /v1/things/{id}"`); fixed with `r.Pattern = + r2.Pattern` after `next.ServeHTTP`. + +Also: both the transport and the middleware pass explicit W3C propagators +instead of relying on the global, so behavior is deterministic under tests +and when tracing is disabled. `Setup` tests reset the global provider to a +fresh noop per case — restoring otel's own default delegate triggers a +"Setting tracer provider to its current value" warning from the SDK. diff --git a/internal/tracing/http.go b/internal/tracing/http.go new file mode 100644 index 0000000..bcad955 --- /dev/null +++ b/internal/tracing/http.go @@ -0,0 +1,41 @@ +package tracing + +import ( + "net/http" + + "github.com/go-logr/logr" + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + "go.opentelemetry.io/otel/propagation" +) + +// HTTPMiddleware returns middleware that opens a server span per request +// (named from the mux route pattern once routing has happened) and hands +// handlers a request context whose logf.FromContext logger is base enriched +// with the trace context. Incoming W3C traceparent headers are honored, so +// clients see their own trace continue into the operator. /healthz is never +// traced. With tracing disabled the middleware degrades to injecting base +// unenriched — handlers can rely on logf.FromContext either way. +func HTTPMiddleware(operation string, base logr.Logger, opts ...Option) func(http.Handler) http.Handler { + o := newOptions(opts) + return func(next http.Handler) http.Handler { + inner := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + r2 := r.WithContext(ContextWithLogger(r.Context(), base)) + next.ServeHTTP(w, r2) + // WithContext copies the request, so the mux recorded the matched + // route on r2; surface it to otelhttp, which renames the span + // from r.Pattern after the handler returns. + r.Pattern = r2.Pattern + }) + otelOpts := []otelhttp.Option{ + otelhttp.WithFilter(func(r *http.Request) bool { return r.URL.Path != "/healthz" }), + // Explicit propagators: deterministic regardless of whether the + // global propagator has been installed (tests, disabled tracing). + otelhttp.WithPropagators(propagation.NewCompositeTextMapPropagator( + propagation.TraceContext{}, propagation.Baggage{})), + } + if o.tp != nil { + otelOpts = append(otelOpts, otelhttp.WithTracerProvider(o.tp)) + } + return otelhttp.NewHandler(inner, operation, otelOpts...) + } +} diff --git a/internal/tracing/http_test.go b/internal/tracing/http_test.go new file mode 100644 index 0000000..de9a1d9 --- /dev/null +++ b/internal/tracing/http_test.go @@ -0,0 +1,82 @@ +package tracing + +import ( + "context" + "net/http" + "net/http/httptest" + "strings" + "testing" + + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + logf "sigs.k8s.io/controller-runtime/pkg/log" +) + +const sampleTraceparent = "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" + +func TestHTTPMiddleware(t *testing.T) { + t.Parallel() + + newServer := func(lines *[]string, tp *sdktrace.TracerProvider) http.Handler { + mux := http.NewServeMux() + handler := func(w http.ResponseWriter, r *http.Request) { + logf.FromContext(r.Context()).Info("handling") + w.WriteHeader(http.StatusOK) + } + mux.HandleFunc("GET /healthz", handler) + mux.HandleFunc("GET /v1/things/{id}", handler) + return HTTPMiddleware("discovery", captureLogger(lines), WithTracerProvider(tp))(mux) + } + + t.Run("route span, enriched handler logs, traceparent continuation", func(t *testing.T) { + t.Parallel() + sr := tracetest.NewSpanRecorder() + tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + + var lines []string + rec := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodGet, "/v1/things/42", nil) + req.Header.Set("traceparent", sampleTraceparent) + newServer(&lines, tp).ServeHTTP(rec, req) + + ended := sr.Ended() + if len(ended) != 1 { + t.Fatalf("got %d spans, want 1", len(ended)) + } + if got := ended[0].Name(); got != "GET /v1/things/{id}" { + t.Errorf("span name = %q, want route pattern", got) + } + wantTrace := "4bf92f3577b34da6a3ce929d0e0e4736" + if got := ended[0].SpanContext().TraceID().String(); got != wantTrace { + t.Errorf("span traceID = %s, want continuation of client trace %s", got, wantTrace) + } + if len(lines) != 1 { + t.Fatalf("got %d log lines, want 1: %v", len(lines), lines) + } + if n := strings.Count(lines[0], `"traceID"`); n != 1 { + t.Errorf("traceID appears %d times, want 1: %s", n, lines[0]) + } + if !strings.Contains(lines[0], wantTrace) { + t.Errorf("handler log missing traceID %s: %s", wantTrace, lines[0]) + } + }) + + t.Run("healthz is not traced but still gets a logger", func(t *testing.T) { + t.Parallel() + sr := tracetest.NewSpanRecorder() + tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + + var lines []string + rec := httptest.NewRecorder() + newServer(&lines, tp).ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/healthz", nil)) + + if len(sr.Ended()) != 0 { + t.Fatalf("healthz produced %d spans, want 0", len(sr.Ended())) + } + if len(lines) != 1 || strings.Contains(lines[0], "traceID") { + t.Fatalf("want one unenriched log line, got %v", lines) + } + }) +} diff --git a/internal/tracing/logger.go b/internal/tracing/logger.go new file mode 100644 index 0000000..042bd1d --- /dev/null +++ b/internal/tracing/logger.go @@ -0,0 +1,63 @@ +package tracing + +import ( + "context" + + "github.com/go-logr/logr" + "go.opentelemetry.io/otel/trace" + logf "sigs.k8s.io/controller-runtime/pkg/log" +) + +// baseLoggerKey stores the pre-enrichment logger. logr sinks never see a +// context, so trace IDs must ride on the logger as WithValues — and zap does +// not dedupe repeated keys, so each nested span must re-derive from the same +// base instead of stacking traceID/spanID onto an already-enriched logger. +type baseLoggerKey struct{} + +// Start begins a span from the global tracer and returns a context whose +// logf.FromContext logger carries the span's traceID/spanID. With tracing +// disabled the span is a no-op with an invalid span context and the logger +// is left untouched. +// +// Trade-off, documented: values pushed via logf.IntoContext *between* two +// Start calls are dropped by the inner Start's re-derivation. Nothing +// first-party does that; controller-runtime's per-reconcile logger +// (reconcileID etc.) is captured as the base and survives. +func Start(ctx context.Context, name string, opts ...trace.SpanStartOption) (context.Context, trace.Span) { + return StartSpan(ctx, newOptions(nil).tracer(), name, opts...) +} + +// StartSpan is Start with an explicit tracer, for decorators that carry +// their own (test-injected) TracerProvider. +func StartSpan(ctx context.Context, tracer trace.Tracer, name string, opts ...trace.SpanStartOption) (context.Context, trace.Span) { + ctx, span := tracer.Start(ctx, name, opts...) + sc := span.SpanContext() + if !sc.IsValid() { + return ctx, span + } + base, ok := ctx.Value(baseLoggerKey{}).(logr.Logger) + if !ok { + base = logf.FromContext(ctx) + ctx = context.WithValue(ctx, baseLoggerKey{}, base) + } + return logf.IntoContext(ctx, withSpanValues(base, sc)), span +} + +// ContextWithLogger seeds ctx with base as both the current logger and the +// base for span enrichment. If ctx already carries a valid span (the HTTP +// middleware calls this inside the otelhttp handler), the logger is +// enriched immediately. +func ContextWithLogger(ctx context.Context, base logr.Logger) context.Context { + ctx = context.WithValue(ctx, baseLoggerKey{}, base) + if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { + return logf.IntoContext(ctx, withSpanValues(base, sc)) + } + return logf.IntoContext(ctx, base) +} + +// withSpanValues uses lowerCamel keys to match the house style +// (reconcileID, providerID); Grafana/Loki derived fields must match +// "traceID", not the trace_id default. +func withSpanValues(base logr.Logger, sc trace.SpanContext) logr.Logger { + return base.WithValues("traceID", sc.TraceID().String(), "spanID", sc.SpanID().String()) +} diff --git a/internal/tracing/logger_test.go b/internal/tracing/logger_test.go new file mode 100644 index 0000000..555fa38 --- /dev/null +++ b/internal/tracing/logger_test.go @@ -0,0 +1,136 @@ +package tracing + +import ( + "context" + "strings" + "testing" + + "github.com/go-logr/logr" + "github.com/go-logr/logr/funcr" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" + "go.opentelemetry.io/otel/trace/noop" + logf "sigs.k8s.io/controller-runtime/pkg/log" +) + +// captureLogger records every emitted line so tests can assert on the +// rendered key/value output — the only place duplicate zap-style keys +// would show up. +func captureLogger(lines *[]string) logr.Logger { + return funcr.New(func(prefix, args string) { + *lines = append(*lines, prefix+" "+args) + }, funcr.Options{}) +} + +func recordingTracer(t *testing.T) (trace.Tracer, *tracetest.SpanRecorder) { + t.Helper() + sr := tracetest.NewSpanRecorder() + tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + return tp.Tracer("test"), sr +} + +func TestStartSpan_enrichesLoggerOncePerNesting(t *testing.T) { + t.Parallel() + tracer, sr := recordingTracer(t) + + var lines []string + ctx := logf.IntoContext(context.Background(), captureLogger(&lines)) + + ctx1, span1 := StartSpan(ctx, tracer, "outer") + logf.FromContext(ctx1).Info("outer work") + + ctx2, span2 := StartSpan(ctx1, tracer, "inner") + logf.FromContext(ctx2).Info("inner work") + + span2.End() + span1.End() + + if len(lines) != 2 { + t.Fatalf("got %d log lines, want 2: %v", len(lines), lines) + } + traceID := span1.SpanContext().TraceID().String() + for i, want := range []string{span1.SpanContext().SpanID().String(), span2.SpanContext().SpanID().String()} { + if n := strings.Count(lines[i], `"traceID"`); n != 1 { + t.Errorf("line %d: traceID appears %d times, want exactly 1: %s", i, n, lines[i]) + } + if n := strings.Count(lines[i], `"spanID"`); n != 1 { + t.Errorf("line %d: spanID appears %d times, want exactly 1: %s", i, n, lines[i]) + } + if !strings.Contains(lines[i], traceID) { + t.Errorf("line %d: missing traceID %s: %s", i, traceID, lines[i]) + } + if !strings.Contains(lines[i], want) { + t.Errorf("line %d: missing spanID %s: %s", i, want, lines[i]) + } + } + + ended := sr.Ended() + if len(ended) != 2 { + t.Fatalf("got %d spans, want 2", len(ended)) + } + // Ended in LIFO order: inner first. + if got := ended[0].Parent().SpanID(); got != span1.SpanContext().SpanID() { + t.Errorf("inner span parent = %s, want %s", got, span1.SpanContext().SpanID()) + } +} + +func TestStartSpan_noopTracerLeavesLoggerUntouched(t *testing.T) { + t.Parallel() + + var lines []string + ctx := logf.IntoContext(context.Background(), captureLogger(&lines)) + + ctx, span := StartSpan(ctx, noop.NewTracerProvider().Tracer("test"), "op") + defer span.End() + logf.FromContext(ctx).Info("work") + + if len(lines) != 1 { + t.Fatalf("got %d log lines, want 1", len(lines)) + } + if strings.Contains(lines[0], "traceID") { + t.Errorf("disabled tracing must not add traceID: %s", lines[0]) + } +} + +func TestContextWithLogger(t *testing.T) { + t.Parallel() + tracer, _ := recordingTracer(t) + + t.Run("no span injects base as-is", func(t *testing.T) { + t.Parallel() + var lines []string + ctx := ContextWithLogger(context.Background(), captureLogger(&lines)) + logf.FromContext(ctx).Info("plain") + if len(lines) != 1 || strings.Contains(lines[0], "traceID") { + t.Fatalf("want one line without traceID, got %v", lines) + } + }) + + t.Run("existing span enriches immediately and nested Start does not stack", func(t *testing.T) { + t.Parallel() + var lines []string + ctx, outer := tracer.Start(context.Background(), "server") + defer outer.End() + + ctx = ContextWithLogger(ctx, captureLogger(&lines)) + logf.FromContext(ctx).Info("handler") + + ctx, inner := StartSpan(ctx, tracer, "child") + defer inner.End() + logf.FromContext(ctx).Info("nested") + + if len(lines) != 2 { + t.Fatalf("got %d lines, want 2: %v", len(lines), lines) + } + for i, line := range lines { + if n := strings.Count(line, `"traceID"`); n != 1 { + t.Errorf("line %d: traceID appears %d times, want 1: %s", i, n, line) + } + } + if !strings.Contains(lines[1], inner.SpanContext().SpanID().String()) { + t.Errorf("nested line should carry the child spanID: %s", lines[1]) + } + }) +} diff --git a/internal/tracing/options.go b/internal/tracing/options.go new file mode 100644 index 0000000..07ac486 --- /dev/null +++ b/internal/tracing/options.go @@ -0,0 +1,48 @@ +package tracing + +import ( + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/trace" +) + +// tracerName is the instrumentation scope for every span this module emits. +const tracerName = "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator" + +type options struct { + tp trace.TracerProvider +} + +// Option configures the tracing decorators. The zero configuration uses the +// global TracerProvider installed by Setup; tests inject their own recorder +// via WithTracerProvider so they can run in parallel without touching +// process-global state. +type Option func(*options) + +// WithTracerProvider overrides the global TracerProvider. +func WithTracerProvider(tp trace.TracerProvider) Option { + return func(o *options) { o.tp = tp } +} + +func newOptions(opts []Option) options { + var o options + for _, opt := range opts { + opt(&o) + } + return o +} + +// Tracer resolves a tracer from the given options, for decorators outside +// this package (provider.WithTracing). +func Tracer(opts ...Option) trace.Tracer { + return newOptions(opts).tracer() +} + +// tracer resolves the configured tracer. The global path goes through +// otel.Tracer, which delegates to whatever provider Setup installs later — +// construction order between decorators and Setup does not matter. +func (o options) tracer() trace.Tracer { + if o.tp != nil { + return o.tp.Tracer(tracerName) + } + return otel.Tracer(tracerName) +} diff --git a/internal/tracing/reconciler.go b/internal/tracing/reconciler.go new file mode 100644 index 0000000..82c6216 --- /dev/null +++ b/internal/tracing/reconciler.go @@ -0,0 +1,52 @@ +package tracing + +import ( + "context" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" + "sigs.k8s.io/controller-runtime/pkg/controller" + "sigs.k8s.io/controller-runtime/pkg/reconcile" +) + +// NewReconciler wraps inner so every reconcile runs in a root span named +// "Reconcile " and every log line under it carries the trace context. +// Reconciles are triggered by watch events with no incoming trace to +// continue, so each one starts a new trace. +func NewReconciler(kind string, inner reconcile.Reconciler, opts ...Option) reconcile.Reconciler { + return &tracedReconciler{ + spanName: "Reconcile " + kind, + inner: inner, + tracer: newOptions(opts).tracer(), + } +} + +type tracedReconciler struct { + spanName string + inner reconcile.Reconciler + tracer trace.Tracer +} + +func (t *tracedReconciler) Reconcile(ctx context.Context, req reconcile.Request) (reconcile.Result, error) { + ctx, span := StartSpan(ctx, t.tracer, t.spanName, + trace.WithAttributes( + attribute.String("k8s.namespace.name", req.Namespace), + attribute.String("k8s.object.name", req.Name), + )) + defer span.End() + if id := controller.ReconcileIDFromContext(ctx); id != "" { + span.SetAttributes(attribute.String("reconcile.id", string(id))) + } + + res, err := t.inner.Reconcile(ctx, req) + if err != nil { + span.SetStatus(codes.Error, err.Error()) + return res, err + } + span.SetStatus(codes.Ok, "") + if res.RequeueAfter > 0 { + span.SetAttributes(attribute.Int64("reconcile.requeue_after_ms", res.RequeueAfter.Milliseconds())) + } + return res, nil +} diff --git a/internal/tracing/reconciler_test.go b/internal/tracing/reconciler_test.go new file mode 100644 index 0000000..684d1d9 --- /dev/null +++ b/internal/tracing/reconciler_test.go @@ -0,0 +1,86 @@ +package tracing + +import ( + "context" + "errors" + "testing" + "time" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "k8s.io/apimachinery/pkg/types" + "sigs.k8s.io/controller-runtime/pkg/reconcile" +) + +type fakeReconciler struct { + res reconcile.Result + err error +} + +func (f *fakeReconciler) Reconcile(context.Context, reconcile.Request) (reconcile.Result, error) { + return f.res, f.err +} + +func TestNewReconciler_spanPerReconcile(t *testing.T) { + t.Parallel() + + req := reconcile.Request{NamespacedName: types.NamespacedName{Namespace: "default", Name: "p1"}} + + tests := []struct { + name string + inner *fakeReconciler + wantStatus codes.Code + wantAttr attribute.KeyValue + }{ + { + name: "success records requeue", + inner: &fakeReconciler{res: reconcile.Result{RequeueAfter: 10 * time.Second}}, + wantStatus: codes.Ok, + wantAttr: attribute.Int64("reconcile.requeue_after_ms", 10_000), + }, + { + name: "error sets error status", + inner: &fakeReconciler{err: errors.New("boom")}, + wantStatus: codes.Error, + wantAttr: attribute.String("k8s.object.name", "p1"), + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + sr := tracetest.NewSpanRecorder() + tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + + r := NewReconciler("Proxy", tc.inner, WithTracerProvider(tp)) + res, err := r.Reconcile(context.Background(), req) + if res != tc.inner.res || !errors.Is(err, tc.inner.err) { + t.Fatalf("decorator changed the result: (%v, %v)", res, err) + } + + ended := sr.Ended() + if len(ended) != 1 { + t.Fatalf("got %d spans, want 1", len(ended)) + } + span := ended[0] + if span.Name() != "Reconcile Proxy" { + t.Errorf("span name = %q, want %q", span.Name(), "Reconcile Proxy") + } + if span.Status().Code != tc.wantStatus { + t.Errorf("status = %v, want %v", span.Status().Code, tc.wantStatus) + } + found := false + for _, a := range span.Attributes() { + if a == tc.wantAttr { + found = true + } + } + if !found { + t.Errorf("attribute %v missing in %v", tc.wantAttr, span.Attributes()) + } + }) + } +} diff --git a/internal/tracing/tracing.go b/internal/tracing/tracing.go new file mode 100644 index 0000000..4801d28 --- /dev/null +++ b/internal/tracing/tracing.go @@ -0,0 +1,140 @@ +// Package tracing wires OpenTelemetry tracing into the operator: SDK setup +// gated on standard OTEL_* environment variables, span helpers that keep the +// logr/zap logging enriched with trace context, and decorators for the +// reconciler, providers, HTTP server, and Kubernetes API transport. +package tracing + +import ( + "context" + "fmt" + "os" + "strings" + + "github.com/go-logr/logr" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" + "go.opentelemetry.io/otel/exporters/stdout/stdouttrace" + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/sdk/resource" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" +) + +// maxQueueSize bounds the batch processor's span buffer; the default 2048 +// is oversized for this process (3 concurrent reconciles, tickers) and the +// manager pod runs with a 128Mi memory limit. +const maxQueueSize = 512 + +// Setup initializes the global tracing pipeline from OTEL_* environment +// variables and returns a shutdown func that flushes pending spans. +// +// Tracing stays fully off — no exporter, no global provider, spans are +// no-ops, logs carry no traceID — unless the environment opts in by setting +// OTEL_TRACES_EXPORTER or an OTLP endpoint. OTEL_SDK_DISABLED=true and +// OTEL_TRACES_EXPORTER=none force it off (the Go SDK does not implement +// OTEL_SDK_DISABLED itself). Sampling, endpoints, TLS, and headers follow +// the standard SDK/exporter env vars (OTEL_TRACES_SAMPLER, OTEL_EXPORTER_OTLP_*). +func Setup(ctx context.Context, log logr.Logger, service, version string) (func(context.Context) error, error) { + noop := func(context.Context) error { return nil } + + exporterEnv := strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_TRACES_EXPORTER"))) + endpointSet := os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT") != "" || + os.Getenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT") != "" + sdkDisabled := strings.EqualFold(strings.TrimSpace(os.Getenv("OTEL_SDK_DISABLED")), "true") + + if sdkDisabled || exporterEnv == "none" || (exporterEnv == "" && !endpointSet) { + log.Info("tracing disabled", + "reason", disabledReason(sdkDisabled, exporterEnv)) + return noop, nil + } + + exp, expName, err := newExporter(ctx, exporterEnv) + if err != nil { + return noop, fmt.Errorf("tracing setup: %w", err) + } + + res, err := buildResource(ctx, service, version) + if err != nil { + if res == nil { + return noop, fmt.Errorf("tracing setup: building resource: %w", err) + } + // Schema-URL conflicts between semconv versions still yield a usable + // merged resource; keep it rather than losing tracing over metadata. + log.V(1).Info("tracing resource merge conflict; continuing", "err", err.Error()) + } + + tp := sdktrace.NewTracerProvider( + sdktrace.WithBatcher(exp, sdktrace.WithMaxQueueSize(maxQueueSize)), + sdktrace.WithResource(res), + ) + otel.SetTracerProvider(tp) + otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator( + propagation.TraceContext{}, propagation.Baggage{})) + otelLog := log.WithName("otel") + otel.SetLogger(otelLog) + // V(1), not Error: an unreachable collector fails every export cycle and + // would otherwise spam the error log every few seconds. + otel.SetErrorHandler(otel.ErrorHandlerFunc(func(err error) { + otelLog.V(1).Info("otel error", "err", err.Error()) + })) + + log.Info("tracing enabled", "exporter", expName, "service", service) + return tp.Shutdown, nil +} + +func disabledReason(sdkDisabled bool, exporterEnv string) string { + switch { + case sdkDisabled: + return "OTEL_SDK_DISABLED=true" + case exporterEnv == "none": + return "OTEL_TRACES_EXPORTER=none" + default: + return "no OTEL_TRACES_EXPORTER or OTLP endpoint configured" + } +} + +// newExporter hand-rolls the OTEL_TRACES_EXPORTER / OTEL_EXPORTER_OTLP_* +// protocol selection instead of pulling in contrib's autoexport, which drags +// metric/log/prometheus exporters into a trace-only binary. +func newExporter(ctx context.Context, kind string) (sdktrace.SpanExporter, string, error) { + switch kind { + case "", "otlp": + proto := strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_TRACES_PROTOCOL"))) + if proto == "" { + proto = strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_PROTOCOL"))) + } + switch proto { + case "", "http/protobuf": + exp, err := otlptracehttp.New(ctx) + return exp, "otlp/http", err + case "grpc": + exp, err := otlptracegrpc.New(ctx) + return exp, "otlp/grpc", err + default: + return nil, "", fmt.Errorf("unsupported OTLP protocol %q (supported: http/protobuf, grpc)", proto) + } + case "console": + exp, err := stdouttrace.New() + return exp, "console", err + default: + return nil, "", fmt.Errorf("unsupported OTEL_TRACES_EXPORTER %q (supported: otlp, console, none)", kind) + } +} + +// buildResource layers defaults < service identity < environment, so +// OTEL_SERVICE_NAME / OTEL_RESOURCE_ATTRIBUTES always win. +func buildResource(ctx context.Context, service, version string) (*resource.Resource, error) { + base, err := resource.Merge(resource.Default(), resource.NewWithAttributes(semconv.SchemaURL, + semconv.ServiceName(service), + semconv.ServiceVersion(version), + )) + if err != nil { + return base, err + } + env, err := resource.New(ctx, resource.WithFromEnv()) + if err != nil { + return base, err + } + return resource.Merge(base, env) +} diff --git a/internal/tracing/tracing_test.go b/internal/tracing/tracing_test.go new file mode 100644 index 0000000..b90310b --- /dev/null +++ b/internal/tracing/tracing_test.go @@ -0,0 +1,129 @@ +package tracing + +import ( + "context" + "testing" + "time" + + "github.com/go-logr/logr" + "go.opentelemetry.io/otel" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/trace/noop" +) + +// clearOTelEnv pins every env var Setup reads, so developer shells with +// OTEL_* set can't change test outcomes. Not parallel-safe by design +// (t.Setenv forbids t.Parallel). +func clearOTelEnv(t *testing.T) { + t.Helper() + for _, k := range []string{ + "OTEL_SDK_DISABLED", + "OTEL_TRACES_EXPORTER", + "OTEL_EXPORTER_OTLP_ENDPOINT", + "OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", + "OTEL_EXPORTER_OTLP_PROTOCOL", + "OTEL_EXPORTER_OTLP_TRACES_PROTOCOL", + } { + t.Setenv(k, "") + } +} + +func TestSetup_envGating(t *testing.T) { + tests := []struct { + name string + env map[string]string + wantEnabled bool + wantErr bool + }{ + {name: "no env means disabled", env: nil, wantEnabled: false}, + { + name: "endpoint enables otlp", + env: map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": "http://localhost:4318"}, + wantEnabled: true, + }, + { + name: "traces endpoint enables otlp", + env: map[string]string{"OTEL_EXPORTER_OTLP_TRACES_ENDPOINT": "http://localhost:4318"}, + wantEnabled: true, + }, + { + name: "explicit console exporter", + env: map[string]string{"OTEL_TRACES_EXPORTER": "console"}, + wantEnabled: true, + }, + { + name: "grpc protocol", + env: map[string]string{"OTEL_TRACES_EXPORTER": "otlp", "OTEL_EXPORTER_OTLP_PROTOCOL": "grpc"}, + wantEnabled: true, + }, + { + name: "exporter none wins over endpoint", + env: map[string]string{ + "OTEL_TRACES_EXPORTER": "none", + "OTEL_EXPORTER_OTLP_ENDPOINT": "http://localhost:4318", + }, + wantEnabled: false, + }, + { + name: "OTEL_SDK_DISABLED wins over everything", + env: map[string]string{ + "OTEL_SDK_DISABLED": "true", + "OTEL_EXPORTER_OTLP_ENDPOINT": "http://localhost:4318", + }, + wantEnabled: false, + }, + { + name: "unsupported exporter errors", + env: map[string]string{"OTEL_TRACES_EXPORTER": "jaeger"}, + wantErr: true, + }, + { + name: "unsupported protocol errors", + env: map[string]string{ + "OTEL_TRACES_EXPORTER": "otlp", + "OTEL_EXPORTER_OTLP_PROTOCOL": "http/json", + }, + wantErr: true, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + clearOTelEnv(t) + for k, v := range tc.env { + t.Setenv(k, v) + } + // Fresh noop global per case: disabled paths must leave it + // untouched, and resetting avoids leaking one case's SDK + // provider into the next (or warning-prone restores of the + // process-default delegate). + before := noop.NewTracerProvider() + otel.SetTracerProvider(before) + + shutdown, err := Setup(context.Background(), logr.Discard(), "test-svc", "abc123") + if tc.wantErr { + if err == nil { + t.Fatal("want error, got nil") + } + return + } + if err != nil { + t.Fatalf("Setup: %v", err) + } + + _, isSDK := otel.GetTracerProvider().(*sdktrace.TracerProvider) + if isSDK != tc.wantEnabled { + t.Errorf("global provider is SDK = %v, want %v", isSDK, tc.wantEnabled) + } + if tc.wantEnabled && otel.GetTracerProvider() == before { + t.Error("enabled Setup must install a new global provider") + } + + ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) + defer cancel() + if err := shutdown(ctx); err != nil { + t.Errorf("shutdown: %v", err) + } + }) + } +} diff --git a/internal/tracing/transport.go b/internal/tracing/transport.go new file mode 100644 index 0000000..3968a05 --- /dev/null +++ b/internal/tracing/transport.go @@ -0,0 +1,51 @@ +package tracing + +import ( + "net/http" + + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/trace" + "k8s.io/client-go/transport" +) + +// RestConfigWrapper returns a rest.Config.Wrap-compatible wrapper that adds +// a client span to every Kubernetes API request already running inside a +// trace. Requests with no parent span pass through untouched: informer +// list/watch long-polls, leader-election renewals, and metrics authn would +// otherwise each become meaningless (and in the watch case, minutes-long) +// root spans. client-go applies Wrap innermost, so the span sees the final +// authenticated request. +func RestConfigWrapper(opts ...Option) transport.WrapperFunc { + o := newOptions(opts) + return func(rt http.RoundTripper) http.RoundTripper { + otelOpts := []otelhttp.Option{ + // Explicit propagators: deterministic regardless of global + // state. The apiserver ignores incoming traceparent (by + // design), so injection is harmless there. + otelhttp.WithPropagators(propagation.NewCompositeTextMapPropagator( + propagation.TraceContext{}, propagation.Baggage{})), + } + if o.tp != nil { + otelOpts = append(otelOpts, otelhttp.WithTracerProvider(o.tp)) + } + return &parentGatedTransport{ + traced: otelhttp.NewTransport(rt, otelOpts...), + plain: rt, + } + } +} + +// parentGatedTransport enforces the parent-span requirement itself rather +// than relying on otelhttp filter semantics for transports. +type parentGatedTransport struct { + traced http.RoundTripper + plain http.RoundTripper +} + +func (t *parentGatedTransport) RoundTrip(r *http.Request) (*http.Response, error) { + if trace.SpanContextFromContext(r.Context()).IsValid() { + return t.traced.RoundTrip(r) + } + return t.plain.RoundTrip(r) +} diff --git a/internal/tracing/transport_test.go b/internal/tracing/transport_test.go new file mode 100644 index 0000000..6563dec --- /dev/null +++ b/internal/tracing/transport_test.go @@ -0,0 +1,73 @@ +package tracing + +import ( + "context" + "io" + "net/http" + "net/http/httptest" + "testing" + + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" +) + +func TestRestConfigWrapper_parentGated(t *testing.T) { + t.Parallel() + + var gotTraceparent string + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + gotTraceparent = r.Header.Get("traceparent") + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(srv.Close) + + sr := tracetest.NewSpanRecorder() + tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + + rt := RestConfigWrapper(WithTracerProvider(tp))(http.DefaultTransport) + do := func(ctx context.Context) { + t.Helper() + req, err := http.NewRequestWithContext(ctx, http.MethodGet, srv.URL, nil) + if err != nil { + t.Fatal(err) + } + resp, err := rt.RoundTrip(req) + if err != nil { + t.Fatal(err) + } + _, _ = io.Copy(io.Discard, resp.Body) + _ = resp.Body.Close() + } + + // No parent span: informer watches, leader election. Must not trace. + do(context.Background()) + if len(sr.Ended()) != 0 { + t.Fatalf("request without parent span produced %d spans, want 0", len(sr.Ended())) + } + if gotTraceparent != "" { + t.Fatalf("request without parent span injected traceparent %q", gotTraceparent) + } + + // Under a parent span: one client child span, traceparent injected. + ctx, parent := tp.Tracer("test").Start(context.Background(), "reconcile") + do(ctx) + parent.End() + + var client sdktrace.ReadOnlySpan + for _, s := range sr.Ended() { + if s.SpanKind() == trace.SpanKindClient { + client = s + } + } + if client == nil { + t.Fatalf("no client span recorded, got %d spans", len(sr.Ended())) + } + if got := client.Parent().SpanID(); got != parent.SpanContext().SpanID() { + t.Errorf("client span parent = %s, want %s", got, parent.SpanContext().SpanID()) + } + if gotTraceparent == "" { + t.Error("traceparent header not injected under a parent span") + } +} -- 2.49.1 From d15b06ec4560e4a3251d81609c2f91506f53265b Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 10:50:13 +0200 Subject: [PATCH 04/13] Add provider.WithTracing decorator mirroring WithMetrics Co-Authored-By: Claude --- .../2026-08-24-1025-otel-tracing.md | 16 ++- internal/provider/tracing.go | 80 ++++++++++++ internal/provider/tracing_test.go | 118 ++++++++++++++++++ 3 files changed, 213 insertions(+), 1 deletion(-) create mode 100644 internal/provider/tracing.go create mode 100644 internal/provider/tracing_test.go diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index 39021a4..3f28395 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -4,7 +4,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 1 — Dependencies - [x] Step 2 — New package `internal/tracing` -- [ ] Step 3 — `provider.WithTracing` decorator +- [x] Step 3 — `provider.WithTracing` decorator - [ ] Step 4 — `cmd/main.go` wiring - [ ] Step 5 — Reconciler spans - [ ] Step 6 — Discovery server @@ -67,3 +67,17 @@ instead of relying on the global, so behavior is deterministic under tests and when tracing is disabled. `Setup` tests reset the global provider to a fresh noop per case — restoring otel's own default delegate triggers a "Setting tracer provider to its current value" warning from the SDK. + +## Step 3 — `provider.WithTracing` + +`internal/provider/tracing.go` mirrors `metrics.go` exactly (same wrap shape, +same `resultLabel` classification reused as the `provider.result` span +attribute); tests reuse `staticProvider` from `metrics_test.go`. `ErrNotFound` +maps to span status Ok as planned — the reconciler polls `Get` to NotFound +during replacement/deletion, so it's an answer, not a failure. + +One small API addition to `internal/tracing` for this: exported +`tracing.Tracer(opts...)`, since the decorator lives in package `provider` +and couldn't reach the unexported option resolver. The `cmd/main.go` wiring +(`WithTracing` outermost around `WithMetrics`) lands with Step 4's commit — +same file, one commit. diff --git a/internal/provider/tracing.go b/internal/provider/tracing.go new file mode 100644 index 0000000..a07a492 --- /dev/null +++ b/internal/provider/tracing.go @@ -0,0 +1,80 @@ +package provider + +import ( + "context" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" + + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" +) + +// WithTracing wraps a Provider so every call runs in a client span carrying +// the classified result, mirroring WithMetrics. It goes through +// tracing.StartSpan, so provider-internal logs (e.g. the gcp provider's +// context logger) inherit traceID/spanID. Errors pass through unmodified. +func WithTracing(name string, p Provider, opts ...tracing.Option) Provider { + return &traced{name: name, inner: p, tracer: tracing.Tracer(opts...)} +} + +type traced struct { + name string + inner Provider + tracer trace.Tracer +} + +func (t *traced) Create(ctx context.Context, req CreateRequest) (string, error) { + ctx, span := t.start(ctx, "provider.create") + id, err := t.inner.Create(ctx, req) + if id != "" { + span.SetAttributes(attribute.String("provider.id", id)) + } + t.end(span, err) + return id, err +} + +func (t *traced) Get(ctx context.Context, providerID string) (*Instance, error) { + ctx, span := t.start(ctx, "provider.get") + span.SetAttributes(attribute.String("provider.id", providerID)) + inst, err := t.inner.Get(ctx, providerID) + t.end(span, err) + return inst, err +} + +func (t *traced) Delete(ctx context.Context, providerID string) error { + ctx, span := t.start(ctx, "provider.delete") + span.SetAttributes(attribute.String("provider.id", providerID)) + err := t.inner.Delete(ctx, providerID) + t.end(span, err) + return err +} + +func (t *traced) ListByTag(ctx context.Context) ([]Instance, error) { + ctx, span := t.start(ctx, "provider.list") + instances, err := t.inner.ListByTag(ctx) + span.SetAttributes(attribute.Int("provider.instances", len(instances))) + t.end(span, err) + return instances, err +} + +func (t *traced) start(ctx context.Context, op string) (context.Context, trace.Span) { + return tracing.StartSpan(ctx, t.tracer, op, + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attribute.String("provider.name", t.name))) +} + +// end records the taxonomy class and closes the span. ErrNotFound stays Ok: +// the reconciler polls Get to NotFound during replacement/deletion, so it is +// an expected answer, not a failure — same reasoning as resultLabel's +// distinct "not_found" bucket. +func (t *traced) end(span trace.Span, err error) { + span.SetAttributes(attribute.String("provider.result", resultLabel(err))) + switch Class(err) { + case nil, ErrNotFound: + span.SetStatus(codes.Ok, "") + default: + span.SetStatus(codes.Error, err.Error()) + } + span.End() +} diff --git a/internal/provider/tracing_test.go b/internal/provider/tracing_test.go new file mode 100644 index 0000000..cdb14c6 --- /dev/null +++ b/internal/provider/tracing_test.go @@ -0,0 +1,118 @@ +package provider + +import ( + "context" + "errors" + "slices" + "testing" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" + + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" +) + +func TestWithTracing_spanPerCall(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + inner *staticProvider + call func(p Provider) error + wantSpan string + wantStatus codes.Code + wantResult string + wantAttr attribute.KeyValue + }{ + { + name: "successful create", + inner: &staticProvider{}, + call: func(p Provider) error { _, err := p.Create(context.Background(), CreateRequest{}); return err }, + wantSpan: "provider.create", + wantStatus: codes.Ok, + wantResult: "ok", + wantAttr: attribute.String("provider.id", "id-1"), + }, + { + name: "get NotFound is not a span error", + inner: &staticProvider{getErr: Wrap(ErrNotFound, "get", "x", "id-1", nil)}, + call: func(p Provider) error { _, err := p.Get(context.Background(), "id-1"); return err }, + wantSpan: "provider.get", + wantStatus: codes.Ok, + wantResult: "not_found", + wantAttr: attribute.String("provider.id", "id-1"), + }, + { + name: "delete transient error", + inner: &staticProvider{deleteErr: Wrap(ErrTransient, "delete", "x", "id-1", errors.New("503"))}, + call: func(p Provider) error { return p.Delete(context.Background(), "id-1") }, + wantSpan: "provider.delete", + wantStatus: codes.Error, + wantResult: "transient", + wantAttr: attribute.String("provider.id", "id-1"), + }, + { + name: "quota exceeded create", + inner: &staticProvider{createErr: Wrap(ErrQuotaExceeded, "create", "x", "", nil)}, + call: func(p Provider) error { _, err := p.Create(context.Background(), CreateRequest{}); return err }, + wantSpan: "provider.create", + wantStatus: codes.Error, + wantResult: "quota_exceeded", + wantAttr: attribute.String("provider.name", "x"), + }, + { + name: "list records instance count", + inner: &staticProvider{}, + call: func(p Provider) error { _, err := p.ListByTag(context.Background()); return err }, + wantSpan: "provider.list", + wantStatus: codes.Ok, + wantResult: "ok", + wantAttr: attribute.Int("provider.instances", 0), + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + sr := tracetest.NewSpanRecorder() + tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr)) + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + + p := WithTracing("x", tc.inner, tracing.WithTracerProvider(tp)) + err := tc.call(p) + + wantErr := errors.Join(tc.inner.createErr, tc.inner.getErr, tc.inner.deleteErr, tc.inner.listErr) + if (wantErr == nil) != (err == nil) { + t.Fatalf("decorator changed the error: got %v", err) + } + + ended := sr.Ended() + if len(ended) != 1 { + t.Fatalf("got %d spans, want 1", len(ended)) + } + span := ended[0] + if span.Name() != tc.wantSpan { + t.Errorf("span name = %q, want %q", span.Name(), tc.wantSpan) + } + if span.SpanKind() != trace.SpanKindClient { + t.Errorf("span kind = %v, want client", span.SpanKind()) + } + if span.Status().Code != tc.wantStatus { + t.Errorf("status = %v, want %v", span.Status().Code, tc.wantStatus) + } + attrs := span.Attributes() + hasAttr := func(want attribute.KeyValue) bool { + return slices.Contains(attrs, want) + } + if !hasAttr(attribute.String("provider.result", tc.wantResult)) { + t.Errorf("provider.result %q missing in %v", tc.wantResult, attrs) + } + if !hasAttr(tc.wantAttr) { + t.Errorf("attribute %v missing in %v", tc.wantAttr, attrs) + } + }) + } +} -- 2.49.1 From 8e4f3b9b136d19b7402a4cdde30b58a96ba2afda Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 10:51:24 +0200 Subject: [PATCH 05/13] Wire tracing into the composition root Setup after SetLogger, wrapped rest configs (manager + kubernetes provider), tracing-outermost provider decorators, and an explicit trace flush after mgr.Start returns (os.Exit skips defers). Co-Authored-By: Claude --- cmd/main.go | 40 ++++++++++++++++--- .../2026-08-24-1025-otel-tracing.md | 21 +++++++++- internal/provider/kubernetes/kubernetes.go | 14 ++++++- 3 files changed, 68 insertions(+), 7 deletions(-) diff --git a/cmd/main.go b/cmd/main.go index 8598c90..e42cc72 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -58,6 +58,7 @@ import ( "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider/gcp" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider/kubernetes" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider/registry" + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/version" // +kubebuilder:scaffold:imports ) @@ -148,6 +149,17 @@ func main() { ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts))) setupLog.Info("Starting egress-proxies-operator", "commit", version.Resolve(), "goVersion", goruntime.Version()) + + // Off (no-op spans, unchanged logs) unless OTEL_* env opts in; see + // internal/tracing. Shutdown is called explicitly after mgr.Start + // returns — the os.Exit paths below skip defers. + tracingShutdown, err := tracing.Setup(context.Background(), setupLog, + "egress-proxies-operator", version.Resolve()) + if err != nil { + setupLog.Error(err, "Failed to set up tracing") + os.Exit(1) + } + ctx := ctrl.SetupSignalHandler() // Providers load first and fail fast: a manager that comes up without @@ -162,7 +174,11 @@ func main() { os.Exit(1) } providers, err := registry.Build(ctx, cfg, map[string]registry.Constructor{ - "kubernetes": kubernetes.New, + "kubernetes": func(ctx context.Context, pc provider.ProviderConfig) (provider.Provider, error) { + // The kubernetes provider builds its own uncached client; + // wrap its transport so its API calls join the caller's trace. + return kubernetes.NewWithTransportWrapper(ctx, pc, tracing.RestConfigWrapper()) + }, "gcp": func(ctx context.Context, pc provider.ProviderConfig) (provider.Provider, error) { return gcp.NewWithWireOptions(ctx, pc, gcp.WireLogOptions{FullPayloads: gcpWireFullPayloads}) }, @@ -173,7 +189,8 @@ func main() { } m := metrics.New() for name, p := range providers { - providers[name] = provider.WithMetrics(name, p, m) + // Tracing outermost: the span covers the metrics recording too. + providers[name] = provider.WithTracing(name, provider.WithMetrics(name, p, m)) } // if the enable-http2 flag is false (the default), http/2 should be disabled @@ -236,7 +253,9 @@ func main() { cacheOpts.DefaultNamespaces = map[string]cache.Config{proxyNamespace: {}} } - mgr, err := ctrl.NewManager(ctrl.GetConfigOrDie(), ctrl.Options{ + restCfg := ctrl.GetConfigOrDie() + restCfg.Wrap(tracing.RestConfigWrapper()) + mgr, err := ctrl.NewManager(restCfg, ctrl.Options{ Scheme: scheme, Metrics: metricsServerOptions, HealthProbeBindAddress: probeAddr, @@ -323,8 +342,19 @@ func main() { } setupLog.Info("Starting manager") - if err := mgr.Start(ctx); err != nil { - setupLog.Error(err, "Failed to run manager") + startErr := mgr.Start(ctx) + + // Flush pending spans on the way out, error path included. Fresh + // context: the signal ctx is already cancelled by the time Start + // returns. + shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + if err := tracingShutdown(shutdownCtx); err != nil { + setupLog.Error(err, "Failed to flush traces on shutdown") + } + cancel() + + if startErr != nil { + setupLog.Error(startErr, "Failed to run manager") os.Exit(1) } } diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index 3f28395..d6c1ed0 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -5,7 +5,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 1 — Dependencies - [x] Step 2 — New package `internal/tracing` - [x] Step 3 — `provider.WithTracing` decorator -- [ ] Step 4 — `cmd/main.go` wiring +- [x] Step 4 — `cmd/main.go` wiring - [ ] Step 5 — Reconciler spans - [ ] Step 6 — Discovery server - [ ] Step 7 — GC + health @@ -81,3 +81,22 @@ One small API addition to `internal/tracing` for this: exported and couldn't reach the unexported option resolver. The `cmd/main.go` wiring (`WithTracing` outermost around `WithMetrics`) lands with Step 4's commit — same file, one commit. + +## Step 4 — `cmd/main.go` wiring + +As planned: `tracing.Setup` right after `ctrl.SetLogger`; manager rest.Config +wrapped via `restCfg := ctrl.GetConfigOrDie(); restCfg.Wrap(...)` (the +previous inline call left nowhere to wrap); providers decorated tracing- +outermost; explicit trace flush after `mgr.Start` returns on both the error +and clean paths, with a fresh 10s context since the signal ctx is already +cancelled by then. + +The kubernetes provider grew `NewWithTransportWrapper(ctx, cfg, wrap)` (its +client is built from its own `ctrl.GetConfig()`, invisible to the manager's +wrapped config); `New` now delegates with a nil wrapper, so `newWithClient` +tests stayed untouched, and main registers a closure — the same pattern the +gcp constructor already used for wire-log options. + +Deviation: the plan put `--trace-health-probes` here, but the flag needs the +`health.Engine.TraceProbes` field that Step 7 introduces — moved there to +keep every commit compiling. diff --git a/internal/provider/kubernetes/kubernetes.go b/internal/provider/kubernetes/kubernetes.go index b3a03c3..a2688b0 100644 --- a/internal/provider/kubernetes/kubernetes.go +++ b/internal/provider/kubernetes/kubernetes.go @@ -14,6 +14,7 @@ import ( "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/types" "k8s.io/client-go/tools/cache" + "k8s.io/client-go/transport" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -39,11 +40,22 @@ type Provider struct { // New builds a kubernetes Provider from its config block. Satisfies // registry.Constructor. -func New(_ context.Context, cfg provider.ProviderConfig) (provider.Provider, error) { +func New(ctx context.Context, cfg provider.ProviderConfig) (provider.Provider, error) { + return NewWithTransportWrapper(ctx, cfg, nil) +} + +// NewWithTransportWrapper is New with an optional transport wrapper applied +// to the provider's own rest.Config (this client is built independently of +// the manager's, so the composition root must wrap it separately for +// tracing). A nil wrapper means a plain client. +func NewWithTransportWrapper(_ context.Context, cfg provider.ProviderConfig, wrap transport.WrapperFunc) (provider.Provider, error) { restCfg, err := ctrl.GetConfig() if err != nil { return nil, fmt.Errorf("kubernetes provider %q: loading kubeconfig: %w", cfg.Name, err) } + if wrap != nil { + restCfg.Wrap(wrap) + } scheme := runtime.NewScheme() if err := corev1.AddToScheme(scheme); err != nil { return nil, fmt.Errorf("kubernetes provider %q: %w", cfg.Name, err) -- 2.49.1 From 896bf89a19f18d7da5ac07b9e889cb5a2bc65d49 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 10:53:52 +0200 Subject: [PATCH 06/13] Trace reconciles: root span wrapper plus state-machine sub-spans Co-Authored-By: Claude --- .../2026-08-24-1025-otel-tracing.md | 20 ++++++++++++++++++- internal/controller/proxy_controller.go | 19 ++++++++++++++++-- 2 files changed, 36 insertions(+), 3 deletions(-) diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index d6c1ed0..d7f582c 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -6,7 +6,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 2 — New package `internal/tracing` - [x] Step 3 — `provider.WithTracing` decorator - [x] Step 4 — `cmd/main.go` wiring -- [ ] Step 5 — Reconciler spans +- [x] Step 5 — Reconciler spans - [ ] Step 6 — Discovery server - [ ] Step 7 — GC + health - [ ] Step 8 — GCP wire-log enrichment @@ -100,3 +100,21 @@ gcp constructor already used for wire-log options. Deviation: the plan put `--trace-health-probes` here, but the flag needs the `health.Engine.TraceProbes` field that Step 7 introduces — moved there to keep every commit compiling. + +## Step 5 — Reconciler spans + +`SetupWithManager` completes with `tracing.NewReconciler("Proxy", r)`; +sub-spans `reconcile.managed` / `reconcile.replaceInstance` / +`reconcile.delete` open at the top of each state machine, and `status.patch` +opens inside the deferred flush closure so it stays within the root span +while its error still folds into the recorded result. `reconcileExternal` +left unspanned as planned (no I/O). + +Two small judgment calls: the sub-spans carry no extra attributes — the +provider decorator already records `provider.id`, and the root span carries +the object identity, so duplicating them was noise; and `status.patch` is +emitted every reconcile even when nothing changed (the no-op compare is the +span's content — a real PATCH shows up as its k8s HTTP child). Tests that +call `r.Reconcile` directly bypass the wrapper; with no global tracer set +they see no-op spans, so the existing fake-client and envtest suites run +unchanged. diff --git a/internal/controller/proxy_controller.go b/internal/controller/proxy_controller.go index 3bf1d5f..e5fbb2f 100644 --- a/internal/controller/proxy_controller.go +++ b/internal/controller/proxy_controller.go @@ -41,6 +41,7 @@ import ( crawlv1alpha1 "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/api/v1alpha1" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/health" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider" + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" ) // HealthSnapshotter provides the current probe verdict for a proxy. The @@ -96,9 +97,14 @@ func (r *ProxyReconciler) Reconcile(ctx context.Context, req ctrl.Request) (res } base := p.DeepCopy() defer func() { + // Runs inside the root reconcile span (this defer fires before the + // tracing.NewReconciler wrapper sees the return), and its error is + // folded into err, which that wrapper records. + pctx, span := tracing.Start(ctx, "status.patch") + defer span.End() // NotFound is expected when this reconcile just removed the last // finalizer and the object is already gone. - if perr := r.patchStatusIfChanged(ctx, base, &p); perr != nil && !apierrors.IsNotFound(perr) { + if perr := r.patchStatusIfChanged(pctx, base, &p); perr != nil && !apierrors.IsNotFound(perr) { err = errors.Join(err, perr) } }() @@ -114,6 +120,8 @@ func (r *ProxyReconciler) Reconcile(ctx context.Context, req ctrl.Request) (res } func (r *ProxyReconciler) reconcileManaged(ctx context.Context, p *crawlv1alpha1.Proxy) (ctrl.Result, error) { + ctx, span := tracing.Start(ctx, "reconcile.managed") + defer span.End() log := logf.FromContext(ctx) if controllerutil.AddFinalizer(p, crawlv1alpha1.FinalizerName) { @@ -224,6 +232,8 @@ func (r *ProxyReconciler) reconcileManaged(ctx context.Context, p *crawlv1alpha1 // exists" — hence: delete, poll to NotFound, only then advance the hash and // let the create branch run. func (r *ProxyReconciler) replaceInstance(ctx context.Context, p *crawlv1alpha1.Proxy, prov provider.Provider, hash string) (ctrl.Result, error) { + ctx, span := tracing.Start(ctx, "reconcile.replaceInstance") + defer span.End() _, err := prov.Get(ctx, p.Status.ProviderID) if provider.Class(err) == provider.ErrNotFound { // Old instance is gone. The Update inside setSpecHash refreshes p @@ -252,6 +262,8 @@ func (r *ProxyReconciler) replaceInstance(ctx context.Context, p *crawlv1alpha1. } func (r *ProxyReconciler) reconcileDelete(ctx context.Context, p *crawlv1alpha1.Proxy) (ctrl.Result, error) { + ctx, span := tracing.Start(ctx, "reconcile.delete") + defer span.End() if !controllerutil.ContainsFinalizer(p, crawlv1alpha1.FinalizerName) { return ctrl.Result{}, nil } @@ -409,7 +421,10 @@ func (r *ProxyReconciler) SetupWithManager(mgr ctrl.Manager) error { if r.HealthEvents != nil { b = b.WatchesRawSource(source.Channel(r.HealthEvents, &handler.EnqueueRequestForObject{})) } - return b.Complete(r) + // Root span per reconcile; sub-reconcilers and the status flush hang + // their spans off it. Tests calling r.Reconcile directly bypass the + // wrapper and see no-op spans — the global tracer is never set there. + return b.Complete(tracing.NewReconciler("Proxy", r)) } func (r *ProxyReconciler) applyDefaults() { -- 2.49.1 From ec7267b8de8bbf7a379dec148c6487dc9413e379 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 10:59:48 +0200 Subject: [PATCH 07/13] Trace discovery API requests and enrich request logs Co-Authored-By: Claude --- .../2026-08-24-1025-otel-tracing.md | 17 ++++++++++++++++- internal/discovery/handlers.go | 10 +++++++--- internal/discovery/server.go | 8 ++++++-- 3 files changed, 29 insertions(+), 6 deletions(-) diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index d7f582c..ed83e2a 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -7,7 +7,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 3 — `provider.WithTracing` decorator - [x] Step 4 — `cmd/main.go` wiring - [x] Step 5 — Reconciler spans -- [ ] Step 6 — Discovery server +- [x] Step 6 — Discovery server - [ ] Step 7 — GC + health - [ ] Step 8 — GCP wire-log enrichment - [ ] Step 9 — Manifests + docs @@ -118,3 +118,18 @@ span's content — a real PATCH shows up as its k8s HTTP child). Tests that call `r.Reconcile` directly bypass the wrapper; with no global tracer set they see no-op spans, so the existing fake-client and envtest suites run unchanged. + +## Step 6 — Discovery server + +Middleware chain is now recover → tracing (server span + request logger) → +request-log → body cap → auth; the request-log middleware and the three +handler error sites log via `logf.FromContext(r.Context())` — which is +`s.log` enriched with the request's traceID/spanID by the tracing +middleware, not a different logger (logr sinks can't read ctx at log time, +so per-request values must ride on the logger instance in the ctx; user +asked, answered in-session). + +Deviation from the plan's letter: `recoverMiddleware` keeps `s.log`. It sits +*outside* the tracing layer, so its request ctx never has the enriched +logger — switching it to `FromContext` would silently drop the `"discovery"` +name and gain nothing. diff --git a/internal/discovery/handlers.go b/internal/discovery/handlers.go index 0df67e2..01da21a 100644 --- a/internal/discovery/handlers.go +++ b/internal/discovery/handlers.go @@ -11,6 +11,7 @@ import ( apimeta "k8s.io/apimachinery/pkg/api/meta" "sigs.k8s.io/controller-runtime/pkg/client" + logf "sigs.k8s.io/controller-runtime/pkg/log" crawlv1alpha1 "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/api/v1alpha1" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/lease" @@ -82,7 +83,10 @@ func (s *Server) handleListProxies(w http.ResponseWriter, r *http.Request) { var list crawlv1alpha1.ProxyList if err := s.Reader.List(r.Context(), &list); err != nil { - s.log.Error(err, "listing proxies") + // The ctx logger is s.log enriched with this request's + // traceID/spanID by the tracing middleware (logr sinks can't read + // ctx at log time, so per-request values ride on the logger). + logf.FromContext(r.Context()).Error(err, "listing proxies") writeError(w, http.StatusInternalServerError, "internal", "listing proxies failed") return } @@ -138,7 +142,7 @@ func (s *Server) handleAcquireLease(w http.ResponseWriter, r *http.Request) { var list crawlv1alpha1.ProxyList if err := s.Reader.List(r.Context(), &list); err != nil { - s.log.Error(err, "listing proxies for lease") + logf.FromContext(r.Context()).Error(err, "listing proxies for lease") writeError(w, http.StatusInternalServerError, "internal", "listing proxies failed") return } @@ -231,7 +235,7 @@ func (s *Server) handleReportLease(w http.ResponseWriter, r *http.Request) { writeError(w, http.StatusNotFound, "unknown_lease", "no such lease") return } - s.log.Error(err, "reporting lease", "leaseID", r.PathValue("id")) + logf.FromContext(r.Context()).Error(err, "reporting lease", "leaseID", r.PathValue("id")) writeError(w, http.StatusInternalServerError, "internal", "report failed") return } diff --git a/internal/discovery/server.go b/internal/discovery/server.go index 5c95fa5..c8546bb 100644 --- a/internal/discovery/server.go +++ b/internal/discovery/server.go @@ -20,6 +20,7 @@ import ( logf "sigs.k8s.io/controller-runtime/pkg/log" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/lease" + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" ) // LeaseStore is what the handlers need from a lease backend. Defined here, @@ -136,7 +137,9 @@ func (s *Server) Start(ctx context.Context) error { } // handler assembles the mux and the middleware chain, outermost first: -// recover → request-log → body-size cap → bearer auth. +// recover → tracing (server span + request logger) → request-log → +// body-size cap → bearer auth. Everything inside the tracing layer logs via +// logf.FromContext(r.Context()) and so carries traceID/spanID. func (s *Server) handler() http.Handler { mux := http.NewServeMux() mux.HandleFunc("GET /healthz", func(w http.ResponseWriter, _ *http.Request) { @@ -152,6 +155,7 @@ func (s *Server) handler() http.Handler { h = s.authMiddleware(h) h = maxBytesMiddleware(h) h = s.logMiddleware(h) + h = tracing.HTTPMiddleware("discovery", s.log)(h) h = s.recoverMiddleware(h) return h } @@ -188,7 +192,7 @@ func (s *Server) logMiddleware(next http.Handler) http.Handler { rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} start := time.Now() next.ServeHTTP(rec, r) - s.log.Info("request", + logf.FromContext(r.Context()).Info("request", "method", r.Method, "path", r.URL.Path, "status", rec.status, "duration", time.Since(start).String()) }) -- 2.49.1 From bca32f10d356a3e717a1eb474c4b993cf075793f Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 11:07:13 +0200 Subject: [PATCH 08/13] Trace GC sweeps and (opt-in) health probes Co-Authored-By: Claude --- cmd/main.go | 5 +++ .../2026-08-24-1025-otel-tracing.md | 15 +++++++- internal/gc/gc.go | 12 +++++++ internal/health/engine.go | 34 +++++++++++++++++-- 4 files changed, 63 insertions(+), 3 deletions(-) diff --git a/cmd/main.go b/cmd/main.go index e42cc72..a195907 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -94,6 +94,7 @@ func main() { var leaseCooldown, maxLeaseTTL time.Duration var showVersion bool var gcpWireFullPayloads bool + var traceHealthProbes bool flag.StringVar(&metricsAddr, "metrics-bind-address", "0", "The address the metrics endpoint binds to. "+ "Use :8443 for HTTPS or :8080 for HTTP, or leave as 0 to disable the metrics service.") @@ -134,6 +135,9 @@ func main() { "Print the commit the binary was built from and exit.") flag.BoolVar(&gcpWireFullPayloads, "gcp-wire-log-full-payloads", false, "Log GCP V(5) wire payloads verbatim instead of eliding fields larger than 1KiB.") + flag.BoolVar(&traceHealthProbes, "trace-health-probes", false, + "Emit one trace span per health probe. Off by default: probes run about "+ + "once per second per proxy and would dominate trace volume.") opts := zap.Options{ Development: true, @@ -277,6 +281,7 @@ func main() { engine := health.NewEngine(mgr.GetClient()) engine.Workers = healthWorkers engine.Metrics = m + engine.TraceProbes = traceHealthProbes if err := mgr.Add(engine); err != nil { setupLog.Error(err, "Failed to add health engine") os.Exit(1) diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index ed83e2a..b1f7579 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -8,7 +8,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 4 — `cmd/main.go` wiring - [x] Step 5 — Reconciler spans - [x] Step 6 — Discovery server -- [ ] Step 7 — GC + health +- [x] Step 7 — GC + health - [ ] Step 8 — GCP wire-log enrichment - [ ] Step 9 — Manifests + docs @@ -133,3 +133,16 @@ Deviation from the plan's letter: `recoverMiddleware` keeps `s.log`. It sits *outside* the tracing layer, so its request ctx never has the enriched logger — switching it to `FromContext` would silently drop the `"discovery"` name and gain nothing. + +## Step 7 — GC + health + +`gc.sweep` runs in a root span with `gc.providers` / `gc.deleted` counters +(a failed orphan delete no longer counts as deleted — the loop grew an +explicit `continue`). The health engine got the deferred `--trace-health-probes` +flag and `TraceProbes` field; the probe call moved into `runProbe`, which +wraps it in a `health.probe` client span only when enabled, ending before +`record` (which stays ctx-free by design). Probe transports remain +uninstrumented so no traceparent can leak through a proxy to external +targets. Probe→reconcile span links stay out of scope (GenericEvent carries +no ctx; the workqueue coalesces events) — recorded in the architecture +Decisions in Step 9. diff --git a/internal/gc/gc.go b/internal/gc/gc.go index 269f1dd..bafabd9 100644 --- a/internal/gc/gc.go +++ b/internal/gc/gc.go @@ -12,8 +12,11 @@ import ( "sigs.k8s.io/controller-runtime/pkg/client" logf "sigs.k8s.io/controller-runtime/pkg/log" + "go.opentelemetry.io/otel/attribute" + crawlv1alpha1 "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/api/v1alpha1" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider" + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" ) // Sweeper is the manager Runnable running the sweep loop. @@ -81,6 +84,8 @@ func (s *Sweeper) Start(ctx context.Context) error { // that deletion, and GC racing it would double-delete. A UID becomes // orphan-eligible only once the object is fully gone. func (s *Sweeper) sweep(ctx context.Context) { + ctx, span := tracing.Start(ctx, "gc.sweep") + defer span.End() log := logf.FromContext(ctx).WithName("orphan-gc") var list crawlv1alpha1.ProxyList @@ -95,6 +100,7 @@ func (s *Sweeper) sweep(ctx context.Context) { live[string(list.Items[i].UID)] = true } + deleted := 0 for name, prov := range s.Providers { instances, err := prov.ListByTag(ctx) if err != nil { @@ -119,7 +125,13 @@ func (s *Sweeper) sweep(ctx context.Context) { if err := prov.Delete(ctx, inst.ID); err != nil { log.Error(err, "deleting orphaned instance", "provider", name, "providerID", inst.ID, "uid", inst.UID) + continue } + deleted++ } } + span.SetAttributes( + attribute.Int("gc.providers", len(s.Providers)), + attribute.Int("gc.deleted", deleted), + ) } diff --git a/internal/health/engine.go b/internal/health/engine.go index e35257a..e779939 100644 --- a/internal/health/engine.go +++ b/internal/health/engine.go @@ -10,6 +10,9 @@ import ( "sync" "time" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" apimeta "k8s.io/apimachinery/pkg/api/meta" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/types" @@ -18,6 +21,7 @@ import ( logf "sigs.k8s.io/controller-runtime/pkg/log" crawlv1alpha1 "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/api/v1alpha1" + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/tracing" ) // Snapshot is the engine's current verdict for one proxy, read by the @@ -99,6 +103,10 @@ type Engine struct { // transition-only by design, so metrics are where high-frequency // signal (true probe recency, every latency sample) lives. Metrics ProbeMetrics + // TraceProbes emits one root span per probe (--trace-health-probes). + // Off by default: probes run about once per second per proxy and would + // dominate trace volume. + TraceProbes bool probeFn func(context.Context, *url.URL, crawlv1alpha1.HealthCheckSpec, *tls.Config) probeResult @@ -155,8 +163,7 @@ func (e *Engine) Start(ctx context.Context) error { case <-ctx.Done(): return case job := <-jobs: - res := e.probeFn(ctx, job.proxyURL, job.hc, e.ProbeTLSConfig) - e.record(job, res, time.Now()) + e.record(job, e.runProbe(ctx, job), time.Now()) } } }) @@ -264,6 +271,29 @@ func newState(p *crawlv1alpha1.Proxy, now time.Time, interval time.Duration) *st return st } +// runProbe executes one probe, inside its own root span when TraceProbes is +// on. The span ends before record folds the result (record stays ctx-free), +// and the probe transport is deliberately uninstrumented — no traceparent +// must ever leak through a proxy toward external targets. +func (e *Engine) runProbe(ctx context.Context, job probeJob) probeResult { + if !e.TraceProbes { + return e.probeFn(ctx, job.proxyURL, job.hc, e.ProbeTLSConfig) + } + ctx, span := tracing.Start(ctx, "health.probe", + trace.WithSpanKind(trace.SpanKindClient), + trace.WithAttributes(attribute.String("proxy", job.key.String()))) + defer span.End() + res := e.probeFn(ctx, job.proxyURL, job.hc, e.ProbeTLSConfig) + span.SetAttributes( + attribute.Bool("probe.ok", res.ok), + attribute.Int64("probe.latency_ms", res.latency.Milliseconds()), + ) + if !res.ok { + span.SetStatus(codes.Error, res.err.Error()) + } + return res +} + // record folds one probe result into the proxy's threshold state and emits // an event when the result is status-affecting: a first-ever verdict, a // threshold-crossing flip, or a material latency change (beyond -- 2.49.1 From 53c0d77ef53acc4bf1bf1d9bcdcefa90d426e1ee Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 11:09:48 +0200 Subject: [PATCH 09/13] Enrich GCP wire logs with trace context from the request ctx Co-Authored-By: Claude --- .../2026-08-24-1025-otel-tracing.md | 11 +++- internal/provider/gcp/wirelog.go | 10 ++++ internal/provider/gcp/wirelog_test.go | 50 +++++++++++++++++++ 3 files changed, 70 insertions(+), 1 deletion(-) create mode 100644 internal/provider/gcp/wirelog_test.go diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index b1f7579..9de685a 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -9,7 +9,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 5 — Reconciler spans - [x] Step 6 — Discovery server - [x] Step 7 — GC + health -- [ ] Step 8 — GCP wire-log enrichment +- [x] Step 8 — GCP wire-log enrichment - [ ] Step 9 — Manifests + docs ## Step 1 — Dependencies @@ -146,3 +146,12 @@ uninstrumented so no traceparent can leak through a proxy to external targets. Probe→reconcile span links stay out of scope (GenericEvent carries no ctx; the workqueue coalesces events) — recorded in the architecture Decisions in Step 9. + +## Step 8 — GCP wire-log enrichment + +`wireFilterHandler.Handle` clones the record and appends `traceID`/`spanID` +when the ctx carries a valid span — same keys as the logr enrichment, added +before the elision pass (both values are well under the 1KiB threshold). +The new `wirelog_test.go` covers the enrichment, that the JWT/token security +filter still drops non-wire Debug records even with a span present, and that +spanless records stay unchanged. diff --git a/internal/provider/gcp/wirelog.go b/internal/provider/gcp/wirelog.go index d93423b..91f90b4 100644 --- a/internal/provider/gcp/wirelog.go +++ b/internal/provider/gcp/wirelog.go @@ -6,6 +6,7 @@ import ( "log/slog" "github.com/go-logr/logr" + "go.opentelemetry.io/otel/trace" ) // wireLogMaxFieldBytes is the elision threshold for string fields in wire @@ -47,6 +48,15 @@ func (h *wireFilterHandler) Handle(ctx context.Context, rec slog.Record) error { if rec.Level <= slog.LevelDebug && rec.Message != "api request" && rec.Message != "api response" { return nil } + // The SDK logs with the request ctx, so wire records can carry the + // surrounding provider span — the one place slog's ctx-aware handlers + // beat logr, and the same keys the logr enrichment uses. + if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { + rec = rec.Clone() + rec.AddAttrs( + slog.String("traceID", sc.TraceID().String()), + slog.String("spanID", sc.SpanID().String())) + } if h.fullPayloads { return h.inner.Handle(ctx, rec) } diff --git a/internal/provider/gcp/wirelog_test.go b/internal/provider/gcp/wirelog_test.go new file mode 100644 index 0000000..3e597aa --- /dev/null +++ b/internal/provider/gcp/wirelog_test.go @@ -0,0 +1,50 @@ +package gcp + +import ( + "context" + "strings" + "testing" + + "github.com/go-logr/logr/funcr" + sdktrace "go.opentelemetry.io/otel/sdk/trace" +) + +func TestWireFilterHandler_addsTraceContext(t *testing.T) { + t.Parallel() + + var lines []string + base := funcr.New(func(prefix, args string) { + lines = append(lines, prefix+" "+args) + }, funcr.Options{Verbosity: 5}) + log := wireLogger(base, WireLogOptions{}) + + tp := sdktrace.NewTracerProvider() + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + ctx, span := tp.Tracer("test").Start(context.Background(), "provider.create") + defer span.End() + + log.DebugContext(ctx, "api request", "url", "https://compute.googleapis.com/x") + if len(lines) != 1 { + t.Fatalf("got %d lines, want 1: %v", len(lines), lines) + } + traceID := span.SpanContext().TraceID().String() + if !strings.Contains(lines[0], "traceID") || !strings.Contains(lines[0], traceID) { + t.Errorf("wire record missing trace context %s: %s", traceID, lines[0]) + } + + // The security filter must still win: non-wire Debug records are + // dropped even when a span is present. + log.DebugContext(ctx, "token exchange", "assertion", "secret-jwt") + if len(lines) != 1 { + t.Fatalf("filtered record leaked: %v", lines[1:]) + } + + // No span in ctx: record passes through without trace keys. + log.DebugContext(context.Background(), "api response", "status", 200) + if len(lines) != 2 { + t.Fatalf("got %d lines, want 2", len(lines)) + } + if strings.Contains(lines[1], "traceID") { + t.Errorf("spanless record must not carry traceID: %s", lines[1]) + } +} -- 2.49.1 From aeb4115c723e394490e99217a3ffbb419f4aed19 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 11:30:27 +0200 Subject: [PATCH 10/13] Add tracing manifests and docs; clean up branch lint findings MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Manager env block (downward-API resource attrs, commented OTLP examples), architecture §10 + Decisions entries, README section. Lint: goconst constants, gofmt, logcheck (Setup now takes its logger from ctx via logf.FromContext). Co-Authored-By: Claude --- README.md | 19 ++++++ cmd/main.go | 3 +- config/manager/manager.yaml | 29 +++++++++ docs/architecture.md | 60 +++++++++++++++++++ .../2026-08-24-1025-otel-tracing.md | 28 ++++++++- internal/provider/metrics.go | 18 ++++-- internal/provider/tracing_test.go | 10 ++-- internal/tracing/logger.go | 2 + internal/tracing/tracing.go | 43 +++++++++---- internal/tracing/tracing_test.go | 39 ++++++------ 10 files changed, 207 insertions(+), 44 deletions(-) diff --git a/README.md b/README.md index a7783c9..a3a80dd 100644 --- a/README.md +++ b/README.md @@ -192,6 +192,25 @@ Test against a fake API seam rather than the real cloud — see the [internal/provider/gcp/gcp.go](internal/provider/gcp/gcp.go) for the pattern. +## Tracing + +OpenTelemetry tracing is built in but **off by default** — the operator +only exports spans when pointed at an OTLP receiver: + +```bash +# In config/manager/manager.yaml (commented-out block is already there): +# OTEL_EXPORTER_OTLP_ENDPOINT=http://jaeger-collector.observability:4318 +# Local dev: print spans to stdout instead +OTEL_TRACES_EXPORTER=console go run ./cmd --providers-config hack/providers-dev.yaml +``` + +Every reconcile, discovery API request, and GC sweep becomes a trace, with +child spans for provider and Kubernetes API calls; log lines inside a traced +operation carry matching `traceID`/`spanID` fields (point Grafana/Loki +derived fields at `traceID`). Sampling and endpoints follow the standard +`OTEL_*` env vars; `--trace-health-probes` additionally traces each health +probe (high volume). Details in `docs/architecture.md` §10. + ## Caveats — read these two **Changing a proxy changes its IP.** Proxies are immutable cattle: editing diff --git a/cmd/main.go b/cmd/main.go index a195907..2b85b59 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -42,6 +42,7 @@ import ( "sigs.k8s.io/controller-runtime/pkg/cache" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/healthz" + logf "sigs.k8s.io/controller-runtime/pkg/log" "sigs.k8s.io/controller-runtime/pkg/log/zap" ctrlmetrics "sigs.k8s.io/controller-runtime/pkg/metrics" "sigs.k8s.io/controller-runtime/pkg/metrics/filters" @@ -157,7 +158,7 @@ func main() { // Off (no-op spans, unchanged logs) unless OTEL_* env opts in; see // internal/tracing. Shutdown is called explicitly after mgr.Start // returns — the os.Exit paths below skip defers. - tracingShutdown, err := tracing.Setup(context.Background(), setupLog, + tracingShutdown, err := tracing.Setup(logf.IntoContext(context.Background(), setupLog), "egress-proxies-operator", version.Resolve()) if err != nil { setupLog.Error(err, "Failed to set up tracing") diff --git a/config/manager/manager.yaml b/config/manager/manager.yaml index 7d832f5..5676abb 100644 --- a/config/manager/manager.yaml +++ b/config/manager/manager.yaml @@ -64,6 +64,8 @@ spec: - --leader-elect - --health-probe-bind-address=:8081 - --providers-config=/etc/proxy-operator/providers.yaml + # Add --trace-health-probes to emit one span per health probe + # (high volume: ~1/s per proxy). env: # Bearer token for the discovery API. Optional: without the # Secret the API serves unauthenticated (with a loud warning). @@ -76,6 +78,33 @@ spec: name: discovery-token key: token optional: true + # --- OpenTelemetry tracing --- + # Tracing is OFF until OTEL_EXPORTER_OTLP_ENDPOINT (or + # OTEL_TRACES_EXPORTER) is set; without it the operator runs + # exactly as before. The downward-API vars must stay listed + # before OTEL_RESOURCE_ATTRIBUTES: $(VAR) expansion only sees + # earlier-listed vars. + - name: POD_NAME + valueFrom: + fieldRef: + fieldPath: metadata.name + - name: POD_NAMESPACE + valueFrom: + fieldRef: + fieldPath: metadata.namespace + - name: OTEL_SERVICE_NAME + value: egress-proxies-operator + - name: OTEL_RESOURCE_ATTRIBUTES + value: k8s.pod.name=$(POD_NAME),k8s.namespace.name=$(POD_NAMESPACE) + # Point at an OTLP receiver (Tempo, Jaeger, otel-collector) to + # enable tracing; http/protobuf (4318) is the default protocol, + # set OTEL_EXPORTER_OTLP_PROTOCOL=grpc for 4317. + # - name: OTEL_EXPORTER_OTLP_ENDPOINT + # value: http://jaeger-collector.observability:4318 + # - name: OTEL_TRACES_SAMPLER + # value: parentbased_traceidratio + # - name: OTEL_TRACES_SAMPLER_ARG + # value: "0.1" image: controller:latest name: manager ports: diff --git a/docs/architecture.md b/docs/architecture.md index 7946caf..5c1053b 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -300,6 +300,45 @@ Each consuming package defines its own small recorder interface `metrics.Metrics` satisfies all of them structurally, so no package other than `cmd/main.go` imports the metrics package. +### 10. Tracing (`internal/tracing/`) + +OpenTelemetry tracing, integrated with — not replacing — the logr/zap +logging. Everything hangs off standard `OTEL_*` env vars: with no +`OTEL_EXPORTER_OTLP_ENDPOINT` / `OTEL_TRACES_EXPORTER` set, no SDK is +installed, spans are no-ops, and logs are byte-for-byte what they were. +`OTEL_SDK_DISABLED=true` and `OTEL_TRACES_EXPORTER=none` force it off; +`console` prints spans to stdout for local dev; sampling follows +`OTEL_TRACES_SAMPLER(_ARG)`. + +Span topology — each unit of work is a new trace (watch events carry no +incoming trace context): + +- `Reconcile Proxy` (root, via a `reconcile.Reconciler` decorator) → + `reconcile.managed` / `reconcile.replaceInstance` / `reconcile.delete`, + plus `status.patch` from the deferred flush. `reconcileExternal` does no + I/O and is unspanned. +- `provider.create|get|delete|list` (client spans, `provider.WithTracing` + decorator wired outermost around `WithMetrics`); the GCP SDK's own + otelhttp transport contributes HTTP child spans automatically. +- Kubernetes API calls become client child spans via a wrapped + `rest.Config` transport — gated on an existing parent span, so informer + list/watch long-polls and leader-election renewals never create root + spans. The kube-apiserver ignores incoming `traceparent` by design; + these spans are leaves. +- Discovery API: one server span per request (named from the route + pattern), incoming W3C `traceparent` honored so clients' traces continue + into the operator; `/healthz` excluded. +- `gc.sweep` per GC pass; `health.probe` per probe **only** with + `--trace-health-probes` (default off — probes run ~1/s per proxy). + +Log correlation: logr sinks never see a context, so trace IDs ride on the +logger — `tracing.Start` re-derives the ctx logger from a captured base +with `traceID`/`spanID` values (lowerCamel, matching `reconcileID`; +Grafana/Loki derived-field regexes must match `traceID`, not `trace_id`). +Re-deriving from the base rather than layering keeps zap from emitting +duplicate keys on nested spans. GCP V(5) wire logs get the same keys from +the slog handler's ctx. + ## Decisions Judgment calls the spec left open, and deliberate deviations — recorded so @@ -404,3 +443,24 @@ they read as choices, not accidents. Chronological by build step. logger to everything running under the manager — fighting that would mean two logging systems in one process. Noted as a deviation rather than silently ignored. +- **Tracing is env-gated, not flag-gated:** it activates only when + `OTEL_EXPORTER_OTLP_ENDPOINT` / `OTEL_TRACES_EXPORTER` is set (user + decision). No collector configured means no SDK installed, no-op spans, + unchanged logs — the safe default for every existing deployment. The + one flag is `--trace-health-probes`, off by default, because probes at + ~1/s per proxy would dominate trace volume. +- **Trace keys are `traceID`/`spanID`**, lowerCamel like `reconcileID` and + `providerID`, deliberately not the `trace_id` many Grafana derived-field + examples assume — configure the derived-field regex accordingly. logr + sinks can't read ctx, so the IDs ride on the ctx logger, re-derived from + a captured base per span so zap never emits duplicate keys. +- **Probe→reconcile trace links are not attempted:** the health engine's + `GenericEvent` carries only namespace/name (no ctx), and the workqueue + coalesces events, so any link would be a guess. A health-triggered + reconcile starts a fresh trace; the probe that caused it is findable via + its own (opt-in) span and shared proxy attributes. +- **No `traceparent` toward probe targets:** probe transports stay + uninstrumented so trace headers can never leak through a proxy to + external sites. The kube-apiserver ignores incoming `traceparent` by + design (public endpoint), so k8s client spans are leaves — in-process + traces, not cross-process ones. diff --git a/docs/plans-executions/2026-08-24-1025-otel-tracing.md b/docs/plans-executions/2026-08-24-1025-otel-tracing.md index 9de685a..c4f89ab 100644 --- a/docs/plans-executions/2026-08-24-1025-otel-tracing.md +++ b/docs/plans-executions/2026-08-24-1025-otel-tracing.md @@ -10,7 +10,7 @@ Plan: `docs/plans/2026-08-24-1025-otel-tracing.md` - [x] Step 6 — Discovery server - [x] Step 7 — GC + health - [x] Step 8 — GCP wire-log enrichment -- [ ] Step 9 — Manifests + docs +- [x] Step 9 — Manifests + docs ## Step 1 — Dependencies @@ -155,3 +155,29 @@ before the elision pass (both values are well under the 1KiB threshold). The new `wirelog_test.go` covers the enrichment, that the JWT/token security filter still drops non-wire Debug records even with a span present, and that spanless records stay unchanged. + +## Step 9 — Manifests, docs, lint + +`config/manager/manager.yaml` gained the OTel env block (downward-API +`POD_NAME`/`POD_NAMESPACE` deliberately listed *before* +`OTEL_RESOURCE_ATTRIBUTES` — `$(VAR)` expansion only sees earlier vars), +with the OTLP endpoint and sampler left as commented examples so deployments +stay tracing-off by default. `docs/architecture.md` got "### 10. Tracing" +plus five Decisions entries; README got a Tracing section. + +`make lint` surfaced 16 new-on-branch issues (checked with +`golangci-lint run --new-from-rev main`; the other ~43 pre-date this work): + +- one gofmt slip, 13 goconst repeats — fixed with `env*`/`exporter*` + constants in `internal/tracing/tracing.go` shared by the tests; +- two logcheck hits ("function takes both a context and a logger"): + `Setup` now reads its logger from ctx (`logf.FromContext`, caller seeds + via `logf.IntoContext` — the linter's sanctioned pattern), and + `ContextWithLogger` carries a justified `//nolint:logcheck`, since being + the IntoContext-analogue is its purpose. + +Worth noting: pre-existing lint debt (50 goconst etc. on `main`) was left +untouched — `make lint` still fails overall; only branch-introduced issues +were cleaned. The lint fixes changed `Setup`'s signature after Step 2/4 had +landed, so those commits show the two-arg version; this commit is where it +settles. diff --git a/internal/provider/metrics.go b/internal/provider/metrics.go index 96b24fa..6c9dd08 100644 --- a/internal/provider/metrics.go +++ b/internal/provider/metrics.go @@ -50,17 +50,25 @@ func (i *instrumented) record(op string, err error) { i.rec.ProviderRequest(i.name, op, resultLabel(err)) } +const ( + resultOK = "ok" + resultNotFound = "not_found" + resultQuotaExceeded = "quota_exceeded" + resultPermanent = "permanent" + resultTransient = "transient" +) + func resultLabel(err error) string { switch Class(err) { case nil: - return "ok" + return resultOK case ErrNotFound: - return "not_found" + return resultNotFound case ErrQuotaExceeded: - return "quota_exceeded" + return resultQuotaExceeded case ErrPermanent: - return "permanent" + return resultPermanent default: - return "transient" + return resultTransient } } diff --git a/internal/provider/tracing_test.go b/internal/provider/tracing_test.go index cdb14c6..ca8c62c 100644 --- a/internal/provider/tracing_test.go +++ b/internal/provider/tracing_test.go @@ -33,7 +33,7 @@ func TestWithTracing_spanPerCall(t *testing.T) { call: func(p Provider) error { _, err := p.Create(context.Background(), CreateRequest{}); return err }, wantSpan: "provider.create", wantStatus: codes.Ok, - wantResult: "ok", + wantResult: resultOK, wantAttr: attribute.String("provider.id", "id-1"), }, { @@ -42,7 +42,7 @@ func TestWithTracing_spanPerCall(t *testing.T) { call: func(p Provider) error { _, err := p.Get(context.Background(), "id-1"); return err }, wantSpan: "provider.get", wantStatus: codes.Ok, - wantResult: "not_found", + wantResult: resultNotFound, wantAttr: attribute.String("provider.id", "id-1"), }, { @@ -51,7 +51,7 @@ func TestWithTracing_spanPerCall(t *testing.T) { call: func(p Provider) error { return p.Delete(context.Background(), "id-1") }, wantSpan: "provider.delete", wantStatus: codes.Error, - wantResult: "transient", + wantResult: resultTransient, wantAttr: attribute.String("provider.id", "id-1"), }, { @@ -60,7 +60,7 @@ func TestWithTracing_spanPerCall(t *testing.T) { call: func(p Provider) error { _, err := p.Create(context.Background(), CreateRequest{}); return err }, wantSpan: "provider.create", wantStatus: codes.Error, - wantResult: "quota_exceeded", + wantResult: resultQuotaExceeded, wantAttr: attribute.String("provider.name", "x"), }, { @@ -69,7 +69,7 @@ func TestWithTracing_spanPerCall(t *testing.T) { call: func(p Provider) error { _, err := p.ListByTag(context.Background()); return err }, wantSpan: "provider.list", wantStatus: codes.Ok, - wantResult: "ok", + wantResult: resultOK, wantAttr: attribute.Int("provider.instances", 0), }, } diff --git a/internal/tracing/logger.go b/internal/tracing/logger.go index 042bd1d..5d4a614 100644 --- a/internal/tracing/logger.go +++ b/internal/tracing/logger.go @@ -47,6 +47,8 @@ func StartSpan(ctx context.Context, tracer trace.Tracer, name string, opts ...tr // base for span enrichment. If ctx already carries a valid span (the HTTP // middleware calls this inside the otelhttp handler), the logger is // enriched immediately. +// +//nolint:logcheck // IntoContext-analogue: taking ctx and the logger to seed it with is the point. func ContextWithLogger(ctx context.Context, base logr.Logger) context.Context { ctx = context.WithValue(ctx, baseLoggerKey{}, base) if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { diff --git a/internal/tracing/tracing.go b/internal/tracing/tracing.go index 4801d28..6a31b0b 100644 --- a/internal/tracing/tracing.go +++ b/internal/tracing/tracing.go @@ -10,7 +10,6 @@ import ( "os" "strings" - "github.com/go-logr/logr" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" @@ -19,6 +18,20 @@ import ( "go.opentelemetry.io/otel/sdk/resource" sdktrace "go.opentelemetry.io/otel/sdk/trace" semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + logf "sigs.k8s.io/controller-runtime/pkg/log" +) + +const ( + envSDKDisabled = "OTEL_SDK_DISABLED" + envTracesExporter = "OTEL_TRACES_EXPORTER" + envOTLPEndpoint = "OTEL_EXPORTER_OTLP_ENDPOINT" + envOTLPTracesEndpoint = "OTEL_EXPORTER_OTLP_TRACES_ENDPOINT" + envOTLPProtocol = "OTEL_EXPORTER_OTLP_PROTOCOL" + envOTLPTracesProtocol = "OTEL_EXPORTER_OTLP_TRACES_PROTOCOL" + + exporterOTLP = "otlp" + exporterConsole = "console" + exporterNone = "none" ) // maxQueueSize bounds the batch processor's span buffer; the default 2048 @@ -35,15 +48,19 @@ const maxQueueSize = 512 // OTEL_TRACES_EXPORTER=none force it off (the Go SDK does not implement // OTEL_SDK_DISABLED itself). Sampling, endpoints, TLS, and headers follow // the standard SDK/exporter env vars (OTEL_TRACES_SAMPLER, OTEL_EXPORTER_OTLP_*). -func Setup(ctx context.Context, log logr.Logger, service, version string) (func(context.Context) error, error) { +// +// Setup logs via the logger in ctx (logf.FromContext) rather than a +// parameter — the caller seeds it with logf.IntoContext. +func Setup(ctx context.Context, service, version string) (func(context.Context) error, error) { + log := logf.FromContext(ctx) noop := func(context.Context) error { return nil } - exporterEnv := strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_TRACES_EXPORTER"))) - endpointSet := os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT") != "" || - os.Getenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT") != "" - sdkDisabled := strings.EqualFold(strings.TrimSpace(os.Getenv("OTEL_SDK_DISABLED")), "true") + exporterEnv := strings.ToLower(strings.TrimSpace(os.Getenv(envTracesExporter))) + endpointSet := os.Getenv(envOTLPEndpoint) != "" || + os.Getenv(envOTLPTracesEndpoint) != "" + sdkDisabled := strings.EqualFold(strings.TrimSpace(os.Getenv(envSDKDisabled)), "true") - if sdkDisabled || exporterEnv == "none" || (exporterEnv == "" && !endpointSet) { + if sdkDisabled || exporterEnv == exporterNone || (exporterEnv == "" && !endpointSet) { log.Info("tracing disabled", "reason", disabledReason(sdkDisabled, exporterEnv)) return noop, nil @@ -87,7 +104,7 @@ func disabledReason(sdkDisabled bool, exporterEnv string) string { switch { case sdkDisabled: return "OTEL_SDK_DISABLED=true" - case exporterEnv == "none": + case exporterEnv == exporterNone: return "OTEL_TRACES_EXPORTER=none" default: return "no OTEL_TRACES_EXPORTER or OTLP endpoint configured" @@ -99,10 +116,10 @@ func disabledReason(sdkDisabled bool, exporterEnv string) string { // metric/log/prometheus exporters into a trace-only binary. func newExporter(ctx context.Context, kind string) (sdktrace.SpanExporter, string, error) { switch kind { - case "", "otlp": - proto := strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_TRACES_PROTOCOL"))) + case "", exporterOTLP: + proto := strings.ToLower(strings.TrimSpace(os.Getenv(envOTLPTracesProtocol))) if proto == "" { - proto = strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_PROTOCOL"))) + proto = strings.ToLower(strings.TrimSpace(os.Getenv(envOTLPProtocol))) } switch proto { case "", "http/protobuf": @@ -114,9 +131,9 @@ func newExporter(ctx context.Context, kind string) (sdktrace.SpanExporter, strin default: return nil, "", fmt.Errorf("unsupported OTLP protocol %q (supported: http/protobuf, grpc)", proto) } - case "console": + case exporterConsole: exp, err := stdouttrace.New() - return exp, "console", err + return exp, exporterConsole, err default: return nil, "", fmt.Errorf("unsupported OTEL_TRACES_EXPORTER %q (supported: otlp, console, none)", kind) } diff --git a/internal/tracing/tracing_test.go b/internal/tracing/tracing_test.go index b90310b..ed6b013 100644 --- a/internal/tracing/tracing_test.go +++ b/internal/tracing/tracing_test.go @@ -5,24 +5,25 @@ import ( "testing" "time" - "github.com/go-logr/logr" "go.opentelemetry.io/otel" sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/trace/noop" ) +const testOTLPEndpoint = "http://localhost:4318" + // clearOTelEnv pins every env var Setup reads, so developer shells with // OTEL_* set can't change test outcomes. Not parallel-safe by design // (t.Setenv forbids t.Parallel). func clearOTelEnv(t *testing.T) { t.Helper() for _, k := range []string{ - "OTEL_SDK_DISABLED", - "OTEL_TRACES_EXPORTER", - "OTEL_EXPORTER_OTLP_ENDPOINT", - "OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", - "OTEL_EXPORTER_OTLP_PROTOCOL", - "OTEL_EXPORTER_OTLP_TRACES_PROTOCOL", + envSDKDisabled, + envTracesExporter, + envOTLPEndpoint, + envOTLPTracesEndpoint, + envOTLPProtocol, + envOTLPTracesProtocol, } { t.Setenv(k, "") } @@ -38,50 +39,50 @@ func TestSetup_envGating(t *testing.T) { {name: "no env means disabled", env: nil, wantEnabled: false}, { name: "endpoint enables otlp", - env: map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": "http://localhost:4318"}, + env: map[string]string{envOTLPEndpoint: testOTLPEndpoint}, wantEnabled: true, }, { name: "traces endpoint enables otlp", - env: map[string]string{"OTEL_EXPORTER_OTLP_TRACES_ENDPOINT": "http://localhost:4318"}, + env: map[string]string{envOTLPTracesEndpoint: testOTLPEndpoint}, wantEnabled: true, }, { name: "explicit console exporter", - env: map[string]string{"OTEL_TRACES_EXPORTER": "console"}, + env: map[string]string{envTracesExporter: exporterConsole}, wantEnabled: true, }, { name: "grpc protocol", - env: map[string]string{"OTEL_TRACES_EXPORTER": "otlp", "OTEL_EXPORTER_OTLP_PROTOCOL": "grpc"}, + env: map[string]string{envTracesExporter: exporterOTLP, envOTLPProtocol: "grpc"}, wantEnabled: true, }, { name: "exporter none wins over endpoint", env: map[string]string{ - "OTEL_TRACES_EXPORTER": "none", - "OTEL_EXPORTER_OTLP_ENDPOINT": "http://localhost:4318", + envTracesExporter: exporterNone, + envOTLPEndpoint: testOTLPEndpoint, }, wantEnabled: false, }, { name: "OTEL_SDK_DISABLED wins over everything", env: map[string]string{ - "OTEL_SDK_DISABLED": "true", - "OTEL_EXPORTER_OTLP_ENDPOINT": "http://localhost:4318", + envSDKDisabled: "true", + envOTLPEndpoint: testOTLPEndpoint, }, wantEnabled: false, }, { name: "unsupported exporter errors", - env: map[string]string{"OTEL_TRACES_EXPORTER": "jaeger"}, + env: map[string]string{envTracesExporter: "jaeger"}, wantErr: true, }, { name: "unsupported protocol errors", env: map[string]string{ - "OTEL_TRACES_EXPORTER": "otlp", - "OTEL_EXPORTER_OTLP_PROTOCOL": "http/json", + envTracesExporter: exporterOTLP, + envOTLPProtocol: "http/json", }, wantErr: true, }, @@ -100,7 +101,7 @@ func TestSetup_envGating(t *testing.T) { before := noop.NewTracerProvider() otel.SetTracerProvider(before) - shutdown, err := Setup(context.Background(), logr.Discard(), "test-svc", "abc123") + shutdown, err := Setup(context.Background(), "test-svc", "abc123") if tc.wantErr { if err == nil { t.Fatal("want error, got nil") -- 2.49.1 From 026acea2799791bc176125ccc4510f798cdc9415 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 12:25:30 +0200 Subject: [PATCH 11/13] Add plan: e2e test of OTel tracing against real Tempo Co-Authored-By: Claude --- docs/plans/2026-08-24-1224-tracing-e2e.md | 150 ++++++++++++++++++++++ 1 file changed, 150 insertions(+) create mode 100644 docs/plans/2026-08-24-1224-tracing-e2e.md diff --git a/docs/plans/2026-08-24-1224-tracing-e2e.md b/docs/plans/2026-08-24-1224-tracing-e2e.md new file mode 100644 index 0000000..de3c31f --- /dev/null +++ b/docs/plans/2026-08-24-1224-tracing-e2e.md @@ -0,0 +1,150 @@ +# Plan: e2e test — OTel tracing against real Tempo +**Created:** 2026-08-24 12:24 + +## Context + +The tracing feature (MR #4, branch `feat/otel-tracing`) is covered by unit +tests with an in-memory span recorder, but nothing proves the full pipeline: +operator in a real cluster → OTLP export → Tempo ingest → queryable traces +with the documented span topology. The homelab Tempo lives at +`http://192.168.0.30:3200` (query API — verified live from this host: +`/api/echo`, TraceQL `GET /api/search?q=…`, `GET /api/traces/`), with +OTLP ingest on `:4318` (HTTP, verified 200) and `:4317` (gRPC, open). User +decisions: **Go Ginkgo e2e test** (not a shell script), **structural +assertions** (span tree, not just trace-exists), flow per the user's sketch: +deploy operator in kind with tracing on → create kubernetes-provider proxies +→ delete them → shut down — with traces tagged for easy discovery per test +run. This work continues on `feat/otel-tracing`; MR #4 stays the vehicle. + +## Design decisions (from review, with evidence) + +- **Proxy CRs go in the `default` namespace, not the operator namespace.** + The squid pods the kubernetes provider creates carry no securityContext + (internal/provider/kubernetes/pod.go:33-49) and are created in the CR's + namespace; the operator ns is labeled `pod-security enforce=restricted` + (test/e2e/e2e_test.go:61-62) and would reject them. Pod RBAC is + cluster-scoped (config/rbac/role.yaml:10), so `default` works. All + kubectl calls use explicit `-n`. +- **Anchor assertions on `provider.create`, not the root-span search.** A + `name="Reconcile Proxy"` hit may be the finalizer-add or a drift + reconcile (no provider call inside). TraceQL matches span names anywhere + in a trace, so search `{resource.test.run.id="" && name="provider.create"}`, + fetch *that* traceID, then assert companion span names. +- **Run identification with zero code changes:** OTel resource attribute + `test.run.id=` via `OTEL_RESOURCE_ATTRIBUTES` (env wins — + `resource.WithFromEnv()` merges last, internal/tracing/tracing.go). Tempo + vParquet searches arbitrary resource attrs without config; fallback query + documented: `{resource.service.name="egress-proxies-operator" && name="provider.create"}` + + start/end window (Unix **seconds**). +- **OTLP preflight from inside the cluster:** host-reachability of + 192.168.0.30 doesn't prove pod-reachability from kind on macOS, and + export failures log only at V(1) (invisible) — without a preflight, a + broken path is a 2-minute opaque timeout. Reuse the suite's curl-pod + pattern (e2e_test.go:218-248, incl. the restricted-PSS overrides JSON) + to POST to `/v1/traces` and fail fast. +- **No homelab defaults baked into the Makefile.** The spec Skips unless + `TEMPO_URL`/`OTLP_ENDPOINT` are set (otherwise everyone without that LAN + host inherits a 2-minute failure). The copy-pasteable invocation lives in + docs/testing.md. +- **Ginkgo ordering:** top-level container order is randomized, so the + tracing Describe is fully self-contained (own ns create → make install → + make deploy → teardown), same shape as the Manager Describe. `kubectl + delete ns` blocks until termination, so no create/delete race between + the two Describes. + +## Steps + +### Step 1 — `test/e2e/tracing_test.go` (new; `//go:build e2e`, package e2e) + +`Describe("OTel tracing", Ordered)`: + +- **BeforeAll:** + 1. Read `TEMPO_URL` + `OTLP_ENDPOINT`; `Skip("TEMPO_URL/OTLP_ENDPOINT not set")` when empty. + 2. `runID := "e2e-" + strconv.FormatInt(time.Now().UnixNano(), 10)`; + print it to `GinkgoWriter` so the run is findable in Grafana by hand. + 3. Create operator ns + restricted-PSS label; `make install`; + `make deploy IMG=` (same commands as e2e_test.go:54-75, + via `utils.Run`). + 4. Pre-pull the proxy image to kill the biggest flake source: + `docker pull ubuntu/squid:6.6-24.04_edge` + `kind load docker-image` + (via `utils.Run`, honoring `KIND`/`KIND_CLUSTER` env like + utils.LoadImageToKindClusterWithName). + 5. OTLP preflight: curl pod POSTing `{}` to `/v1/traces`, + assert HTTP 200 in its logs (fail message names the endpoint). + 6. `kubectl set env deployment/egress-proxies-operator-controller-manager + -n OTEL_EXPORTER_OTLP_ENDPOINT= + "OTEL_RESOURCE_ATTRIBUTES=k8s.pod.name=$(POD_NAME),k8s.namespace.name=$(POD_NAMESPACE),test.run.id="` + — in-place update keeps the var after the downward-API vars ($(VAR) + expansion needs that ordering); `exec.Command` means no shell mangling + of `$()`. Then `kubectl rollout status`. + 7. `Eventually`: newest controller pod (sorted by creationTimestamp — a + terminating old pod may otherwise be picked) logs contain + `"tracing enabled"`. +- **It "creates proxies and reports reconcile traces":** + - Write 2 Proxy manifests (names `proxy-tracing-e2e-1/2`, + `provider: kubernetes`, modeled on config/samples/proxy_kubernetes.yaml) + to `GinkgoT().TempDir()` (absolute paths — `utils.Run` chdirs the + process); `kubectl apply -n default`. + - `Eventually` (5m — first squid start) `.status.phase == "Ready"` + (confirmed field, api/v1alpha1/proxy_types.go:41). + - `Eventually`: Tempo search + `{resource.test.run.id="" && name="provider.create"}` ≥1 hit + (BSP flushes every ~5s; 2m default timeout is ample). + - Fetch that traceID via `/api/traces/`; assert span names include + `Reconcile Proxy`, `reconcile.managed`, `provider.create`, + `status.patch`, and resource attr `service.name=egress-proxies-operator`. +- **It "traces deletion":** + - `kubectl delete proxy -n default …`; `Eventually` CRs gone (finalizer + → `provider.delete`, DeletionPoll 10s). + - `Eventually`: Tempo search finds `provider.delete` for the runID; fetch + and assert `reconcile.delete` in the same trace. +- **AfterAll** (= the sketch's "shut down operator"): delete leftover + proxies in `default`; `make undeploy` (SIGTERM → `tracingShutdown` + flushes); `make uninstall`; delete operator ns — errors discarded + (`_, _ = utils.Run(...)`), mirroring e2e_test.go:79-95. +- **Tempo client helpers** (same file, stdlib only — the test process runs + on the host, which reaches Tempo directly): + - `tempoSearch(traceql string)` → `GET {TEMPO_URL}/api/search?q=…&start=…&end=…` + (Unix seconds, window = suite start − 5m → now); minimal struct + `{Traces []struct{ TraceID string }}`. + - `tempoTrace(id string)` → `/api/traces/`, decoded as **OTLP-JSON** + (`batches[].scopeSpans[].spans[].name`, resource attrs as + `{key, value:{stringValue}}`) — not Jaeger's shape. Helper flattens to + a span-name set + resource attr map. + +### Step 2 — Makefile + +- `test-e2e`: pass `TEMPO_URL`/`OTLP_ENDPOINT` through to `go test` env + (no defaults) and add `-timeout 30m` — the suite already runs + docker-build + kind-load in BeforeSuite plus 3–5m Eventuallys, and this + adds a second full deploy cycle + image pulls; the 10m default will be + exceeded on cold caches. + +### Step 3 — Docs + +- `docs/testing.md` (§ e2e, currently "scaffold… only asserts manager runs + and serves metrics"): document the tracing spec, its Skip gate, and the + invocation: + `TEMPO_URL=http://192.168.0.30:3200 OTLP_ENDPOINT=http://192.168.0.30:4318 make test-e2e`. +- Execution-log entries per step in `docs/plans-executions/2026-08-24-1224-tracing-e2e.md`. +- CHANGELOG entry only after the user confirms a green run (house rule). + +## Not doing (and why) + +- No dedicated flush assertion on shutdown — teardown exercises the flush + path, but attributing a specific late span to it is guesswork. +- No gRPC (4317) variant — http/protobuf is the operator default and the + verified path; a variant run is a one-env-var change if ever wanted. +- No changes to `internal/` — the whole test works through public surface + (env vars, kubectl, Tempo API), which is the point of an e2e test. + +## Verification + +1. `TEMPO_URL=http://192.168.0.30:3200 OTLP_ENDPOINT=http://192.168.0.30:4318 make test-e2e` + → tracing spec passes (both Its); without the env vars → spec reports + Skipped, remainder of suite unaffected. +2. In Grafana: TraceQL `{resource.test.run.id=""}` + shows the run's traces with the expected tree. +3. `go vet -tags=e2e ./...` clean (documented routine). +4. A deliberately wrong `OTLP_ENDPOINT` (e.g. port 9) fails fast in the + preflight step with a clear message, not a 2-minute search timeout. -- 2.49.1 From e691105f895155dba08ec3398d6c17f9a52e68e0 Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 12:31:41 +0200 Subject: [PATCH 12/13] Add Tempo-gated e2e test for OTel tracing Co-Authored-By: Claude --- Makefile | 3 +- .../2026-08-24-1224-tracing-e2e.md | 38 ++ docs/testing.md | 34 +- test/e2e/tracing_test.go | 424 ++++++++++++++++++ 4 files changed, 496 insertions(+), 3 deletions(-) create mode 100644 docs/plans-executions/2026-08-24-1224-tracing-e2e.md create mode 100644 test/e2e/tracing_test.go diff --git a/Makefile b/Makefile index ac8df24..d348f5d 100644 --- a/Makefile +++ b/Makefile @@ -90,7 +90,8 @@ setup-test-e2e: ## Set up a Kind cluster for e2e tests if it does not exist .PHONY: test-e2e test-e2e: setup-test-e2e manifests generate fmt vet ## Run the e2e tests. Expected an isolated environment using Kind. - KIND=$(KIND) KIND_CLUSTER=$(KIND_CLUSTER) go test -tags=e2e ./test/e2e/ -v -ginkgo.v + KIND=$(KIND) KIND_CLUSTER=$(KIND_CLUSTER) TEMPO_URL=$(TEMPO_URL) OTLP_ENDPOINT=$(OTLP_ENDPOINT) \ + go test -tags=e2e ./test/e2e/ -v -ginkgo.v -timeout 30m $(MAKE) cleanup-test-e2e .PHONY: cleanup-test-e2e diff --git a/docs/plans-executions/2026-08-24-1224-tracing-e2e.md b/docs/plans-executions/2026-08-24-1224-tracing-e2e.md new file mode 100644 index 0000000..95ac2d6 --- /dev/null +++ b/docs/plans-executions/2026-08-24-1224-tracing-e2e.md @@ -0,0 +1,38 @@ +# Execution log: e2e test — OTel tracing against real Tempo + +Plan: `docs/plans/2026-08-24-1224-tracing-e2e.md` + +- [x] Step 1 — `test/e2e/tracing_test.go` +- [x] Step 2 — Makefile +- [x] Step 3 — Docs + +## Steps 1–3 — spec, Makefile, docs (one commit) + +The three steps landed together — the spec is one new file and the other +two are its wiring. `Describe("OTel tracing", Ordered)` is fully +self-contained (own ns create → `make install`/`make deploy` → teardown) +because Ginkgo randomizes top-level container order, so it cannot share the +Manager Describe's deployment. It reuses the package-level `namespace` / +`managerImage` and the suite's idioms (`utils.Run`, curl-pod with the +restricted-PSS overrides JSON, log-substring `Eventually`s). + +Judgment calls beyond the plan's letter: + +- The squid pre-pull (`docker pull` + `kind load`) is **best effort** — a + missing docker binary logs a note and continues rather than failing the + spec; the 5m Ready timeout still covers an in-cluster pull. +- The OTLP preflight pod prints per-attempt HTTP codes and a final + `OTLP_OK`/`OTLP_UNREACHABLE` marker; the assertion quotes the pod's + output, so an unreachable endpoint names itself in the failure. +- `kubectl set env` is passed the literal + `OTEL_RESOURCE_ATTRIBUTES=...$(POD_NAME)...` string via `exec.Command` — + no shell involved, kubectl stores `$()` verbatim, and the in-place update + keeps the var after the downward-API vars it references. +- Tempo helpers are stdlib-only; `/api/traces/` is decoded as + OTLP-JSON (`batches[].scopeSpans[].spans[].name`), which is Tempo's + actual shape (not Jaeger's). + +Verified so far: `go vet -tags=e2e ./...` clean. The live run against +Tempo (`TEMPO_URL=http://192.168.0.30:3200 +OTLP_ENDPOINT=http://192.168.0.30:4318 make test-e2e`) is recorded below +once it has been executed. diff --git a/docs/testing.md b/docs/testing.md index 61a2d8a..03fee39 100644 --- a/docs/testing.md +++ b/docs/testing.md @@ -92,8 +92,38 @@ compiles only under `-tags=e2e`, manages its own kind cluster (`make test-e2e` / `make cleanup-test-e2e`), and has been kept compiling (`go vet -tags=e2e ./...` is part of the routine) but is **not part of `make test` and was not used for the release verification** — the manual -kind run below covers strictly more. Treat it as scaffold to grow into if -CI wants an automated cluster smoke test. +kind run below covers strictly more. + +### The OTel tracing spec (Tempo-gated) + +`test/e2e/tracing_test.go` proves the full tracing pipeline against a +**real Tempo**: deploy in kind with tracing enabled, create two +kubernetes-provider proxies, delete them, and assert in Tempo that the +traces exist with the documented span topology (`Reconcile Proxy` → +`reconcile.managed` / `provider.create` / `status.patch`, and +`reconcile.delete` / `provider.delete` on the way out). + +It **skips unless both env vars are set** (so the rest of the suite runs +anywhere). Homelab invocation: + +```bash +TEMPO_URL=http://192.168.0.30:3200 \ +OTLP_ENDPOINT=http://192.168.0.30:4318 \ +make test-e2e +``` + +Worth knowing: + +- Every span of a run carries the resource attribute + `test.run.id=e2e-` (injected via `OTEL_RESOURCE_ATTRIBUTES`, no + code involved); the run ID is printed in the test log, and + `{resource.test.run.id=""}` in Grafana shows exactly that run. +- The spec preflights the OTLP endpoint **from inside the cluster** with a + curl pod and fails fast with a clear message if it's unreachable — + export failures are otherwise only visible at `-zap-log-level=1`. +- Proxy CRs are created in `default`, not the operator namespace: the + squid pods carry no securityContext and the operator namespace enforces + restricted PSS. ## The kind verification run (the real end-to-end) diff --git a/test/e2e/tracing_test.go b/test/e2e/tracing_test.go new file mode 100644 index 0000000..3bd8091 --- /dev/null +++ b/test/e2e/tracing_test.go @@ -0,0 +1,424 @@ +//go:build e2e +// +build e2e + +/* +Copyright 2026. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package e2e + +import ( + "context" + "encoding/json" + "fmt" + "io" + "net/http" + "net/url" + "os" + "os/exec" + "path/filepath" + "strconv" + "strings" + "time" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" + + "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/test/utils" +) + +// The tracing e2e proves the full pipeline against a real Tempo: operator in +// kind → OTLP export → Tempo ingest → traces queryable with the documented +// span topology. It is gated on TEMPO_URL (Tempo query API, e.g. +// http://192.168.0.30:3200) and OTLP_ENDPOINT (OTLP HTTP ingest, e.g. +// http://192.168.0.30:4318) and skips when either is unset, so the rest of +// the suite runs anywhere. +// +// Every span of a run carries the resource attribute test.run.id= +// (injected via OTEL_RESOURCE_ATTRIBUTES — no code changes), so one TraceQL +// query finds exactly this run's traces, in the test and in Grafana alike. +var _ = Describe("OTel tracing", Ordered, func() { + // Proxy CRs live in default, not the operator namespace: the squid pods + // the kubernetes provider creates carry no securityContext and would be + // rejected by the operator namespace's restricted PSS label. + const proxyNS = "default" + const deploymentName = "egress-proxies-operator-controller-manager" + const squidImage = "ubuntu/squid:6.6-24.04_edge" + + proxyNames := []string{"proxy-tracing-e2e-1", "proxy-tracing-e2e-2"} + + var ( + tempoURL string + otlpEndpoint string + runID string + suiteStart time.Time + ) + + BeforeAll(func() { + tempoURL = os.Getenv("TEMPO_URL") + otlpEndpoint = os.Getenv("OTLP_ENDPOINT") + if tempoURL == "" || otlpEndpoint == "" { + Skip("TEMPO_URL / OTLP_ENDPOINT not set — skipping the Tempo-backed tracing e2e") + } + suiteStart = time.Now() + runID = "e2e-" + strconv.FormatInt(suiteStart.UnixNano(), 10) + _, _ = fmt.Fprintf(GinkgoWriter, + "tracing e2e run id: %s — find this run in Grafana with TraceQL {resource.test.run.id=%q}\n", + runID, runID) + + By("creating manager namespace") + cmd := exec.Command("kubectl", "create", "ns", namespace) + _, err := utils.Run(cmd) + Expect(err).NotTo(HaveOccurred(), "Failed to create namespace") + + By("labeling the namespace to enforce the restricted security policy") + cmd = exec.Command("kubectl", "label", "--overwrite", "ns", namespace, + "pod-security.kubernetes.io/enforce=restricted") + _, err = utils.Run(cmd) + Expect(err).NotTo(HaveOccurred(), "Failed to label namespace with restricted policy") + + By("installing CRDs") + cmd = exec.Command("make", "install") + _, err = utils.Run(cmd) + Expect(err).NotTo(HaveOccurred(), "Failed to install CRDs") + + By("deploying the controller-manager") + cmd = exec.Command("make", "deploy", fmt.Sprintf("IMG=%s", managerImage)) + _, err = utils.Run(cmd) + Expect(err).NotTo(HaveOccurred(), "Failed to deploy the controller-manager") + + By("pre-pulling the squid image into kind (best effort, kills the biggest flake source)") + if _, err := utils.Run(exec.Command("docker", "pull", squidImage)); err == nil { + if err := utils.LoadImageToKindClusterWithName(squidImage); err != nil { + _, _ = fmt.Fprintf(GinkgoWriter, "kind load of %s failed (continuing): %v\n", squidImage, err) + } + } else { + _, _ = fmt.Fprintf(GinkgoWriter, "docker pull %s failed (continuing): %v\n", squidImage, err) + } + + By("preflighting the OTLP endpoint from inside the cluster") + // Host-reachability of the OTLP endpoint does not prove + // pod-reachability from inside kind, and the operator logs export + // failures only at V(1) — without this, a broken path is a slow, + // opaque search timeout instead of a clear failure. + preflightOTLP(otlpEndpoint) + + By("pointing the operator at the OTLP endpoint and tagging the test run") + // OTEL_RESOURCE_ATTRIBUTES is replaced in place, which keeps it + // listed after the downward-API POD_NAME/POD_NAMESPACE vars — + // $(VAR) expansion only sees earlier-listed vars. exec.Command + // passes $(...) through without shell mangling. + cmd = exec.Command("kubectl", "set", "env", + "deployment/"+deploymentName, "-n", namespace, + "OTEL_EXPORTER_OTLP_ENDPOINT="+otlpEndpoint, + fmt.Sprintf( + "OTEL_RESOURCE_ATTRIBUTES=k8s.pod.name=$(POD_NAME),k8s.namespace.name=$(POD_NAMESPACE),test.run.id=%s", + runID)) + _, err = utils.Run(cmd) + Expect(err).NotTo(HaveOccurred(), "Failed to set OTel env on the deployment") + + cmd = exec.Command("kubectl", "rollout", "status", + "deployment/"+deploymentName, "-n", namespace, "--timeout=3m") + _, err = utils.Run(cmd) + Expect(err).NotTo(HaveOccurred(), "Rollout after set env did not finish") + + By("verifying the operator reports tracing enabled") + Eventually(func(g Gomega) { + pod := newestControllerPod(g) + out, err := utils.Run(exec.Command("kubectl", "logs", pod, "-n", namespace)) + g.Expect(err).NotTo(HaveOccurred()) + g.Expect(out).To(ContainSubstring("tracing enabled"), + "operator did not log 'tracing enabled' after rollout") + }, 2*time.Minute).Should(Succeed()) + }) + + AfterAll(func() { + if tempoURL == "" || otlpEndpoint == "" { + return // spec was skipped; nothing was deployed + } + By("cleaning up test proxies") + args := append([]string{"delete", "proxy", "-n", proxyNS, "--ignore-not-found"}, proxyNames...) + _, _ = utils.Run(exec.Command("kubectl", args...)) + + By("cleaning up the OTLP preflight pod") + _, _ = utils.Run(exec.Command("kubectl", "delete", "pod", otlpProbePodName, "-n", namespace, + "--ignore-not-found")) + + By("undeploying the controller-manager") + _, _ = utils.Run(exec.Command("make", "undeploy")) + + By("uninstalling CRDs") + _, _ = utils.Run(exec.Command("make", "uninstall")) + + By("removing manager namespace") + _, _ = utils.Run(exec.Command("kubectl", "delete", "ns", namespace)) + }) + + It("creates proxies and reports reconcile traces to Tempo", func() { + By("applying two kubernetes-provider proxies") + // Absolute paths on purpose: utils.Run chdirs the whole process. + dir := GinkgoT().TempDir() + for _, name := range proxyNames { + manifest := fmt.Sprintf(`apiVersion: crawl.example.com/v1alpha1 +kind: Proxy +metadata: + name: %s + namespace: %s +spec: + mode: Managed + provider: kubernetes + attributes: + purpose: tracing-e2e +`, name, proxyNS) + path := filepath.Join(dir, name+".yaml") + Expect(os.WriteFile(path, []byte(manifest), 0o644)).To(Succeed()) + _, err := utils.Run(exec.Command("kubectl", "apply", "-f", path)) + Expect(err).NotTo(HaveOccurred(), "Failed to apply %s", name) + } + + By("waiting for the proxies to become Ready") + Eventually(func(g Gomega) { + for _, name := range proxyNames { + out, err := utils.Run(exec.Command("kubectl", "get", "proxy", name, + "-n", proxyNS, "-o", "jsonpath={.status.phase}")) + g.Expect(err).NotTo(HaveOccurred()) + g.Expect(out).To(Equal("Ready"), "proxy %s not Ready", name) + } + }, 5*time.Minute).Should(Succeed()) + + By("finding a provider.create trace for this run in Tempo") + // Anchored on provider.create, not the root span name: a + // "Reconcile Proxy" hit could be the finalizer-add or a drift + // reconcile, which contain no provider call. + traceID := eventuallyFindTrace(tempoURL, runID, "provider.create", suiteStart) + + By("asserting the reconcile trace structure") + spanNames, resAttrs, err := tempoTrace(tempoURL, traceID) + Expect(err).NotTo(HaveOccurred()) + Expect(spanNames).To(ContainElements( + "Reconcile Proxy", "reconcile.managed", "provider.create", "status.patch"), + "trace %s is missing expected spans; got: %v", traceID, spanNames) + Expect(resAttrs["service.name"]).To(Equal("egress-proxies-operator")) + Expect(resAttrs["test.run.id"]).To(Equal(runID)) + }) + + It("traces proxy deletion", func() { + By("deleting the proxies") + args := append([]string{"delete", "proxy", "-n", proxyNS, "--wait=false"}, proxyNames...) + _, err := utils.Run(exec.Command("kubectl", args...)) + Expect(err).NotTo(HaveOccurred(), "Failed to delete proxies") + + By("waiting for the proxies to be gone (finalizer ran provider.delete)") + Eventually(func(g Gomega) { + out, err := utils.Run(exec.Command("kubectl", "get", "proxy", "-n", proxyNS, "-o", "name")) + g.Expect(err).NotTo(HaveOccurred()) + g.Expect(out).NotTo(ContainSubstring("proxy-tracing-e2e")) + }, 3*time.Minute).Should(Succeed()) + + By("finding a provider.delete trace for this run in Tempo") + traceID := eventuallyFindTrace(tempoURL, runID, "provider.delete", suiteStart) + + By("asserting the deletion trace structure") + spanNames, _, err := tempoTrace(tempoURL, traceID) + Expect(err).NotTo(HaveOccurred()) + Expect(spanNames).To(ContainElements("Reconcile Proxy", "reconcile.delete", "provider.delete"), + "trace %s is missing expected spans; got: %v", traceID, spanNames) + }) +}) + +// preflightOTLP runs a one-shot curl pod inside the cluster POSTing to the +// OTLP HTTP ingest, and fails with a clear message when it is unreachable. +// The pod runs in the restricted-PSS operator namespace, hence the full +// securityContext (same shape as the curl-metrics pod). +func preflightOTLP(otlpEndpoint string) { + script := fmt.Sprintf( + "for i in $(seq 1 10); do "+ + "code=$(curl -sS -o /dev/null -w '%%{http_code}' -X POST "+ + "-H 'Content-Type: application/json' -d '{}' %s/v1/traces); "+ + "echo \"attempt $i: HTTP $code\"; "+ + "[ \"$code\" = \"200\" ] && echo OTLP_OK && exit 0; sleep 2; "+ + "done; echo OTLP_UNREACHABLE; exit 1", + otlpEndpoint) + cmd := exec.Command("kubectl", "run", otlpProbePodName, "--restart=Never", + "--namespace", namespace, + "--image=curlimages/curl:latest", + "--overrides", + fmt.Sprintf(`{ + "spec": { + "containers": [{ + "name": "curl", + "image": "curlimages/curl:latest", + "command": ["/bin/sh", "-c"], + "args": [%q], + "securityContext": { + "readOnlyRootFilesystem": true, + "allowPrivilegeEscalation": false, + "capabilities": { + "drop": ["ALL"] + }, + "runAsNonRoot": true, + "runAsUser": 1000, + "seccompProfile": { + "type": "RuntimeDefault" + } + } + }] + } + }`, script)) + _, err := utils.Run(cmd) + Expect(err).NotTo(HaveOccurred(), "Failed to create the OTLP preflight pod") + + Eventually(func(g Gomega) { + out, err := utils.Run(exec.Command("kubectl", "get", "pod", otlpProbePodName, + "-n", namespace, "-o", "jsonpath={.status.phase}")) + g.Expect(err).NotTo(HaveOccurred()) + g.Expect(out).To(BeElementOf("Succeeded", "Failed"), "preflight pod still running") + }, 2*time.Minute).Should(Succeed()) + + logs, _ := utils.Run(exec.Command("kubectl", "logs", otlpProbePodName, "-n", namespace)) + Expect(logs).To(ContainSubstring("OTLP_OK"), + "OTLP endpoint %s is not reachable from inside the kind cluster; curl output:\n%s", + otlpEndpoint, logs) +} + +// otlpProbePodName mirrors the Describe-local constant for the helpers below. +const otlpProbePodName = "curl-otlp" + +// newestControllerPod returns the most recently created controller pod — +// right after a rollout, an unsorted lookup may pick the terminating one. +func newestControllerPod(g Gomega) string { + out, err := utils.Run(exec.Command("kubectl", "get", "pods", + "-l", "control-plane=controller-manager", "-n", namespace, + "--sort-by=.metadata.creationTimestamp", "-o", "name")) + g.Expect(err).NotTo(HaveOccurred()) + lines := utils.GetNonEmptyLines(out) + g.Expect(lines).NotTo(BeEmpty(), "no controller pods found") + return strings.TrimPrefix(lines[len(lines)-1], "pod/") +} + +// eventuallyFindTrace polls Tempo until a trace containing a span with the +// given name exists for this run, and returns its trace ID. The batch span +// processor flushes every ~5s, so a couple of polls is normal. +func eventuallyFindTrace(tempoURL, runID, spanName string, since time.Time) string { + var traceID string + query := fmt.Sprintf(`{resource.test.run.id=%q && name=%q}`, runID, spanName) + Eventually(func(g Gomega) { + ids, err := tempoSearch(tempoURL, query, since) + g.Expect(err).NotTo(HaveOccurred()) + g.Expect(ids).NotTo(BeEmpty(), "no trace for %s yet (query: %s)", spanName, query) + traceID = ids[0] + }, 2*time.Minute).Should(Succeed()) + return traceID +} + +// tempoSearch runs a TraceQL query against Tempo's search API and returns +// the matching trace IDs. start/end are Unix seconds. +func tempoSearch(tempoURL, traceql string, since time.Time) ([]string, error) { + u, err := url.Parse(tempoURL + "/api/search") + if err != nil { + return nil, err + } + q := u.Query() + q.Set("q", traceql) + q.Set("start", strconv.FormatInt(since.Add(-5*time.Minute).Unix(), 10)) + q.Set("end", strconv.FormatInt(time.Now().Add(time.Minute).Unix(), 10)) + q.Set("limit", "20") + u.RawQuery = q.Encode() + + body, err := tempoGet(u.String()) + if err != nil { + return nil, err + } + var result struct { + Traces []struct { + TraceID string `json:"traceID"` + } `json:"traces"` + } + if err := json.Unmarshal(body, &result); err != nil { + return nil, fmt.Errorf("decoding Tempo search response: %w", err) + } + ids := make([]string, 0, len(result.Traces)) + for _, t := range result.Traces { + ids = append(ids, t.TraceID) + } + return ids, nil +} + +// tempoTrace fetches one trace and flattens it to a span-name list plus the +// resource attributes. Tempo returns OTLP-JSON (batches → scopeSpans → +// spans), not Jaeger's shape. +func tempoTrace(tempoURL, traceID string) ([]string, map[string]string, error) { + body, err := tempoGet(tempoURL + "/api/traces/" + traceID) + if err != nil { + return nil, nil, err + } + var trace struct { + Batches []struct { + Resource struct { + Attributes []struct { + Key string `json:"key"` + Value struct { + StringValue string `json:"stringValue"` + } `json:"value"` + } `json:"attributes"` + } `json:"resource"` + ScopeSpans []struct { + Spans []struct { + Name string `json:"name"` + } `json:"spans"` + } `json:"scopeSpans"` + } `json:"batches"` + } + if err := json.Unmarshal(body, &trace); err != nil { + return nil, nil, fmt.Errorf("decoding Tempo trace %s: %w", traceID, err) + } + var spanNames []string + resAttrs := map[string]string{} + for _, b := range trace.Batches { + for _, a := range b.Resource.Attributes { + if a.Value.StringValue != "" { + resAttrs[a.Key] = a.Value.StringValue + } + } + for _, ss := range b.ScopeSpans { + for _, s := range ss.Spans { + spanNames = append(spanNames, s.Name) + } + } + } + return spanNames, resAttrs, nil +} + +func tempoGet(rawURL string) ([]byte, error) { + ctx, cancel := context.WithTimeout(context.Background(), 15*time.Second) + defer cancel() + req, err := http.NewRequestWithContext(ctx, http.MethodGet, rawURL, nil) + if err != nil { + return nil, err + } + resp, err := http.DefaultClient.Do(req) + if err != nil { + return nil, fmt.Errorf("querying Tempo: %w", err) + } + defer func() { _ = resp.Body.Close() }() + body, err := io.ReadAll(resp.Body) + if err != nil { + return nil, err + } + if resp.StatusCode != http.StatusOK { + return nil, fmt.Errorf("tempo returned %d for %s: %s", resp.StatusCode, rawURL, string(body)) + } + return body, nil +} -- 2.49.1 From f8b911f1db16e92c3e282e0a70b2668567016dac Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Mon, 24 Aug 2026 12:39:05 +0200 Subject: [PATCH 13/13] Record live and negative Tempo e2e runs in the execution log Co-Authored-By: Claude --- .../2026-08-24-1224-tracing-e2e.md | 38 +++++++++++++++++-- 1 file changed, 34 insertions(+), 4 deletions(-) diff --git a/docs/plans-executions/2026-08-24-1224-tracing-e2e.md b/docs/plans-executions/2026-08-24-1224-tracing-e2e.md index 95ac2d6..fc02b96 100644 --- a/docs/plans-executions/2026-08-24-1224-tracing-e2e.md +++ b/docs/plans-executions/2026-08-24-1224-tracing-e2e.md @@ -32,7 +32,37 @@ Judgment calls beyond the plan's letter: OTLP-JSON (`batches[].scopeSpans[].spans[].name`), which is Tempo's actual shape (not Jaeger's). -Verified so far: `go vet -tags=e2e ./...` clean. The live run against -Tempo (`TEMPO_URL=http://192.168.0.30:3200 -OTLP_ENDPOINT=http://192.168.0.30:4318 make test-e2e`) is recorded below -once it has been executed. +Verified so far: `go vet -tags=e2e ./...` clean. + +## Live run against homelab Tempo + +First attempt failed before the suite started — Docker Desktop wasn't +running (`kind` could not create the cluster), and the failure was masked +to exit 0 by a `| tail` pipe on the make invocation (no pipefail in that +shell). Rerun with Docker started first and no pipe: + +```bash +TEMPO_URL=http://192.168.0.30:3200 OTLP_ENDPOINT=http://192.168.0.30:4318 make test-e2e +``` + +Result: **SUCCESS — 4/4 specs (Manager smoke + both tracing Its), 219 s**, +kind cluster auto-deleted. Run id `e2e-1787567624494810000`; the traces are +findable in Grafana with TraceQL +`{resource.test.run.id="e2e-1787567624494810000"}`. Both proxies reached +`Ready` on real squid pods; the create trace carried +`Reconcile Proxy` / `reconcile.managed` / `provider.create` / +`status.patch` and the expected resource attrs; the deletion trace carried +`reconcile.delete` / `provider.delete`. + +Worth noting: the OTLP preflight and both Tempo polls succeeded on the +in-cluster → LAN path (kind on macOS reaches 192.168.0.30 through Docker +Desktop's NAT), so no extra networking setup is needed on this machine. + +The plan's negative verification also ran: with a deliberately wrong +endpoint (`OTLP_ENDPOINT=http://192.168.0.30:9999`) the tracing spec +failed in the BeforeAll preflight after ~52 s with +`OTLP endpoint http://192.168.0.30:9999 is not reachable from inside the +kind cluster; curl output: OTLP_UNREACHABLE` — a named, fast failure +instead of a 2-minute opaque search timeout — and teardown still deleted +the kind cluster (`make cleanup-test-e2e` run explicitly, since a failing +`go test` skips the Makefile's cleanup step). -- 2.49.1