OLM seems to be only logging to stderr

[apeschel]

Bug Report

We're using Datadog for our logging system, and all of OLM's logging is showing up at the ERROR level. We reached out to Datadog and confirmed that the most likely situation where this would occur is if OLM is logging to STDERR instead of STDOUT. I have not been able to come up with a good way to check if this is the case or not though.

What did you do?

Standard install of OLM, no changes from default.

What did you expect to see?

Logging showing up as INFO

What did you see instead? Under which circumstances?

Logging showing up as ERROR

Environment

• operator-lifecycle-manager version:

v0.18.0

• Kubernetes version information:

Client Version: version.Info{Major:"1", Minor:"19", GitVersion:"v1.19.10", GitCommit:"98d5dc5d36d34a7ee13368a7893dcb400ec4e566", GitTreeState:"clean", BuildDate:"2021-04-15T03:28:42Z", GoVersion:"go1.15.10", Compiler:"gc", Platform:"darwin/amd64"}
Server Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.14", GitCommit:"4d62230f10af41cec2851b5b113874f6d2098297", GitTreeState:"clean", BuildDate:"2021-03-22T23:01:55Z", GoVersion:"go1.13.15", Compiler:"gc", Platform:"linux/amd64"}

• Kubernetes cluster kind:

AKS w/ VMSS

Possible Solution

OLM should log errors to STDERR, and everything else to STDOUT.

Additional context

It also seems like debug logging may be enabled for the packageserver deployment, it's extremely noisy and the logs don't seem particularly useful unless you're an OLM developer.

[benluddy]

Thanks for taking the time to report this. I poked around and it seems that klog writes to stderr by default (https://github.com/kubernetes/klog/blob/v1.0.0/klog.go#L38-L39), and the packageserver deployment sets -v=4 (https://github.com/operator-framework/operator-lifecycle-manager/blob/master/deploy/upstream/manifests/0.18.1/0000_50_olm_15-packageserver.clusterserviceversion.yaml#L92). Both seem like oversights to me.

[exdx]

This seems like a straightforward issue, but we need to check to see if there is any reason for the log settings to be as they are now. Also, presumably anything that uses klog would run into this issue, so it's not entirely clear if this is a bug per se.

Would you be able to modify klog flags to get the desired logging behavior that datadog expects?

[apeschel]

@exdx I couldn't figure out how to modify the klog settings, so ended up setting up a log filter on the Datadog side. klog puts the log level in the log as well, so I could parse on that.

[Shivkumar13]

/assign

[pierluigilenoci]

I've opened a PR to fix this: #3801

The PR migrates from k8s.io/klog v1 to k8s.io/klog/v2 v2.140.0 and opts into the new klog behavior where -stderrthreshold is actually honored even when -logtostderr=true. This was a long-standing klog bug (kubernetes/klog#212) fixed in kubernetes/klog#432.

With this change, operators can set -stderrthreshold=WARNING or -stderrthreshold=ERROR to only send higher-severity messages to stderr, which allows log aggregation systems (DataDog, CloudWatch, GCP Cloud Logging) to correctly classify log severity instead of treating everything as ERROR.