csi-node can permanently lose ALL logs: controller-runtime's 30s null-logger fallback wins the race against SetLogger when startup stalls

[whg517]

Observed

On a kind cluster (secret-csi-driver:0.0.0-dev, controller-runtime v0.23.3), a running secret-operator-csi-node instance produced 13 lines of output in total — the warning below and its stack trace — and then nothing, ever, while actively serving volume mounts:

[controller-runtime] log.SetLogger(...) was never called; logs will not be displayed.
Detected at:
	>  sigs.k8s.io/controller-runtime/pkg/log.eventuallyFulfillRoot()
	>  	.../controller-runtime@v0.23.3/pkg/log/log.go:60
	>  sigs.k8s.io/controller-runtime/pkg/log.(*delegatingLogSink).WithName(...)
	>  github.com/go-logr/logr.Logger.WithName(...)
	>  sigs.k8s.io/controller-runtime/pkg/cache/internal.init()
	>  	.../controller-runtime@v0.23.3/pkg/cache/internal/informers.go:46

During the same window this instance was failing kerberos keytab NodePublishVolume calls; the only diagnostic anywhere was the kubelet event rpc error: code = Internal desc = exit status 1 — the driver had no logs to consult at exactly the moment logs were needed. The sibling csi-controller pod (same codebase, same image generation, same node) logged normally, which rules out a build/config difference.

Why this is NOT a missing SetLogger call

cmd/csiplugin/main.go:95 does call ctrl.SetLogger(zap.New(...)), and has since #258. The mechanism is a race:

1. controller-runtime's pkg/log starts a 30s clock at its own package init (rootLogCreated).
2. Any use of the delegating root logger ≥30s later, before SetLogger, triggers eventuallyFulfillRoot: it prints the warning and fulfills the root with NullLogSink.
3. The delegating sink can only be fulfilled once — the real SetLogger at main.go:95 then becomes a silent no-op. The process runs for its entire lifetime with every log discarded.

The stack shows the detection fired from cache/internal.init() — i.e. ≥30s elapsed between two package inits, before main() even started. On this machine the trigger was a host suspend / heavy-IO stall mid-startup (the same event storm that produced leader-election losses across the operator fleet, kubelet restart counts in the teens). Any >30s startup stall reproduces it: a suspended laptop node, a CPU/IO-starved node, cold image thaw. Reordering main() cannot fix it, because both the clock and the racing consumer live in the pre-main init phase.

Impact

• A node-plugin that hits one slow start loses all logs until the container is manually restarted, with only a one-shot stderr warning nobody is watching.
• The failure is invisible to probes: the driver keeps serving. You discover it exactly when a mount fails and you go looking for logs that do not exist. (This is how it was found — debugging kafka-operator kerberos e2e keytab mounts.)

Suggested fixes

1. Product-side hardening (this repo): construct the zap logger first thing and use it (or loggers derived from it) directly for all product/CSI logging, instead of deriving everything from ctrl.Log — product logs then survive even when the delegating root has been null-fulfilled. Framework-internal logs stay muted in the race, but the driver's own gRPC/mount logging (the part that matters for mount debugging) becomes immune. Applies to both cmd/main.go and cmd/csiplugin/main.go.
2. Error detail independent of logs: NodePublishVolume failures should wrap the underlying error into the returned gRPC status (exit status 1 → which command, what stderr), since kubelet events are the only channel guaranteed to survive this failure mode.
3. Optionally raise upstream (controller-runtime): once-only null fulfillment silently defeating a later, legitimate SetLogger is arguably a bug — a later SetLogger could be allowed to replace the null sink.

🤖 Generated with Claude Code