Open
Description
After upgrading our distro to the latest upstream version, one of our E2E tests suddenly started failing.
To me it looks like #7255 unfortunately introduced (or rather surfaced) a race-condition:
The agent uses the AutoConfiguredOpenTelemetrySdkBuilder directly to register the GlobalOpenTelemetry instance in OpenTelemetryInstaller. Therefore, it does not hold the mutex from GlobalOpenTelemetry while building the SDK.
In our E2E test we define a metrics-exporter with a very low export interval (e.g. 10ms). In this case it can happen that this exporter attempts to run before AutoConfiguredOpenTelemetrySdkBuilder has finished installing the GlobalOpenTelemetry instance. Due to #7255, this will result in the exporter calling GlobalOpenTelemetry.get(), effectively triggering a nested, wrong autoconfiguration.
I don't think this is a critical bug, because such low export intervals are likely to be used only in tests. Nonetheless I think we should fix the underlying issue. One approach would be to make AutoConfiguredOpenTelemetrySdkBuilder.build() hold the mutex from GlobalOpenTelemetry while building the SDK, if the builder was configured to install the SDK globally.
Error logs
2025-05-19 10:58:05,256 [main] INFO io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdkBuilder - Error encountered during autoconfiguration. Closing partially configured components.
2025-05-19 10:58:05,260 [PeriodicMetricReader-1] ERROR io.opentelemetry.exporter.internal.http.HttpExporter - Failed to export metrics. The request could not be executed. Full error message: executor rejected
java.io.InterruptedIOException: executor rejected
at okhttp3.internal.connection.RealCall$AsyncCall.executeOn(RealCall.kt:501) ~[agent.jar:1.4.2-SNAPSHOT]
at okhttp3.Dispatcher.promoteAndExecute(Dispatcher.kt:184) ~[agent.jar:1.4.2-SNAPSHOT]
at okhttp3.Dispatcher.enqueue$okhttp(Dispatcher.kt:125) ~[agent.jar:1.4.2-SNAPSHOT]
at okhttp3.internal.connection.RealCall.enqueue(RealCall.kt:164) ~[agent.jar:1.4.2-SNAPSHOT]
at io.opentelemetry.exporter.sender.okhttp.internal.OkHttpHttpSender.lambda$send$2(OkHttpHttpSender.java:139) ~[agent.jar:1.4.2-SNAPSHOT]
at io.opentelemetry.javaagent.shaded.io.opentelemetry.context.Context.lambda$wrap$1(Context.java:241) ~[?:1.4.2-SNAPSHOT]
at io.opentelemetry.javaagent.shaded.io.opentelemetry.api.internal.InstrumentationUtil.suppressInstrumentation(InstrumentationUtil.java:28) ~[?:1.4.2-SNAPSHOT]
at io.opentelemetry.exporter.sender.okhttp.internal.OkHttpHttpSender.send(OkHttpHttpSender.java:135) ~[agent.jar:1.4.2-SNAPSHOT]
at io.opentelemetry.exporter.internal.http.HttpExporter.export(HttpExporter.java:63) ~[agent.jar:1.4.2-SNAPSHOT]
at io.opentelemetry.exporter.internal.otlp.metrics.MetricReusableDataMarshaler.export(MetricReusableDataMarshaler.java:48) [agent.jar:1.4.2-SNAPSHOT]
at io.opentelemetry.exporter.otlp.http.metrics.OtlpHttpMetricExporter.export(OtlpHttpMetricExporter.java:113) [agent.jar:1.4.2-SNAPSHOT]
at co.elastic.otel.dynamicconfig.BlockableMetricExporter.export(BlockableMetricExporter.java:70) [agent.jar:1.4.2-SNAPSHOT]
at io.opentelemetry.sdk.metrics.export.PeriodicMetricReader$Scheduled.doRun(PeriodicMetricReader.java:167) [agent.jar:1.4.2-SNAPSHOT]
at io.opentelemetry.sdk.metrics.export.PeriodicMetricReader$Scheduled.run(PeriodicMetricReader.java:153) [agent.jar:1.4.2-SNAPSHOT]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.util.concurrent.RejectedExecutionException: Task okhttp3.internal.connection.RealCall$AsyncCall@2429452d rejected from java.util.concurrent.ThreadPoolExecutor@3bfc0e36[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
at java.base/java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2065) ~[?:?]
at java.base/java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:833) ~[?:?]
at java.base/java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1365) ~[?:?]
at okhttp3.internal.connection.RealCall$AsyncCall.executeOn(RealCall.kt:498) ~[agent.jar:1.4.2-SNAPSHOT]
... 19 more
2025-05-19 10:58:05,268 [main] INFO io.opentelemetry.exporter.internal.http.HttpExporter - Calling shutdown() multiple times.
2025-05-19 10:58:05,269 [main] INFO io.opentelemetry.exporter.internal.http.HttpExporter - Calling shutdown() multiple times.
10:58:05.272 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: io.opentelemetry.sdk.autoconfigure.spi.ConfigurationException: Unexpected configuration error
10:58:05.272 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdkBuilder.build(AutoConfiguredOpenTelemetrySdkBuilder.java:489)
10:58:05.272 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller.installOpenTelemetrySdk(OpenTelemetryInstaller.java:29)
2025-05-19 10:58:05,270 [main] INFO io.opentelemetry.exporter.internal.http.HttpExporter - Calling shutdown() multiple times.
2025-05-19 10:58:05,271 [main] INFO io.opentelemetry.exporter.internal.http.HttpExporter - Calling shutdown() multiple times.
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.tooling.AgentInstaller.installBytebuddyAgent(AgentInstaller.java:160)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.tooling.AgentInstaller.installBytebuddyAgent(AgentInstaller.java:110)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.tooling.AgentStarterImpl.start(AgentStarterImpl.java:101)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.bootstrap.AgentInitializer$2.run(AgentInitializer.java:66)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.bootstrap.AgentInitializer$2.run(AgentInitializer.java:60)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.bootstrap.AgentInitializer.execute(AgentInitializer.java:82)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.bootstrap.AgentInitializer.initialize(AgentInitializer.java:59)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.OpenTelemetryAgent.startAgent(OpenTelemetryAgent.java:59)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.OpenTelemetryAgent.premain(OpenTelemetryAgent.java:46)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at co.elastic.otel.agent.ElasticAgent.premain(ElasticAgent.java:39)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/java.lang.reflect.Method.invoke(Method.java:569)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:491)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:503)
10:58:05.273 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: Caused by: java.lang.IllegalStateException: GlobalOpenTelemetry.set has already been called. GlobalOpenTelemetry.set must be called only once before any calls to GlobalOpenTelemetry.get. If you are using the OpenTelemetrySdk, use OpenTelemetrySdkBuilder.buildAndRegisterGlobal instead. Previous invocation set to cause of this exception.
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.shaded.io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:107)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdkBuilder.maybeSetAsGlobal(AutoConfiguredOpenTelemetrySdkBuilder.java:580)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdkBuilder.build(AutoConfiguredOpenTelemetrySdkBuilder.java:470)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: ... 17 more
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: Caused by: java.lang.Throwable
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.shaded.io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:115)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.shaded.io.opentelemetry.api.GlobalOpenTelemetry.get(GlobalOpenTelemetry.java:85)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.javaagent.shaded.io.opentelemetry.api.GlobalOpenTelemetry.getMeterProvider(GlobalOpenTelemetry.java:174)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.exporter.internal.ExporterMetrics.meter(ExporterMetrics.java:90)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.exporter.internal.ExporterMetrics.seen(ExporterMetrics.java:74)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.exporter.internal.ExporterMetrics.addSeen(ExporterMetrics.java:58)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.exporter.internal.http.HttpExporter.export(HttpExporter.java:59)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.exporter.internal.otlp.metrics.MetricReusableDataMarshaler.export(MetricReusableDataMarshaler.java:48)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.exporter.otlp.http.metrics.OtlpHttpMetricExporter.export(OtlpHttpMetricExporter.java:113)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at co.elastic.otel.dynamicconfig.BlockableMetricExporter.export(BlockableMetricExporter.java:70)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.sdk.metrics.export.PeriodicMetricReader$Scheduled.doRun(PeriodicMetricReader.java:167)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at io.opentelemetry.sdk.metrics.export.PeriodicMetricReader$Scheduled.run(PeriodicMetricReader.java:153)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
10:58:05.274 [docker-java-stream-2559052] INFO c.e.j.smoketest.UserAgentHeaderTest - STDERR: at java.base/java.lang.Thread.run(Thread.java:840)