From 4114d43e8701d9e43bc9f0b6f7743cc01db73dfe Mon Sep 17 00:00:00 2001 From: kacerr Date: Thu, 17 Sep 2026 20:24:37 +0000 Subject: [PATCH] Route klog and net/http's own errors into the structured logger Some lines ignored the zap encoder entirely, so `kubectl logs | jq` could never work: I0917 19:50:02.580097 1 leaderelection.go:258] "Attempting to acquire leader lease..." lock="egress-proxies-operator-system/b47711d1..." That is klog's own stderr writer, not ours. client-go's leader elector calls klog.FromContext(ctx), and controller-runtime hands the elector a context with no logr in it -- mgr.Start receives ctrl.SetupSignalHandler(), which carries no logger. FromContext falls back to Background(), and with no logger registered that is klog's text sink. Nothing here 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. Plain klog.SetLogger, deliberately not SetLoggerWithOptions with ContextualLogger(true). The contextual form is what klog's docs recommend because it skips a klogr round trip, but it also disables klog's verbosity gate and hands the decision to zap, whose level under Development is Debug -- so 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. Same fix to the format, no new volume, which matters because volume is what prompted this. 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 already uses for the same purpose. The deployment gets --zap-encoder=json and --zap-time-encoding=rfc3339. The flag beats the in-code Development default -- addDefaults fills NewEncoder only when it is nil -- and the time encoding is not optional, since the JSON encoder defaults to epoch seconds. Verbosity stays at debug on purpose; --zap-log-level=info drops the per-RPC lines. zap.Options{Development: true} stays as the in-code default: flipping it would change the format for every deployment of this operator, and the flags get the same result here without that reach. k8s.io/klog/v2 moves from indirect to direct in go.mod. It was already in the module graph, so nothing new is downloaded. No tests: three changes, all wiring, in a file with no test coverage, and pinning klog.SetLogger means mutating process-global state that leaks into every other test in the package. Verified in-cluster instead -- `kubectl logs | jq -e -s 'length > 0'` now passes, which fails if any single line is not JSON. Co-Authored-By: Claude Opus 5 (1M context) --- cmd/main.go | 11 ++- config/manager/manager.yaml | 7 ++ .../2026-09-17-1515-kvm2-review-fixes.md | 89 +++++++++++++++++++ go.mod | 2 +- internal/discovery/server.go | 7 +- 5 files changed, 113 insertions(+), 3 deletions(-) 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,