[Kafka instrumentation] "Instrument has recorded multiple values for the same attributes" with version 2.7.0

[gaeljw]

Describe the bug

When upgrading from opentelemetry-instrumentation-bom-alpha version 2.6.0 to 2.7.0, we encounter a lot of WARN messages like the following:

Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:619 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.fetch_throttle_time_avg has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:620 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.fetch_throttle_time_max has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:620 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.fetch_latency_avg has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:620 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.fetch_latency_max has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.fetch_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.fetch_rate has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.connection_close_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.connection_close_rate has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.connection_creation_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.connection_creation_rate has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.successful_authentication_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.successful_authentication_rate has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.successful_reauthentication_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:621 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.successful_reauthentication_rate has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:622 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.successful_authentication_no_reauth_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:622 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.failed_authentication_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:622 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.failed_authentication_rate has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:622 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.failed_reauthentication_total has recorded multiple values for the same attributes: {client-id="my_app_0"}
Sep 10 07:48:44 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:44:622 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Instrument kafka.consumer.failed_reauthentication_rate has recorded multiple values for the same attributes: {client-id="my_app_0"}

And at some point it even says:

Sep 10 07:48:50 srv-xx sh[66538]: [otel.javaagent 2024-09-10 07:48:50:819 +0000] [prometheus-http-1-1] WARN io.opentelemetry.sdk.metrics.internal.state.AsynchronousMetricStorage - Too many log messages detected. Will only log once per minute from now on.

Steps to reproduce

I don't have a reproduction repository for now but I may provide one later if needed.

On our side, this happens with an application that has a very basic Kafka consumer, automatic instrumentation using the java agent and the following OTEL config:

OTEL_SERVICE_NAME="my-app"
OTEL_METRICS_EXPORTER=prometheus
OTEL_EXPORTER_PROMETHEUS_PORT=19002
# Traces=disabled
OTEL_TRACES_EXPORTER=none
# Logs=disabled
OTEL_LOGS_EXPORTER=none

This happens with kafka-clients library 3.7.1 and 3.8.0 (we didn't test previous versions). Seems unrelated to the kafka client library.

Expected behavior

No such warnings.

Moreover these logs are sent to stdout (/var/log/messages in our case) for some reason instead of being sent to the logging library. I'm not sure if this is expected and/or related.

Actual behavior

Continuous warning logs.

Javaagent or library instrumentation version

2.7.0

Environment

JDK: 17.0.12
OS: Linux (AlmaLinux release 8.10)

Additional context

No response

[gaeljw]

this happens with an application that has a very basic Kafka consumer

Actually, our application has multiple consumers (to different topics/brokers). This may be related. Is there maybe a specific label that should be defined for each consumer, if so from what is it supposed to be derived?

[gaeljw]

From the changelog, the only thing that pops to my eyes that may be related is #11975 🤷

[laurit]

This happens when a metric with given name is reported multiple times with the same attributes. If you create multiple consumers/producers from the same configuration then they will end up reporting exactly the same metrics. Form the log you pasted they all have client-id="my_app_0" so you can't really tell which consumer instance reported the metrics. I guess you could see if you can make all consumers have an unique client id. If you are constantly creating new consumers you might consider whether you want these metrics at all.

Moreover these logs are sent to stdout (/var/log/messages in our case) for some reason instead of being sent to the logging library.

By default agent logs to stderr. For some applications it may be possible to redirect agent logs to application logging framework, see https://opentelemetry.io/docs/zero-code/java/agent/configuration/#java-agent-logging-output

[gaeljw]

Thanks @laurit .

I confirm that using different client ids does work.

I'm fine with that in my current use case. But on the other hand, I think it's a valid Kafka setup: you can have 2 consumers with the same client id (as part of the same client/application instance), each one subscribed to a different topic ; or even more valid: they can belong to 2 different consumer groups.

[Starefossen]

@laurit we are seeing this a lot with applications with more then one consumer, would you mind detailing how one can set a different client to suppress this error or how to turn of the metrics in question if we can not find a sufficient workaround?