JMX gatherer logs warnings "Instrument ... has recorded multiple values for the same attributes"

[sirianni]

Component(s)

jmx-metrics

What happened?

Description

Using JMX Gatherer otel.mbeans to match a collection of MBeans consistently emits the warning Instrument ...has recorded multiple values for the same attributes

Steps to Reproduce

Run jmx-gatherer with the following configuration:

otel.jmx.service.url=service:jmx:rmi:///jndi/rmi://:7203/jmxrmi
otel.jmx.groovy.script=./script.groovy
otel.jmx.interval.milliseconds=5000

def garbageCollector = otel.mbeans("java.lang:type=GarbageCollector,*")
otel.instrument(garbageCollector, "jvm.gc.collections.count", "total number of collections that have occurred",
        "1", ["name" : { mbean -> mbean.name().getKeyProperty("name") }],
        "CollectionCount", otel.&longCounterCallback)

(Groovy script snippet copied from jvm metrics)

Expected Result

I expected no warnings to be logged

Actual Result

I got warning messages WARNING: Instrument jvm.gc.collections.count has recorded multiple values for the same attributes.

Jun 27, 2023 8:03:23 PM io.opentelemetry.sdk.internal.ThrottlingLogger doLog
WARNING: Instrument jvm.gc.collections.count has recorded multiple values for the same attributes.
Jun 27, 2023 8:03:23 PM io.opentelemetry.exporter.logging.LoggingMetricExporter export
INFO: Received a collection of 2 metrics for export.
Jun 27, 2023 8:03:23 PM io.opentelemetry.exporter.logging.LoggingMetricExporter export
INFO: metric: ImmutableMetricData{resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.20.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.27.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.sdk.logs, version=null, schemaUrl=null, attributes={}}, name=queueSize, description=The number of logs queued, unit=1, type=LONG_GAUGE, data=ImmutableGaugeData{points=[ImmutableLongPointData{startEpochNanos=1687896193925000000, epochNanos=1687896203931000000, attributes={logRecordProcessorType="BatchLogRecordProcessor"}, value=0, exemplars=[]}]}}
Jun 27, 2023 8:03:23 PM io.opentelemetry.exporter.logging.LoggingMetricExporter export
INFO: metric: ImmutableMetricData{resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.20.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.27.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.opentelemetry.contrib.jmxmetrics, version=1.27.0-alpha, schemaUrl=null, attributes={}}, name=jvm.gc.collections.count, description=total number of collections that have occurred, unit=1, type=LONG_SUM, data=ImmutableSumData{points=[ImmutableLongPointData{startEpochNanos=1687896193925000000, epochNanos=1687896203931000000, attributes={name="G1 Old Generation"}, value=0, exemplars=[]}, ImmutableLongPointData{startEpochNanos=1687896193925000000, epochNanos=1687896203931000000, attributes={name="G1 Young Generation"}, value=1, exemplars=[]}], monotonic=true, aggregationTemporality=CUMULATIVE}}

Component version

1.27.0-alpha

Log output

No response

Additional context

No response

[trask]

cc: jmx-metrics component owners @breedx-splk @Mrod1598 @rmfitzpatrick @dehaansa

[breedx-splk]

I was able to repeat the test and verify the behavior (warning is emitted).

[rmfitzpatrick]

https://github.com/open-telemetry/opentelemetry-java-contrib/pull/253 was opened to resolve this issue but there was pushback to the workaround and I wasn't able to track down the issue in how we interact w/ the sdk (or if it was in sdk itself). cc @aunshc for prioritization.

[jack-berg]

253 was about duplicate instrument registration. This is about one (or more) callbacks for an instrument recording values for the same set of attributes, which is indeed an error that the SDK should warn about.

[sirianni]

Is the issue that the name tag on the MBean may not be unique?

["name" : { mbean -> mbean.name().getKeyProperty("name") }],

?

[dehaansa]

@sirianni the issue is that the existing code will register a new callback each time metrics are collected, which each attempts to record the metric value collected when that callback was registered. I believe i've resolved this (and several other issues) in https://github.com/open-telemetry/opentelemetry-java-contrib/pull/949

[dehaansa]

949 was merged and should be available in 1.29.0. Let us know if the issue persists after integrating the next release.