[receiver/jmxreceiver] Duplicate metric definition warnings

[mwear]

Describe the bug
I configured the JMX receiver with kafka as the target system and I see warnings in the logs for duplicate metric definition. These appear to happen on each export. Here is a stacktrace:

2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287	Mar 08, 2022 7:41:31 PM io.opentelemetry.sdk.metrics.internal.state.MeterSharedState register	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287	WARNING: Found duplicate metric definition: kafka.request.queue	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287		at unknown source	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287			To enable better debugging, run your JVM with -Dotel.experimental.sdk.metrics.debug=true	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287	Causes	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287	- InstrumentType [OBSERVABLE_GAUGE] is async and already registered	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287	Original instrument registered with same name but is incompatible.	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287		at unknown source	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287			To enable better debugging, run your JVM with -Dotel.experimental.sdk.metrics.debug=true	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.964Z	debug	subprocess/subprocess.go:287	io.opentelemetry.sdk.metrics.internal.state.DuplicateMetricStorageException: Async metric with same name has already been created. Found previous metric: MetricDescriptor{name=kafka.request.queue, description=size of the request queue, unit={requests}, sourceView=Optional[View{name=null, description=null, aggregation=DefaultAggregation, attributesProcessor=io.opentelemetry.sdk.metrics.internal.view.AttributesProcessor$1@187ddfc, sourceInfo=INSTANCE}], sourceInstrument=InstrumentDescriptor{name=kafka.request.queue, description=size of the request queue, unit={requests}, type=OBSERVABLE_GAUGE, valueType=LONG, sourceInfo=INSTANCE}}, cannot register metric: MetricDescriptor{name=kafka.request.queue, description=size of the request queue, unit={requests}, sourceView=Optional[View{name=null, description=null, aggregation=DefaultAggregation, attributesProcessor=io.opentelemetry.sdk.metrics.internal.view.AttributesProcessor$1@187ddfc, sourceInfo=INSTANCE}], sourceInstrument=InstrumentDescriptor{name=kafka.request.queue, description=size of the request queue, unit={requests}, type=OBSERVABLE_GAUGE, valueType=LONG, sourceInfo=INSTANCE}}	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.sdk.metrics.internal.state.MetricStorageRegistry.register(MetricStorageRegistry.java:75)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.sdk.metrics.internal.state.MeterSharedState.register(MeterSharedState.java:139)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.Collections$2.tryAdvance(Collections.java:4863)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.Collections$2.forEachRemaining(Collections.java:4871)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.sdk.metrics.internal.state.MeterSharedState.registerLongAsynchronousInstrument(MeterSharedState.java:115)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.sdk.metrics.AbstractInstrumentBuilder.registerLongAsynchronousInstrument(AbstractInstrumentBuilder.java:82)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.sdk.metrics.SdkLongGaugeBuilder.buildWithCallback(SdkLongGaugeBuilder.java:37)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.GroovyMetricEnvironment.registerLongValueCallback(GroovyMetricEnvironment.java:255)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.GroovyMetricEnvironment$registerLongValueCallback$1.call(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.OtelHelper.longValueCallback(OtelHelper.groovy:257)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at java.base/java.lang.reflect.Method.invoke(Method.java:568)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:107)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.965Z	debug	subprocess/subprocess.go:287		at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1268)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at groovy.lang.MetaClassImpl.invokeMethodClosure(MetaClassImpl.java:1048)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1142)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1035)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at groovy.lang.Closure.call(Closure.java:412)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at jdk.internal.reflect.GeneratedMethodAccessor26.invoke(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at java.base/java.lang.reflect.Method.invoke(Method.java:568)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PlainObjectMetaMethodSite.doInvoke(PlainObjectMetaMethodSite.java:43)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSite.invoke(PogoMetaMethodSite.java:170)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.call(PogoMetaMethodSite.java:73)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:166)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.InstrumentHelper$_update_closure3.doCall(InstrumentHelper.groovy:125)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at jdk.internal.reflect.GeneratedMethodAccessor25.invoke(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at java.base/java.lang.reflect.Method.invoke(Method.java:568)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:107)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:263)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.966Z	debug	subprocess/subprocess.go:287		at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1035)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at groovy.lang.Closure.call(Closure.java:412)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.DefaultGroovyMethods.callClosureForMapEntry(DefaultGroovyMethods.java:6055)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:2408)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.dgm$203.invoke(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:247)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:56)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:139)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.InstrumentHelper.update(InstrumentHelper.groovy:115)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.InstrumentHelper$update.call(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.OtelHelper.instrument(OtelHelper.groovy:92)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.OtelHelper$instrument$1.callCurrent(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.OtelHelper.instrument(OtelHelper.groovy:97)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at jdk.internal.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at java.base/java.lang.reflect.Method.invoke(Method.java:568)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PlainObjectMetaMethodSite.doInvoke(PlainObjectMetaMethodSite.java:43)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSite.invoke(PogoMetaMethodSite.java:170)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:61)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.OtelHelper.instrument(OtelHelper.groovy:101)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.OtelHelper$instrument$0.call(Unknown Source)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at Script1.run(Script1.groovy:181)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.GroovyRunner.run(GroovyRunner.java:136)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at io.opentelemetry.contrib.jmxmetrics.JmxMetrics$1.run(JmxMetrics.java:46)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.967Z	debug	subprocess/subprocess.go:287		at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)	{"kind": "receiver", "name": "jmx"}
2022-03-08T19:41:31.968Z	debug	subprocess/subprocess.go:287		at java.base/java.lang.Thread.run(Thread.java:831)	{"kind": "receiver", "name": "jmx"}

Steps to reproduce
Setup the JMX exporter with target system of Kafka and observe the logs. I have an example of this already setup with docker compose. To run it do the following:

git clone [email protected]:mwear/otel-collector-examples.git
cd otel-collector-examples/jmx-receiver-kafka
docker-compose up

What did you expect to see?
I did not expect duplicate metrics to be registered.

What did you see instead?
Warnings of duplicate metric registration

What version did you use?

• Collector Contrib v0.45.0
• opentelemetry-jmx-metrics-1.11.0-alpha
• See my Dockerfile for exact details

What config did you use?

receivers:
  otlp:
    protocols:
      http:
      grpc:
  
  jmx:
    jar_path: /opt/opentelemetry-jmx-metrics.jar
    endpoint: kafka:1099
    target_system: kafka
    collection_interval: 10s
    
exporters:
  logging:

processors:
  batch:

service:
  pipelines:
    metrics:
      receivers: [otlp, jmx]
      processors: [batch]
      exporters: [logging]
  telemetry:
    logs:
      level: debug

Environment

• openjdk:17-alpine (docker base image)

[jpkrohling]

cc @rmfitzpatrick

[rmfitzpatrick]

@mwear thanks for the report and reproducing environment. I think this is likely a duplicate of open-telemetry/opentelemetry-java-contrib#222 and not an issue w/ the jmx receiver as a collector component. Issues w/ the jmx metric gatherer itself should be reported to the java contrib project.

[mwear]

Thanks for looking at this @rmfitzpatrick. I wasn't sure if the core issue was with the receiver or the metric gatherer. Since it appears to be the latter I'll go ahead and close this.