KEDA metrics api server not honoring log level

[mrparkers]

Report

Exact same issue as #3053 and #2316. Trace logs appear in stdout despite running the pod with -v=0.

The trace logs look like this:

I1030 16:06:17.184854       1 trace.go:236] Trace[1893921442]: "List" accept:application/vnd.kubernetes.protobuf, */*,audit-id:7da6ab1a-9d01-4c75-b3fc-11fcbee2f159,client:172.16.123.93,protocol:HTTP/2.0,resource:foo-303xx1-5-3022xx1-5,scope:namespace,url:/apis/external.metrics.k8s.io/v1beta1/namespaces/bar/foo-303xx1-5-3022xx1-5,user-agent:kube-controller-manager/v1.27.6 (linux/amd64) kubernetes/b6911bf/system:serviceaccount:kube-system:horizontal-pod-autoscaler,verb:LIST (30-Oct-2023 16:06:16.651) (total time: 533ms):
Trace[1893921442]: ---"Listing from storage done" 533ms (16:06:17.184)
Trace[1893921442]: [533.696851ms] [533.696851ms] END

Expected Behavior

Trace logs should not show up when -v=0.

Actual Behavior

Trace logs show up when -v=0.

Steps to Reproduce the Problem

1. Deploy keda metrics api server with -v=0.
2. Observe the trace logs in stdout

Logs from KEDA operator

not relevant

KEDA Version

2.12.0

Kubernetes Version

1.27

Platform

Amazon Web Services

Scaler Details

not relevant

Anything else?

No response

[JorTurFer]

You're right,
I can reproduce it. At this moment I have commented this with @dgrisonnet and he will take a look as the code is part of https://github.com/kubernetes-sigs/custom-metrics-apiserver and it uses https://github.com/kubernetes/utils/blob/master/trace/README.md, which looks that doesn't allow ignoring the trace.

We will update this when we have more info

[dgrisonnet]

Looking at the code from the Kubernetes library this seems to be expected: https://github.com/kubernetes/utils/blob/3b25d923346b/trace/trace.go#L202-L204

The traces are expected to be written not matter what if the request takes longer than the provided 500 miliseconds threshold: https://github.com/kubernetes-sigs/custom-metrics-apiserver/blob/master/pkg/apiserver/endpoints/handlers/get.go#L129

That said I don't think these are critical enough to have with a log level of 0 and I think we should have it for level 4 and higher since it is debug information. We can add a piece of code to custom-metrics-apiserver to do that, but in the meantime I'll revive the discussion in kubernetes/kubernetes#115993

[zroubalik]

Looking at the code from the Kubernetes library this seems to be expected: https://github.com/kubernetes/utils/blob/3b25d923346b/trace/trace.go#L202-L204

The traces are expected to be written not matter what if the request takes longer than the provided 500 miliseconds threshold: https://github.com/kubernetes-sigs/custom-metrics-apiserver/blob/master/pkg/apiserver/endpoints/handlers/get.go#L129

That said I don't think these are critical enough to have with a log level of 0 and I think we should have it for level 4 and higher since it is debug information. We can add a piece of code to custom-metrics-apiserver to do that, but in the meantime I'll revive the discussion in kubernetes/kubernetes#115993

Agree with this approach, thanks @dgrisonnet

[JorTurFer]

Any update on this?

[dgrisonnet]

We had an agreement in kubernetes/kubernetes#115993 to make the traces log level 2. I will try to implement the fix this week.

[zroubalik]

Awesome, thanks!

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

[mindw]

Still and issue. Thanks!

[JorTurFer]

ping @dgrisonnet !

[dgrisonnet]

On it. Sorry I didn't follow-up on it after we wrapped up the discussion upstream.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 7 days if no further activity occurs. Thank you for your contributions.

[mindw]

keep-alive :)

[stale]

This issue has been automatically closed due to inactivity.

[dgrisonnet]

I lost track of this one, the PR has been up for a while, I'll try to ping some people on slack to have a look at it kubernetes/utils#301