KEDA metrics api server not honoring log level #5139

mrparkers · 2023-10-30T16:13:27Z

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

Deploy keda metrics api server with -v=0.
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

The text was updated successfully, but these errors were encountered:

JorTurFer · 2023-10-31T11:55:00Z

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 · 2023-11-01T04:12:52Z

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 · 2023-11-01T15:01:53Z

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 · 2023-12-11T07:17:34Z

Any update on this?

dgrisonnet · 2023-12-11T09:10:36Z

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 · 2023-12-11T15:34:51Z

Awesome, thanks!

stale · 2024-02-10T06:21:47Z

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 · 2024-02-10T07:36:10Z

Still and issue. Thanks!

JorTurFer · 2024-02-10T10:01:16Z

ping @dgrisonnet !

dgrisonnet · 2024-02-13T14:53:22Z

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

stale · 2024-04-13T19:49:56Z

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 · 2024-04-14T08:22:45Z

keep-alive :)

stale · 2024-04-23T02:31:19Z

This issue has been automatically closed due to inactivity.

dgrisonnet · 2024-04-23T17:32:53Z

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

dberuben · 2024-06-19T08:24:28Z

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

Merged 👍

zroubalik · 2024-06-25T21:17:33Z

Anybody willing to test this out? :)

stale · 2024-08-27T18:45:48Z

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.

stale · 2024-09-05T03:13:09Z

This issue has been automatically closed due to inactivity.

mindw · 2024-09-24T06:58:33Z

Keda 2.15.1 - trace logs are present despite -v=0 -

+ kube-system keda-operator-metrics-apiserver-5d9f6b7b58-4mnct › keda-operator-metrics-apiserver
2024/09/24 06:46:08 maxprocs: Honoring GOMAXPROCS="1" as set in environment
I0924 06:46:08.343047       1 welcome.go:34] "msg"="Starting metrics server" "logger"="keda_metrics_adapter"
I0924 06:46:08.343066       1 welcome.go:35] "msg"="KEDA Version: 2.15.1" "logger"="keda_metrics_adapter"
I0924 06:46:08.343072       1 welcome.go:36] "msg"="Git Commit: 09a4951478746ba0d95521b786439e58aeda179b" "logger"="keda_metrics_adapter"
I0924 06:46:08.343080       1 welcome.go:37] "msg"="Go Version: go1.22.5" "logger"="keda_metrics_adapter"
I0924 06:46:08.343086       1 welcome.go:38] "msg"="Go OS/Arch: linux/amd64" "logger"="keda_metrics_adapter"
I0924 06:46:08.343112       1 welcome.go:39] "msg"="Running on Kubernetes 1.29+" "logger"="keda_metrics_adapter" "version"={"major":"1","minor":"29+","gitVersion":"v1.29.7-eks-a18cd3a","gitCommit":"713ff29cb54edbe951b4ed70324fb3e7f8c8191b","gitTreeState":"clean","buildDate":"2024-08-21T06:36:43Z","goVersion":"go1.22.5","compiler":"gc","platform":"linux/amd64"}
I0924 06:46:08.343475       1 main.go:112] "msg"="Connecting Metrics Service gRPC client to the server" "address"="keda-operator.kube-system.svc.cluster.local:9666" "logger"="keda_metrics_adapter"
I0924 06:46:08.348605       1 provider.go:56] "msg"="starting" "logger"="keda_metrics_adapter.provider"
I0924 06:46:08.348627       1 main.go:271] "msg"="starting adapter..." "logger"="keda_metrics_adapter"
I0924 06:46:08.355548       1 client.go:103] "msg"="Waiting for establishing a gRPC connection to KEDA Metrics Server" "logger"="keda_metrics_adapter.provider"
I0924 06:46:08.355596       1 main.go:187] "msg"="starting /metrics server endpoint" "logger"="keda_metrics_adapter"
I0924 06:46:08.769302       1 secure_serving.go:213] Serving securely on [::]:6443
I0924 06:46:08.769358       1 requestheader_controller.go:169] Starting RequestHeaderAuthRequestController
I0924 06:46:08.769366       1 shared_informer.go:311] Waiting for caches to sync for RequestHeaderAuthRequestController
I0924 06:46:08.769397       1 dynamic_serving_content.go:132] "Starting controller" name="serving-cert::/certs/tls.crt::/certs/tls.key"
I0924 06:46:08.769491       1 tlsconfig.go:240] "Starting DynamicServingCertificateController"
I0924 06:46:08.769585       1 dynamic_cafile_content.go:157] "Starting controller" name="client-ca-bundle::/certs/ca.crt"
I0924 06:46:08.769647       1 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"
I0924 06:46:08.769658       1 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
I0924 06:46:08.856572       1 provider.go:64] "msg"="Connection to KEDA Metrics Service gRPC server has been successfully established" "logger"="keda_metrics_adapter.provider" "server"="keda-operator.kube-system.svc.cluster.local:9666"
I0924 06:46:08.869757       1 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
I0924 06:46:08.869804       1 shared_informer.go:318] Caches are synced for RequestHeaderAuthRequestController
I0924 06:46:30.670958       1 client.go:103] "msg"="Waiting for establishing a gRPC connection to KEDA Metrics Server" "logger"="keda_metrics_adapter.provider"
W0924 06:46:30.671185       1 logging.go:55] [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "10.100.48.146:9666", ServerName: "keda-operator.kube-system.svc.cluster.local:9666", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.100.48.146:9666: connect: connection refused"
I0924 06:46:31.166616       1 client.go:103] "msg"="Waiting for establishing a gRPC connection to KEDA Metrics Server" "logger"="keda_metrics_adapter.provider"
I0924 06:46:31.215527       1 client.go:103] "msg"="Waiting for establishing a gRPC connection to KEDA Metrics Server" "logger"="keda_metrics_adapter.provider"
I0924 06:46:31.655558       1 client.go:103] "msg"="Waiting for establishing a gRPC connection to KEDA Metrics Server" "logger"="keda_metrics_adapter.provider"
W0924 06:46:31.672016       1 logging.go:55] [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "10.100.48.146:9666", ServerName: "keda-operator.kube-system.svc.cluster.local:9666", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.100.48.146:9666: connect: connection refused"
I0924 06:46:32.286862       1 client.go:103] "msg"="Waiting for establishing a gRPC connection to KEDA Metrics Server" "logger"="keda_metrics_adapter.provider"
W0924 06:46:33.251476       1 logging.go:55] [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "10.100.48.146:9666", ServerName: "keda-operator.kube-system.svc.cluster.local:9666", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.100.48.146:9666: connect: connection refused"
W0924 06:46:35.956541       1 logging.go:55] [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "10.100.48.146:9666", ServerName: "keda-operator.kube-system.svc.cluster.local:9666", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.100.48.146:9666: connect: connection refused"
W0924 06:46:39.516207       1 logging.go:55] [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "10.100.48.146:9666", ServerName: "keda-operator.kube-system.svc.cluster.local:9666", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.100.48.146:9666: connect: connection refused"
W0924 06:46:46.811197       1 logging.go:55] [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "10.100.48.146:9666", ServerName: "keda-operator.kube-system.svc.cluster.local:9666", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 10.100.48.146:9666: connect: connection refused"
I0924 06:46:57.187632       1 trace.go:236] Trace[672416736]: "List" accept:application/vnd.kubernetes.protobuf, */*,audit-id:36b2ab81-fcf2-4098-a92b-16c1edbbc031,client:10.0.54.214,api-group:external.metrics.k8s.io,api-version:v1beta1,name:,subresource:,namespace:gabi,protocol:HTTP/2.0,resource:s0-metric-api-backend1-activesocketsinsandbox,scope:namespace,url:/apis/external.metrics.k8s.io/v1beta1/namespaces/gabi/s0-metric-api-backend1-activesocketsinsandbox,user-agent:kube-controller-manager/v1.29.7 (linux/amd64) kubernetes/713ff29/system:serviceaccount:kube-system:horizontal-pod-autoscaler,verb:LIST (24-Sep-2024 06:46:31.655) (total time: 25532ms):
Trace[672416736]: ---"Listing from storage done" 25531ms (06:46:57.187)
Trace[672416736]: [25.532094513s] [25.532094513s] END
I0924 06:46:57.193512       1 trace.go:236] Trace[660481778]: "List" accept:application/vnd.kubernetes.protobuf, */*,audit-id:195ae0b8-f976-4a3b-a5f9-c578a3d0aac2,client:10.0.54.214,api-group:external.metrics.k8s.io,api-version:v1beta1,name:,subresource:,namespace:gabi,protocol:HTTP/2.0,resource:s1-metric-api-backend1-activesocketsinsandbox,scope:namespace,url:/apis/external.metrics.k8s.io/v1beta1/namespaces/gabi/s1-metric-api-backend1-activesocketsinsandbox,user-agent:kube-controller-manager/v1.29.7 (linux/amd64) kubernetes/713ff29/system:serviceaccount:kube-system:horizontal-pod-autoscaler,verb:LIST (24-Sep-2024 06:46:31.166) (total time: 26026ms):
Trace[660481778]: ---"Listing from storage done" 26026ms (06:46:57.193)
Trace[660481778]: [26.0269198s] [26.0269198s] END
I0924 06:46:57.202703       1 trace.go:236] Trace[791548033]: "List" accept:application/vnd.kubernetes.protobuf, */*,audit-id:99f37c07-3d6b-43d5-833f-a318dbf4f7c7,client:10.0.54.214,api-group:external.metrics.k8s.io,api-version:v1beta1,name:,subresource:,namespace:gabi,protocol:HTTP/2.0,resource:s1-rabbitmq-gabi-realtime-engagement-tracking,scope:namespace,url:/apis/external.metrics.k8s.io/v1beta1/namespaces/gabi/s1-rabbitmq-gabi-realtime-engagement-tracking,user-agent:kube-controller-manager/v1.29.7 (linux/amd64) kubernetes/713ff29/system:serviceaccount:kube-system:horizontal-pod-autoscaler,verb:LIST (24-Sep-2024 06:46:30.670) (total time: 26531ms):
Trace[791548033]: ---"Listing from storage done" 26531ms (06:46:57.202)
Trace[791548033]: [26.531765776s] [26.531765776s] END
I0924 06:46:57.250168       1 trace.go:236] Trace[1306294443]: "List" accept:application/vnd.kubernetes.protobuf, */*,audit-id:777bd9a6-bd51-4f39-b8c0-6659411d53b8,client:10.0.54.214,api-group:external.metrics.k8s.io,api-version:v1beta1,name:,subresource:,namespace:gabi,protocol:HTTP/2.0,resource:s0-metric-api-data-insights-totalpoints,scope:namespace,url:/apis/external.metrics.k8s.io/v1beta1/namespaces/gabi/s0-metric-api-data-insights-totalpoints,user-agent:kube-controller-manager/v1.29.7 (linux/amd64) kubernetes/713ff29/system:serviceaccount:kube-system:horizontal-pod-autoscaler,verb:LIST (24-Sep-2024 06:46:31.215) (total time: 26034ms):
Trace[1306294443]: ---"Listing from storage done" 26034ms (06:46:57.250)
Trace[1306294443]: [26.034659059s] [26.034659059s] END
I0924 06:46:57.311050       1 trace.go:236] Trace[410244028]: "List" accept:application/vnd.kubernetes.protobuf, */*,audit-id:096d4398-0175-479a-a881-3d00d7931b03,client:10.0.54.214,api-group:external.metrics.k8s.io,api-version:v1beta1,name:,subresource:,namespace:munch,protocol:HTTP/2.0,resource:s0-redis-bull-munch-mm-video-transcoding-wait,scope:namespace,url:/apis/external.metrics.k8s.io/v1beta1/namespaces/munch/s0-redis-bull-munch-mm-video-transcoding-wait,user-agent:kube-controller-manager/v1.29.7 (linux/amd64) kubernetes/713ff29/system:serviceaccount:kube-system:horizontal-pod-autoscaler,verb:LIST (24-Sep-2024 06:46:32.286) (total time: 25024ms):
Trace[410244028]: ---"Listing from storage done" 25024ms (06:46:57.310)
Trace[410244028]: [25.024188636s] [25.024188636s] END

harelhadar · 2024-10-23T11:49:35Z

The bug appears in 2.15.1
kedacore/charts#696

mrparkers added the bug Something isn't working label Oct 30, 2023

stale bot added the stale All issues that are marked as stale due to inactivity label Feb 10, 2024

stale bot removed the stale All issues that are marked as stale due to inactivity label Feb 10, 2024

stale bot added the stale All issues that are marked as stale due to inactivity label Apr 13, 2024

stale bot closed this as completed Apr 23, 2024

zroubalik reopened this Apr 23, 2024

stale bot removed the stale All issues that are marked as stale due to inactivity label Apr 23, 2024

zroubalik mentioned this issue Apr 23, 2024

Metrics Server: klogr.New is deprecated use textlogger.NewLogger instead #5732

Closed

stale bot added the stale All issues that are marked as stale due to inactivity label Aug 27, 2024

stale bot closed this as completed Sep 5, 2024

harelhadar mentioned this issue Oct 23, 2024

stderrthreshold not honored by operator-metrics-apiserver kedacore/charts#696

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

KEDA metrics api server not honoring log level #5139

KEDA metrics api server not honoring log level #5139

mrparkers commented Oct 30, 2023 •

edited

Loading

JorTurFer commented Oct 31, 2023 •

edited

Loading

dgrisonnet commented Nov 1, 2023

zroubalik commented Nov 1, 2023

JorTurFer commented Dec 11, 2023

dgrisonnet commented Dec 11, 2023

zroubalik commented Dec 11, 2023

stale bot commented Feb 10, 2024

mindw commented Feb 10, 2024

JorTurFer commented Feb 10, 2024

dgrisonnet commented Feb 13, 2024

stale bot commented Apr 13, 2024

mindw commented Apr 14, 2024

stale bot commented Apr 23, 2024

dgrisonnet commented Apr 23, 2024

dberuben commented Jun 19, 2024

zroubalik commented Jun 25, 2024

stale bot commented Aug 27, 2024

stale bot commented Sep 5, 2024

mindw commented Sep 24, 2024

harelhadar commented Oct 23, 2024

KEDA metrics api server not honoring log level #5139

KEDA metrics api server not honoring log level #5139

Comments

mrparkers commented Oct 30, 2023 • edited Loading

Report

Expected Behavior

Actual Behavior

Steps to Reproduce the Problem

Logs from KEDA operator

KEDA Version

Kubernetes Version

Platform

Scaler Details

Anything else?

JorTurFer commented Oct 31, 2023 • edited Loading

dgrisonnet commented Nov 1, 2023

zroubalik commented Nov 1, 2023

JorTurFer commented Dec 11, 2023

dgrisonnet commented Dec 11, 2023

zroubalik commented Dec 11, 2023

stale bot commented Feb 10, 2024

mindw commented Feb 10, 2024

JorTurFer commented Feb 10, 2024

dgrisonnet commented Feb 13, 2024

stale bot commented Apr 13, 2024

mindw commented Apr 14, 2024

stale bot commented Apr 23, 2024

dgrisonnet commented Apr 23, 2024

dberuben commented Jun 19, 2024

zroubalik commented Jun 25, 2024

stale bot commented Aug 27, 2024

stale bot commented Sep 5, 2024

mindw commented Sep 24, 2024

harelhadar commented Oct 23, 2024

mrparkers commented Oct 30, 2023 •

edited

Loading

JorTurFer commented Oct 31, 2023 •

edited

Loading