diff --git a/docs/plans/2026-09-17-1515-kvm2-review-fixes.md b/docs/plans/2026-09-17-1515-kvm2-review-fixes.md index 70c94f6..b8db5e1 100644 --- a/docs/plans/2026-09-17-1515-kvm2-review-fixes.md +++ b/docs/plans/2026-09-17-1515-kvm2-review-fixes.md @@ -21,7 +21,8 @@ Precedent for this shape: `docs/plans/2026-09-10-2222-kvm-review-fixes.md`. - [ ] **Step 3** — H3: `address()` swallows every error and demotes healthy proxies. - [ ] **Step 4** — H4: the base image cache is shared across provider entries. - [ ] **Step 5** — Validate H1-H4 in-cluster against the real hypervisor (detailed below). -- [ ] **Step 6+** — the mediums, from `review/REPORT.md`. Detailed when reached. +- [ ] **Step 6** — Route klog into the structured logger (found during Step 5; detailed below). +- [ ] **Step 7+** — the mediums, from `review/REPORT.md`. Detailed when reached. --- @@ -478,6 +479,124 @@ pre-existing orphan volumes the review found. --- +## Step 6 — Route klog into the structured logger + +**Not a review finding.** Found while watching the Step 5 validation: some lines ignore the +zap encoder entirely, so no amount of `--zap-encoder=json` makes the stream parseable. + +``` +I0917 19:50:02.580097 1 leaderelection.go:258] "Attempting to acquire leader lease..." lock="..." +``` + +That is klog's own text sink. client-go's leader elector does `logger := klog.FromContext(ctx)` +(`leaderelection.go:257`), and controller-runtime hands the elector a context with no logr in it +(`pkg/manager/internal.go:461-473` — `mgr.Start` gets `ctrl.SetupSignalHandler()`, which carries +no logger). `klog.FromContext` falls back to `Background()`, and with no logger registered that +is klog's stderr writer. Nothing in this repo imports or configures klog; it is an indirect +dependency (`k8s.io/klog/v2 v2.140.0`) that ~60 linked packages use, including +`client-go/tools/{leaderelection,cache,record}`, `client-go/transport` and `client-go/rest`. +controller-runtime does not route it either — its only `klog.SetLogger` call is in its own test +suite. + +### 6a. `cmd/main.go` — one line and an import + +```go +logger := zap.New(zap.UseFlagOptions(&opts)) +ctrl.SetLogger(logger) +klog.SetLogger(logger) +``` + +**Plain `SetLogger`, deliberately not `SetLoggerWithOptions(logger, klog.ContextualLogger(true))`.** +The contextual form is what klog's own docs recommend, because it skips a klogr round trip — but +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's level. With `Development: true` +that level is Debug, which enables V(1), so client-go's V(1) chatter that klog currently +suppresses at its default `-v=0` would start appearing. Plain `SetLogger` keeps klog's own check +in front ("klog will do its own verbosity checks before calling logger.V().Info", +`contextual.go:43-44`) and still redirects everything it does emit ("all log lines will be +suppressed from the regular output, and redirected to the logr implementation", `:47-48`). +Same fix, no new volume. Performance is irrelevant at this scale. + +`go.mod` promotes `k8s.io/klog/v2` from indirect to direct. It is already in the module graph, +so nothing new is downloaded. + +### 6b. `internal/discovery/server.go` — the other stderr bypass + +The discovery API's `http.Server` (`:113-119`) sets no `ErrorLog`, so `net/http`'s own errors — +`Accept` failures, handler panics that escape — go to `log.Default()` and out to stderr in +stdlib format. `s.log` is already in scope two lines above: + +```go +srv := &http.Server{ + Handler: s.handler(), + ErrorLog: slog.NewLogLogger(logr.ToSlogHandler(s.log), slog.LevelError), + ReadHeaderTimeout: readHeadTimeout, + ... +} +``` + +`logr.ToSlogHandler` is the pattern the repo already uses for the same purpose in +`internal/provider/gcp/wirelog.go:31-36`. This server is plain HTTP with no TLS, so `ErrorLog` +carries genuine faults rather than handshake noise from scanners — Error level is right. + +### 6c. `config/manager/manager.yaml` — make the deployed stream parseable + +```yaml +args: + - --leader-elect + - --health-probe-bind-address=:8081 + - --providers-config=/etc/proxy-operator/providers.yaml + - --zap-encoder=json + - --zap-time-encoding=rfc3339 +``` + +Verified that the flag wins over the in-code default: `addDefaults` only fills `NewEncoder` +`if o.NewEncoder == nil` (`zap.go:176-191`), and `BindFlags` sets it from `--zap-encoder`. +`--zap-time-encoding=rfc3339` matters because the JSON encoder defaults to `epoch`, which would +give `1758138422.31` instead of a timestamp anyone can read. Verbosity is left at debug, so the +per-RPC lines stay — that was the choice. + +### Deliberately not doing + +`opts := zap.Options{Development: true}` (`cmd/main.go:154-155`) stays. Flipping it to a +production default would change the format for every existing deployment, not just this one, and +the flags in 6c get the same result here without that blast radius. + +### What stays unformatted regardless, and why that is fine + +Flag-parse errors and `--version` (`cmd/main.go:160-163`) print before any logger exists, and +`utilruntime.Must` panics in `init()` run before `main`. controller-runtime's own metrics and +health servers also set no `ErrorLog` (`pkg/internal/httpserver/server.go:11-19`) and expose no +option to set one. All three are outside reach; none can fire during steady-state operation. + +### Tests + +None. All three changes are wiring: two struct fields and one manifest key. `cmd/main.go` has no +test coverage at all, and pinning `klog.SetLogger` hermetically means mutating global state that +would leak into every other test in the package. Verified by observation instead — see below. +Same call as H1's: a test that costs more than it protects does not earn its place. + +### Verification + +Rebuild, redeploy, and watch the rollout produce the line that started this: + +```bash +kubectl -n egress-proxies-operator-system logs deploy/egress-proxies-operator-controller-manager \ + | grep -i 'leader' | head -3 +``` + +It must be JSON with an rfc3339 `ts`, not `I0917 ...`. Then confirm the whole stream parses: + +```bash +kubectl -n egress-proxies-operator-system logs deploy/egress-proxies-operator-controller-manager \ + | jq -e -s 'length > 0' >/dev/null && echo "every line is JSON" +``` + +That second command is the real check — it fails if *any* line is not JSON, which is exactly the +property being fixed. + +--- + ## Ordering **H2 → H3 → H4**, three commits.