diff --git a/cmd/main.go b/cmd/main.go index dfa8a38..4bacd2f 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -38,6 +38,7 @@ import ( "k8s.io/apimachinery/pkg/runtime" utilruntime "k8s.io/apimachinery/pkg/util/runtime" clientgoscheme "k8s.io/client-go/kubernetes/scheme" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/cache" "sigs.k8s.io/controller-runtime/pkg/client" @@ -162,7 +163,15 @@ func main() { os.Exit(0) } - ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts))) + logger := zap.New(zap.UseFlagOptions(&opts)) + ctrl.SetLogger(logger) + // client-go logs through klog, and controller-runtime hands the leader + // elector a context with no logr in it, so klog.FromContext falls back + // to klog's own stderr writer and those lines ignore the encoder + // entirely. Plain SetLogger rather than the contextual form: it keeps + // klog's verbosity check in front, so this changes the format of what + // klog already emits without letting client-go's V(1) chatter through. + klog.SetLogger(logger) setupLog.Info("Starting egress-proxies-operator", "commit", version.Resolve(), "goVersion", goruntime.Version()) diff --git a/config/manager/manager.yaml b/config/manager/manager.yaml index 2dd089d..c334b6d 100644 --- a/config/manager/manager.yaml +++ b/config/manager/manager.yaml @@ -64,6 +64,13 @@ spec: - --leader-elect - --health-probe-bind-address=:8081 - --providers-config=/etc/proxy-operator/providers.yaml + # Structured logs: every line is one JSON object, so `kubectl logs + # | jq` works. The time encoding is not optional — the JSON encoder + # defaults to epoch seconds. Verbosity stays at the binary's + # default (debug, one line per provider API call); add + # --zap-log-level=info for outcomes only. + - --zap-encoder=json + - --zap-time-encoding=rfc3339 # Add --trace-health-probes to emit one span per health probe # (high volume: ~1/s per proxy). # Provider health checks (kubectl get providerhealth) run every diff --git a/docs/plans-executions/2026-09-17-1515-kvm2-review-fixes.md b/docs/plans-executions/2026-09-17-1515-kvm2-review-fixes.md index 910d0b7..08ef135 100644 --- a/docs/plans-executions/2026-09-17-1515-kvm2-review-fixes.md +++ b/docs/plans-executions/2026-09-17-1515-kvm2-review-fixes.md @@ -7,6 +7,9 @@ Plan: [docs/plans/2026-09-17-1515-kvm2-review-fixes.md](../plans/2026-09-17-1515 - [x] Step 3 — H3: an unreadable address must not look like a missing one - [x] Step 4 — H4: the base image cache must not be shared across provider entries +- [ ] Step 5 — Validate H1-H4 in-cluster against beelink (in progress) +- [x] Step 6 — Route klog into the structured logger + Remaining after those: the 48 mediums and lows in `review/REPORT.md`. Each gets its own checklist line here when it is planned, so this list stays a record of decided work rather than a wish. @@ -378,3 +381,89 @@ the first end-to-end exercise of the new name, and it will do a real cold downlo **Docs touched beyond the obvious:** the eviction recipe named `base-debian-13.qcow2`, which after this change is *kvm's* file — following it would have deleted the wrong provider's base. It now greps for the prefix and deletes the marker first. + +## Step 6 — Route klog into the structured logger + +Not a review finding. Found while watching the Step 5 validation: some lines ignored the zap +encoder no matter what, so `kubectl logs | jq` could never work. + +``` +I0917 19:50:02.580097 1 leaderelection.go:258] "Attempting to acquire leader lease..." lock="..." +``` + +That is klog's own stderr writer, not ours. client-go's leader elector calls +`klog.FromContext(ctx)` (`leaderelection.go:257`), and controller-runtime hands the elector a +context with no logr in it — `mgr.Start` receives `ctrl.SetupSignalHandler()`, which carries no +logger (`pkg/manager/internal.go:461-473`). `FromContext` falls back to `Background()`, and with +no logger registered that is klog's text sink. Nothing in this repo imported or configured klog; +it was an indirect dependency that around 60 linked packages use, including +`client-go/tools/{leaderelection,cache,record}` and `client-go/transport`. controller-runtime +does not route it either — its only `klog.SetLogger` call is in its own test suite. + +**`klog.SetLogger(logger)`, deliberately not `SetLoggerWithOptions(logger, ContextualLogger(true))`.** +The contextual form is what klog's docs recommend, because it skips a klogr round trip. It also +disables klog's verbosity gate ("Such a logger cannot rely on verbosity checking in klog", +`contextual.go:83-86`), handing the decision to zap — whose level under `Development: true` is +Debug, which enables V(1). client-go's V(1) chatter, suppressed today by klog's own `-v=0`, +would have started appearing. Plain `SetLogger` keeps klog's check in front and still redirects +what it does emit ("all log lines will be suppressed from the regular output, and redirected to +the logr implementation", `contextual.go:47-48`). Same fix to the format, no new volume — which +matters, because the complaint that started this was volume. + +`k8s.io/klog/v2` moves from indirect to direct in `go.mod`. It was already in the module graph; +nothing new is downloaded. + +**The other bypass.** The discovery API's `http.Server` set no `ErrorLog`, so `net/http`'s own +faults — a failed `Accept`, a panic escaping a handler — went to the stdlib logger on stderr. +It now drains into logr through `logr.ToSlogHandler`, the pattern +`internal/provider/gcp/wirelog.go:31-36` already uses. This server is plain HTTP with no TLS, so +`ErrorLog` carries real faults rather than handshake noise, and Error level is right. + +**Deployment.** `--zap-encoder=json` and `--zap-time-encoding=rfc3339` on the manager. +Verified the flag beats the in-code default rather than assuming it: `addDefaults` fills +`NewEncoder` only `if o.NewEncoder == nil` (`zap.go:176-191`) and `BindFlags` sets it from the +flag. The time encoding is not optional — the JSON encoder defaults to epoch seconds. +Verbosity was left at debug on purpose; `--zap-log-level=info` drops the per-RPC lines. + +`opts := zap.Options{Development: true}` stays. Flipping it would change the format for every +deployment of this operator, and the flags get the same result here without that reach. + +### Tests + +None. Three changes, all wiring: two struct fields and a manifest key. `cmd/main.go` has no test +coverage, and pinning `klog.SetLogger` means mutating process-global state that leaks into every +other test in the package. Verified by observation instead, which for this change is stronger +than a unit test would be. + +### Verification + +```bash +kubectl -n egress-proxies-operator-system logs deploy/... | grep -i leader +# {"level":"info","ts":"2026-09-17T20:10:00Z","msg":"Attempting to acquire leader lease...", +# "lock":"egress-proxies-operator-system/b47711d1.example.com"} + +kubectl -n egress-proxies-operator-system logs deploy/... | jq -e -s 'length > 0' +# YES - every line is valid JSON +``` + +The `jq -s` check is the one that counts: it fails if *any* line is not JSON, which is exactly +the property being fixed. All four existing proxies stayed Ready across the rollout and all +three ProviderHealth entries stayed Ready. + +### Worth noting + +**The JSON encoder renders durations as float seconds**, so `"duration":"566.12µs"` became +`"duration":0.000336664`. Machine-friendlier, worse to read. Either format in the query — +`(.duration*1000000|round)` for µs — or pass an encoder config option in code, which +controller-runtime exposes (`zap.Options.EncoderConfigOptions`, `zap.go:140-144`): + +```go +opts := zap.Options{ + Development: true, + EncoderConfigOptions: []zap.EncoderConfigOption{ + func(c *zapcore.EncoderConfig) { c.EncodeDuration = zapcore.StringDurationEncoder }, + }, +} +``` + +Left out of this step as scope the plan did not cover. diff --git a/go.mod b/go.mod index 8e6cf30..c8aefb3 100644 --- a/go.mod +++ b/go.mod @@ -23,6 +23,7 @@ require ( k8s.io/api v0.36.0 k8s.io/apimachinery v0.36.0 k8s.io/client-go v0.36.0 + k8s.io/klog/v2 v2.140.0 sigs.k8s.io/controller-runtime v0.24.1 sigs.k8s.io/yaml v1.6.0 ) @@ -104,7 +105,6 @@ require ( k8s.io/apiextensions-apiserver v0.36.0 // indirect k8s.io/apiserver v0.36.0 // indirect k8s.io/component-base v0.36.0 // indirect - k8s.io/klog/v2 v2.140.0 // indirect k8s.io/kube-openapi v0.0.0-20260317180543-43fb72c5454a // indirect k8s.io/streaming v0.36.0 // indirect k8s.io/utils v0.0.0-20260210185600-b8788abfbbc2 // indirect diff --git a/internal/discovery/server.go b/internal/discovery/server.go index c8546bb..e387b35 100644 --- a/internal/discovery/server.go +++ b/internal/discovery/server.go @@ -9,6 +9,7 @@ import ( "context" "crypto/subtle" "encoding/json" + "log/slog" "net" "net/http" "strings" @@ -111,7 +112,11 @@ func (s *Server) Start(ctx context.Context) error { s.mu.Unlock() srv := &http.Server{ - Handler: s.handler(), + Handler: s.handler(), + // Without this, net/http's own faults (a failed Accept, a panic that + // escapes a handler) go to the stdlib logger on stderr, outside the + // structured stream. + ErrorLog: slog.NewLogLogger(logr.ToSlogHandler(s.log), slog.LevelError), ReadHeaderTimeout: readHeadTimeout, ReadTimeout: 10 * time.Second, WriteTimeout: 10 * time.Second,