149 lines
7.3 KiB
Markdown
149 lines
7.3 KiB
Markdown
# Execution log: OpenTelemetry tracing integrated with logr/zap logging
|
|
|
|
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
|
|
- [x] Step 4 — `cmd/main.go` wiring
|
|
- [x] Step 5 — Reconciler spans
|
|
- [x] Step 6 — Discovery server
|
|
- [x] 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.
|
|
|
|
## 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.
|
|
|
|
## 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.
|
|
|
|
## 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.
|
|
|
|
## 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.
|
|
|
|
## 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.
|
|
|
|
## 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.
|