controller-runtime Controller Runtime Outputs `klog` in non-standard format

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?

Jan 22 '24 02:01 jonathan-innis

/kind support

Jan 22 '24 14:01 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.

Jan 22 '24 16:01 troy0820

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.

Jan 23 '24 05:01 jonathan-innis

Sounds like something that should be fixed

Jan 26 '24 07:01 sbueringer

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?

Feb 01 '24 06:02 jonathan-innis

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: https://github.com/kubernetes/enhancements/issues/3077

Feb 07 '24 15:02 sbueringer

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

May 07 '24 15:05 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

Jun 06 '24 16:06 k8s-triage-robot

/remove-lifecycle rotten

Jun 06 '24 17:06 jonathan-innis

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.

Jul 30 '24 21:07 algo7

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.

Aug 05 '24 16:08 sbueringer

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

Nov 03 '24 16:11 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

Dec 03 '24 17:12 k8s-triage-robot

/remove-lifecycle rotten

Dec 04 '24 05:12 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.

Dec 04 '24 05:12 jonathan-innis

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

Mar 04 '25 05:03 k8s-triage-robot

/remove-lifecycle stale

Mar 07 '25 19:03 jonathan-innis

I think this requires the same work in upstream as what helped to fix: https://github.com/kubernetes-sigs/controller-runtime/issues/2987

The upstream package has to be migrated to use contextual logging (xref: https://github.com/kubernetes/kubernetes/issues/126379)

@pohly I know k8s.io/client-go/tools/leaderelection is not the most important package, but do you know if it's already tracked somewhere that it should be migrated to use contextual logging?

(once that work is done in upstream, we can make sure that controller-runtime passes in a context with a logger in the right place)

Mar 08 '25 12:03 sbueringer

tools/leaderelection is covered by https://github.com/kubernetes/kubernetes/pull/129331. Should better be in a separate PR... that it is in "portforward + apiserver proxy" is a mistake.

If you are interested in moving this forward, then please help review: https://github.com/kubernetes/kubernetes/pulls?q=is%3Aopen+is%3Apr+author%3Apohly+label%3Awg%2Fstructured-logging

Mar 08 '25 19:03 pohly

/help

If folks have time/interest, please help move the k/k PRs forward (https://github.com/kubernetes-sigs/controller-runtime/issues/2656#issuecomment-2708465631)

Mar 17 '25 17:03 sbueringer

@sbueringer: This request has been marked as needing help from a contributor.

Guidelines

Please ensure that the issue body includes answers to the following questions:

Why are we solving this issue?
To address this issue, are there any code changes? If there are code changes, what needs to be done in the code and what places can the assignee treat as reference points?
Does this issue have zero to low barrier of entry?
How can the assignee reach out to you for help?

For more details on the requirements of such an issue, please see here and ensure that they are met.

If this request no longer meets these requirements, the label can be removed by commenting with the /remove-help command.

In response to this:

/help

If folks have time/interest, please help move the k/k PRs forward (https://github.com/kubernetes-sigs/controller-runtime/issues/2656#issuecomment-2708465631)

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

Mar 17 '25 17:03 k8s-ci-robot