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) <noreply@anthropic.com>
This commit is contained in:
2026-09-17 20:24:37 +00:00
co-authored by Claude Opus 5
parent 82d01efb96
commit 4114d43e87
5 changed files with 113 additions and 3 deletions
+10 -1
View File
@@ -38,6 +38,7 @@ import (
"k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/runtime"
utilruntime "k8s.io/apimachinery/pkg/util/runtime" utilruntime "k8s.io/apimachinery/pkg/util/runtime"
clientgoscheme "k8s.io/client-go/kubernetes/scheme" clientgoscheme "k8s.io/client-go/kubernetes/scheme"
"k8s.io/klog/v2"
ctrl "sigs.k8s.io/controller-runtime" ctrl "sigs.k8s.io/controller-runtime"
"sigs.k8s.io/controller-runtime/pkg/cache" "sigs.k8s.io/controller-runtime/pkg/cache"
"sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/client"
@@ -162,7 +163,15 @@ func main() {
os.Exit(0) 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", setupLog.Info("Starting egress-proxies-operator",
"commit", version.Resolve(), "goVersion", goruntime.Version()) "commit", version.Resolve(), "goVersion", goruntime.Version())
+7
View File
@@ -64,6 +64,13 @@ spec:
- --leader-elect - --leader-elect
- --health-probe-bind-address=:8081 - --health-probe-bind-address=:8081
- --providers-config=/etc/proxy-operator/providers.yaml - --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 # Add --trace-health-probes to emit one span per health probe
# (high volume: ~1/s per proxy). # (high volume: ~1/s per proxy).
# Provider health checks (kubectl get providerhealth) run every # Provider health checks (kubectl get providerhealth) run every
@@ -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 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 - [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 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 checklist line here when it is planned, so this list stays a record of decided work rather
than a wish. 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 **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. 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. 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.
+1 -1
View File
@@ -23,6 +23,7 @@ require (
k8s.io/api v0.36.0 k8s.io/api v0.36.0
k8s.io/apimachinery v0.36.0 k8s.io/apimachinery v0.36.0
k8s.io/client-go 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/controller-runtime v0.24.1
sigs.k8s.io/yaml v1.6.0 sigs.k8s.io/yaml v1.6.0
) )
@@ -104,7 +105,6 @@ require (
k8s.io/apiextensions-apiserver v0.36.0 // indirect k8s.io/apiextensions-apiserver v0.36.0 // indirect
k8s.io/apiserver v0.36.0 // indirect k8s.io/apiserver v0.36.0 // indirect
k8s.io/component-base 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/kube-openapi v0.0.0-20260317180543-43fb72c5454a // indirect
k8s.io/streaming v0.36.0 // indirect k8s.io/streaming v0.36.0 // indirect
k8s.io/utils v0.0.0-20260210185600-b8788abfbbc2 // indirect k8s.io/utils v0.0.0-20260210185600-b8788abfbbc2 // indirect
+6 -1
View File
@@ -9,6 +9,7 @@ import (
"context" "context"
"crypto/subtle" "crypto/subtle"
"encoding/json" "encoding/json"
"log/slog"
"net" "net"
"net/http" "net/http"
"strings" "strings"
@@ -111,7 +112,11 @@ func (s *Server) Start(ctx context.Context) error {
s.mu.Unlock() s.mu.Unlock()
srv := &http.Server{ 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, ReadHeaderTimeout: readHeadTimeout,
ReadTimeout: 10 * time.Second, ReadTimeout: 10 * time.Second,
WriteTimeout: 10 * time.Second, WriteTimeout: 10 * time.Second,