search

kubernetes-sigs / controller-runtime

Repo for the controller-runtime subproject of kubebuilder (sig-apimachinery)
Apache License 2.0
2.43k stars 1.12k forks source link

Controller Runtime Outputs `klog` in non-standard format #2656

Open jonathan-innis opened 7 months ago

jonathan-innis commented 7 months ago

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 commented 7 months ago

/kind support

troy0820 commented 7 months ago

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 commented 7 months ago

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 commented 7 months ago

Sounds like something that should be fixed

jonathan-innis commented 7 months ago

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 commented 7 months ago

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:

k8s-triage-robot commented 4 months ago

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

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

You can:

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

/lifecycle stale

k8s-triage-robot commented 3 months ago

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:

You can:

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

/lifecycle rotten

jonathan-innis commented 3 months ago

/remove-lifecycle rotten

algo7 commented 1 month ago

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 commented 1 month ago

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.