reduce log level in metrics logger not to trash the log

[nirrozenbaum]

metrics logger is trashing the epp log. so instead of allowing a focused view of what changed, the epp log looks like this:

{"level":"Level(-3)","ts":"2025-04-17T21:04:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:04:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:04:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"info","ts":"2025-04-17T21:05:10Z","caller":"runnable/grpc.go:19","msg":"gRPC server starting","name":"ext-proc"}
{"level":"info","ts":"2025-04-17T21:05:10Z","caller":"runnable/grpc.go:28","msg":"gRPC server listening","name":"ext-proc","port":9002}
{"level":"Level(-3)","ts":"2025-04-17T21:05:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:38Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:43Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:38Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:43Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:38Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:43Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}

since EPP default log level is 4, this PR reduces the log level of the metrics logger (only this specific message) to TRACE to reduce this noise in the log.

additionally, as a followup to previous PR, change in few more places to use NamespacedName instead of passing around name + namespace as separate args.

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: nirrozenbaum
Once this PR has been reviewed and has the lgtm label, please assign ahg-g for approval. For more information see the Code Review Process.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

• OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[nirrozenbaum]

cc @kfswain

[netlify]

✅ Deploy Preview for gateway-api-inference-extension ready!

Name	Link
🔨 Latest commit	c9a456f
🔍 Latest deploy log	https://app.netlify.com/sites/gateway-api-inference-extension/deploys/6803d7f5dcb8890008b69079
😎 Deploy Preview	https://deploy-preview-708--gateway-api-inference-extension.netlify.app
📱 Preview on mobile	Toggle QR Code... Use your smartphone camera to open QR code link.

---

To edit notification comments on pull requests, go to your Netlify site configuration.

[danehans]

+1 on changing the log level to DEBUG. Additionally, pool in the following log message should be capitalized:

logger.V(logutil.DEFAULT).Info("pool is not initialized, skipping flushing metrics")

In reviewing flushPrometheusMetricsOnce(), the Pod metrics are not being "flushed" but are instead being "Regenerated", "Recalculated", etc. We should consider renaming the function and the associated log message.

[nirrozenbaum]

+1 on changing the log level to DEBUG. Additionally, pool in the following log message should be capitalized:

logger.V(logutil.DEFAULT).Info("pool is not initialized, skipping flushing metrics")

In reviewing flushPrometheusMetricsOnce(), the Pod metrics are not being "flushed" but are instead being "Regenerated", "Recalculated", etc. We should consider renaming the function and the associated log message.

@danehans updated the log level and capitalized log message.
as for the function name, I updated it to refreshPrometheusMetrics to stay aligned with the terminology used in the code (the cmd-ling flag is called refreshPrometheusMetricsInterval, the function arg is called refreshPrometheusMetricsInterval, default value is defined in runserver.DefaultRefreshPrometheusMetricsInterval, etc)

[ahg-g]

Is there an alternative log in verbose or default level that logs the number of ready pods when they change?

[nirrozenbaum]

I haven't seen any other place logging the ready pods (it's reported as a metric though).
I completely agree this is information we would like to know.

having said that, I don't think it belongs here.
the refreshMetrics function runs every few seconds to update metrics, which makes perfect sense since we would like to update metrics very frequently.
BUT, printing to the EPP log the number of ready pods every 5 seconds is spamming the log and making it very hard to debug (see example above).

IMO the number of pods in the pool shouldn't be printed as part of metrics recalculation function, it should be part of the Inf Pool status (kinda similar to ready pods status in deployment).
we could easily add this field to Inf Pool status + additional printer columns to show it when running kubectl get InferencePool. it's pretty easy to implement in the controllers reconcile event which also updates only when something changes (as opposed to this log printing, which happens every 5 seconds even if nothing has changed).
If this sounds reasonable I'm happy to implement it this week.

@ahg-g cc @kfswain

[nirrozenbaum]

proposed this change in #714