Controller Runtime Outputs klog in non-standard format

[jonathan-innis]

We are leveraging controller-runtime default logging to write our reconcilers; however, oddly, the leader election logs do not get output in the same format as our other logs. Our other logs use structured logging through zap, but without a call to klog.SetLogger() we don't get the same formatting for leader election logs. I would have anticipated that controller runtime could do something in the startup log configuration (similar to the rest.SetDefaultWarningHandler call that is made)

I0122 01:02:10.748462       1 leaderelection.go:250] attempting to acquire leader lease karpenter/karpenter...
I0122 01:02:15.176668       1 leaderelection.go:260] successfully acquired lease karpenter/karpenter

Considering how common leader election is, am I just missing some easy configuration knob in controller-runtime or do we just need to add a feature to support this out-of-the-box?

[troy0820]

/kind support

[troy0820]

This issue explains why this is happening. I believe if you are not setting the log.SetLogger() you will not have those logs displayed.

In the release below, it explains why this was done, with this PR being the commit where it landed.

https://github.com/kubernetes-sigs/controller-runtime/releases/tag/v0.15.0

Are you trying not to set this or are you setting this in main with log.SetLogger(logr) and the leader-election logging in not being structured. I'm trying to understand the issue you are having.

[jonathan-innis]

Are you trying not to set this or are you setting this in main with log.SetLogger(logr) and the leader-election logging in not being structured. I'm trying to understand the issue you are having

It's the second one. We are calling log.SetLogger() but still getting non-structured logs.

[sbueringer]

Sounds like something that should be fixed

[jonathan-innis]

I'm a tad skeptical that we can "just fix" this in controller-runtime itself. Calls to klog are global and I don't think controller-runtime can assume that it is the sole one that is controlling the logger in the binary. It seems like there may be no way for a library to just enable this. Maybe the best solve here is for kubebuilder to bootstrap a main.go file that configures this out-of-the-box?

[sbueringer]

Interesting. We get a different behavior in Cluster API. We are using component-base/logs to setup our logger: https://github.com/kubernetes-sigs/cluster-api/blob/edc8348877aa08f15de24564f0f1dd121b408f5b/main.go#L239-L245

IIRC, under the hood this uses zap for JSON logging and klog directly (?) for normal text logging.

Resulting logs look like this: https://storage.googleapis.com/kubernetes-jenkins/logs/periodic-cluster-api-e2e-main/1755221027673083904/artifacts/clusters/bootstrap/logs/capi-system/capi-controller-manager/capi-controller-manager-55c7446fcb-dzrcx/manager.log

{"ts":1707312800496.392,"caller":"leaderelection/leaderelection.go:250","msg":"attempting to acquire leader lease capi-system/controller-leader-election-capi...","v":0}

Just for context for other readers. These are the "offending" calls: https://github.com/kubernetes/client-go/blob/master/tools/leaderelection/leaderelection.go#L245-L264
e.g.

klog.Infof("attempting to acquire leader lease %v...", desc)

I assume component-base/logs sets up this stuff in a way that klog "forwards" to zap when JSON logging is configured.

I see two possible options:

• Setting up the logger with component-base/logs or in a similar way which achieves the same
• Implement contextual logging in the leaderelection package
  • I"m not sure if this is something that is already planned in the context of: contextual logging kubernetes/enhancements#3077

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle stale
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle rotten
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

[jonathan-innis]

/remove-lifecycle rotten

[algo7]

A temporary workaround would be importing "k8s.io/klog/v2" and manually setting

klog.SetLogger(<your_logger_implementation>)

It is kind of annoying that that a line of unstructured log just shows up while everything else are nicely formatted.

[sbueringer]

I think the best way to address this issue is to engage with upstream folks maintaining this package. Controller-runtime won't fork the package just to get rid of the log.

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle stale
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle rotten
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

[jonathan-innis]

/remove-lifecycle rotten

[jonathan-innis]

It is kind of annoying that that a line of unstructured log just shows up while everything else are nicely formatted

We do end up doing this (https://github.com/kubernetes-sigs/karpenter/blob/main/pkg/operator/operator.go#L122) -- it would just be nice if we didn't have to :) Agreed that working with changing the actual leader election client is probably the way though.