search

open-telemetry / opentelemetry-collector-contrib

Contrib repository for the OpenTelemetry Collector
https://opentelemetry.io
Apache License 2.0
3.01k stars 2.32k forks source link

[receiver/jmxreceiver] Duplicate metric definition warnings #8347

Closed mwear closed 2 years ago

mwear commented 2 years ago

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 git@github.com: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?

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

jpkrohling commented 2 years ago

cc @rmfitzpatrick

rmfitzpatrick commented 2 years ago

@mwear thanks for the report and reproducing environment. I think this is likely a duplicate of https://github.com/open-telemetry/opentelemetry-java-contrib/issues/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 commented 2 years ago

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.