Tracing custom-metrics-stackdriver-adapter trace logging enabled

[kallangerard]

It appears that in gcr.io/gke-release/custom-metrics-stackdriver-adapter:v0.14.2-gke.0, traces are enabled and logging to stdout.

We're using the manifests from this commit reference https://github.com/GoogleCloudPlatform/k8s-stackdriver/blob/303ec9ad1ca8d09e2ea93a7ff2ce3aea7a9f8a97/custom-metrics-stackdriver-adapter/deploy/production/adapter.yaml,

We end up with an enormous amount of logs like below:

I0205 06:40:24.007357       1 trace.go:205] Trace[1008513964]: "List" url:/apis/external.metrics.k8s.io/v1beta1/namespaces/default/pubsub.googleapis.com|subscription|num_undelivered_messages,user-agent:vpa-recommender/v0.0.0 (linux/amd64) kubernetes/$Format/metrics-horizontal-pod-autoscaler,audit-id:<REDACTED>,client:<REDACTED>,accept:application/vnd.kubernetes.protobuf, */*,protocol:HTTP/2.0 (05-Feb-2024 06:40:23.298) (total time: 709ms):
Trace[1008513964]: ---"Listing from storage done" 709ms (06:40:24.007)
Trace[1008513964]: [709.130634ms] [709.130634ms] END
I0205 06:40:26.383958       1 trace.go:205] Trace[15241325]: "List" url:/apis/external.metrics.k8s.io/v1beta1/namespaces/default/pubsub.googleapis.com|subscription|oldest_unacked_message_age,user-agent:vpa-recommender/v0.0.0 (linux/amd64) kubernetes/$Format/metrics-horizontal-pod-autoscaler,audit-id:<REDACTED>,client:<REDACTED>,accept:application/vnd.kubernetes.protobuf, */*,protocol:HTTP/2.0 (05-Feb-2024 06:40:25.687) (total time: 696ms):
Trace[15241325]: ---"Listing from storage done" 696ms (06:40:26.383)
Trace[15241325]: [696.636825ms] [696.636825ms] END

[CatherineF-dev]

qq: does this issue happen starting from v0.14.2-gke.0?

[supersam654]

I believe this has been going on for a while. We're on gcr.io/gke-release/custom-metrics-stackdriver-adapter:v0.12.2-gke.0 and I see this in our logs:

2024-03-14 08:23:25.409 EDT Trace[939984059]: [801.213144ms] [801.213144ms] END
2024-03-14 08:23:25.607 EDT Trace[911902081]: "SerializeObject" method:GET,url:/apis/custom.metrics.k8s.io/v1beta1,protocol:HTTP/2.0,mediaType:application/json,encoder:{"encoder":"{\"name\":\"json\",\"pretty\":\"false\",\"yaml\":\"false\"}","name":"versioning"} (14-Mar-2024 12:23:20.508) (total time: 5098ms):
2024-03-14 08:23:25.608 EDT Trace[911902081]: [5.098732769s] [5.098732769s] END

[CatherineF-dev]

Thanks for providing this information!

[CatherineF-dev]

/label custom-metrics-stackdriver-adapter

[CatherineF-dev]

btw, @supersam654 did you find high memory issue in v0.12.2-gke.0? If so, try v0.14.2-gke.0 which fixed OOM/high memory issue.

Release note is here https://github.com/GoogleCloudPlatform/k8s-stackdriver/releases/tag/cm-sd-adapter-v0.14.0

[CatherineF-dev]

These traces log are ignorable. Could you try increasing log level by

        - /adapter
        - --use-new-resource-model=false
        - --v=1

@kallangerard

Trace prints out because whatever action the trace is about takes longer than what the author expects. This is expected for metrics adapter because it fetches data from Cloud Monitoring.

[hermanbanken]

Since the last version (0.15) this now outputs:

unknown flag: --v

when trying to mute Trace output. I think something broke the klog flag parsing. Maybe the initialisation order is wrong?

Update: the logTrace in k8s-stackdriver/event-exporter/vendor/k8s.io/utils/trace/trace.go matches the trace output (Trace[\d+] and END) perfectly. The issue seems to be that commit f3a96b5ed2c4dd345390001cee3500f4cca3c41c updated to klog v2, which no longer uses init() to register the flags:

# How to use klog
1. Replace imports for "github.com/golang/glog" with "k8s.io/klog/v2"
2. Use klog.InitFlags(nil) explicitly for initializing global flags as we no longer use init() method to register the flags

[hermanbanken]

Our main problem with this is that the latter go (logs starting with "Trace") end up in stderr, and are therefore classified as "Error" in GCP Cloud Logging, falsely triggering as a problem in our monitoring.