After updating Java APM agent from 1.36 to 1.37 context propagation in reactor is no longer working as expected

svenrienstra · May 8, 2023, 11:54am

I have an issue with the Java APM agent, after updating from 1.36 to 1.37 or 1.38 one of my plugins stopped working. I have a plugin which adds instrumentation for the r2dbc postgres driver. The relevant code of this plugins looks like this:

        @Advice.OnMethodExit(inline = false)
        @Advice.AssignReturned.ToReturned(typing = Assigner.Typing.DYNAMIC)
        public static Flux<PostgresqlResult> onExitExecute(@Advice.Argument(0) String sql,
                                                           @Advice.Return Flux<io.r2dbc.postgresql.api.PostgresqlResult> result) {
            return Mono.defer(() -> Mono.just(createSpan(sql)))
                    .flatMapMany(spanBuilder -> {
                        LOG.debug("Starting span");
                        LOG.debug("Parent: {}", Span.current());
                        Span span = spanBuilder
                                .startSpan();

                        return result
                                .doOnComplete(() -> {
                                    LOG.debug("Closing span");
                                    span.setStatus(StatusCode.OK).end();
                                })
                                .doOnError(throwable -> {
                                    LOG.debug("Closing span");
                                    span.recordException(throwable).end();
                                });
                    });
        }

After updating the APM agent version in the application using this plugin, 'Span.current()' is no longer the actual active span. See this logging:

1.36

2023-05-08 13:27:00,504 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-5b0577cff59fc51336b6c0bf5a6904d0-53bb7f8cac0efe8e-01 (6582d919) (133)
2023-05-08 13:27:00.504 DEBUG 7220 --- [actor-tcp-nio-3] [default] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Found signature SELECT FROM patient
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-5b0577cff59fc51336b6c0bf5a6904d0-53bb7f8cac0efe8e-01 (6582d919) (134)
2023-05-08 13:27:00.504 DEBUG 7220 --- [actor-tcp-nio-3] [default] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Starting span
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-5b0577cff59fc51336b6c0bf5a6904d0-53bb7f8cac0efe8e-01 (6582d919) (135)
2023-05-08 13:27:00.504 DEBUG 7220 --- [actor-tcp-nio-3] [default] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Parent: OtelSpan['PatientRestController#getAllPatients' 00-5b0577cff59fc51336b6c0bf5a6904d0-53bb7f8cac0efe8e-01 (6582d919)]
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-5b0577cff59fc51336b6c0bf5a6904d0-fb1827a00c5e18a0-01 (53382723)
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-5b0577cff59fc51336b6c0bf5a6904d0-53bb7f8cac0efe8e-01 (6582d919) (136)
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-5b0577cff59fc51336b6c0bf5a6904d0-fb1827a00c5e18a0-01 (53382723) (1)
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-5b0577cff59fc51336b6c0bf5a6904d0-53bb7f8cac0efe8e-01 (6582d919) (137)
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-5b0577cff59fc51336b6c0bf5a6904d0-53bb7f8cac0efe8e-01 (6582d919) (138)
2023-05-08 13:27:00,504 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'SELECT FROM patient' 00-5b0577cff59fc51336b6c0bf5a6904d0-fb1827a00c5e18a0-01 (53382723) (2)

1.38

2023-05-08 13:30:27,100 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (116)
2023-05-08 13:30:27,100 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (117)
2023-05-08 13:30:27.100 DEBUG 7533 --- [actor-tcp-nio-2] [default] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Creating R2DBC span
2023-05-08 13:30:27.100 DEBUG 7533 --- [actor-tcp-nio-2] [default] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Found signature SELECT FROM patient
2023-05-08 13:30:27,100 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (118)
2023-05-08 13:30:27.100 DEBUG 7533 --- [actor-tcp-nio-2] [default] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Starting span
2023-05-08 13:30:27.100 DEBUG 7533 --- [actor-tcp-nio-2] [default] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Parent: PropagatedSpan{ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}}
2023-05-08 13:30:27,100 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (119)
2023-05-08 13:30:27,100 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (120)
2023-05-08 13:30:27,100 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (121)
2023-05-08 13:30:27,100 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (122)
2023-05-08 13:30:27,101 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (123)
2023-05-08 13:30:27,101 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (124)
2023-05-08 13:30:27,101 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (125)
2023-05-08 13:30:27,101 [reactor-tcp-nio-3] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (126)
2023-05-08 13:30:27,101 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-a95764c6e36e44a2475a09fea27c21bb-cc15f9b7457009c6-01 (2f0e0a86) (127)

As you can see 'Parent:' log line is not showing the actual active span when running with agent version 1.38. The only change between these two runs is the APM agent version. I've tried to look through the changes made between 1.36 and 1.37/1.38 what could have broken this, but so for I've been unable to narrow down the actual cause.

I could really use some pointers on how to debug this, because at the moment I don't really know where to start.

Sylvain_Juge · May 9, 2023, 8:23am

Hi @svenrienstra , thanks for reporting this !

From the provided code example I see that you are manually wrapping the method result, which is very different from the way the agent currently does it. For example, with the Webflux client, we use the the co.elastic.apm.agent.springwebclient.WebClientHelper#wrapSubscriber and wrap the publisher with co.elastic.apm.agent.springwebclient.WebClientSubscriber.

It definitely looks like something isn't working as expected here, could you share the code of your plugin by chance ? I am asking this because it would definitely be easier for me to try attempting to reproduce it.

Also, you are using the OTel API, so it could be related to this issue which I haven't been able to reproduce so far, so any help to reproduce it on our side would really help.

svenrienstra · May 9, 2023, 9:06am

Hi Sylvain,

I can share the code with you, if I can do so in a way secure way. Do you have a place where I could upload the code? Or I could email you the code?

I'll have a look at the classes you mentioned. For me this was just the easiest way to get this plugin working.

You're correct in that I'm using the OTel API, as that is the way the guide on how to write a plugin (Plugin API | APM Java Agent Reference [1.x] | Elastic) describes how to do it.

I've been trying to reproduce it in a test case, unfortunately no success so far.

Sylvain_Juge · May 9, 2023, 9:31am

I will send you an upload link in a private message for secure file transfer.

svenrienstra · May 9, 2023, 11:42am

I've found something interesting I think. I started adding some logging statements in my controller to see if the span was still populated. I added these two lines:

.doOnNext(__ -> log.info(
                        "Elastic span in service: {}", ElasticApm.currentSpan().getId()))
                .doOnNext(__ -> log.info("OTel span in service: {}", Span.current()))

What I noticed was that both were giving the correct information, but also that the OTel instrumentation was loaded just before that log line was printed:

2023-05-09 13:39:29.844  INFO 64681 --- [actor-tcp-nio-2] [default] i.h.r.service.PatientService             : Elastic span in service: e9f4a6bb93e3904f
2023-05-09 13:39:29,845 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ContextStorageInstrumentation: name(equals(io.opentelemetry.context.ContextStorage)) matches interface io.opentelemetry.context.ContextStorage
2023-05-09 13:39:29,847 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation ContextStorageInstrumentation: (name(equals(get)) and returns(erasure(name(equals(io.opentelemetry.context.ContextStorage)))) and not(isAbstract())) matches public static io.opentelemetry.context.ContextStorage io.opentelemetry.context.ContextStorage.get()
2023-05-09 13:39:29,852 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.bci.IndyPluginClassLoaderFactory - Creating plugin class loader for jdk.internal.loader.ClassLoaders$AppClassLoader@2aae9190 containing [co.elastic.apm.agent.opentelemetry.GlobalOpenTelemetryInstrumentation, co.elastic.apm.agent.opentelemetry.tracing.OTelTracerProvider, co.elastic.apm.agent.opentelemetry.tracing.OTelSpan$1, co.elastic.apm.agent.opentelemetry.tracing.OTelSpan, co.elastic.apm.agent.opentelemetry.tracing.OTelTracer, co.elastic.apm.agent.opentelemetry.tracing.BehavioralAttributes, co.elastic.apm.agent.opentelemetry.tracing.package-info, co.elastic.apm.agent.opentelemetry.tracing.OTelBridgeContext, co.elastic.apm.agent.opentelemetry.tracing.OTelSpanBuilder, co.elastic.apm.agent.opentelemetry.tracing.OTelSpanContext, co.elastic.apm.agent.opentelemetry.ContextStorageInstrumentation$ContextStorageAdvice, co.elastic.apm.agent.opentelemetry.global.ElasticOpenTelemetry, co.elastic.apm.agent.opentelemetry.global.ElasticOpenTelemetryWithMetrics, co.elastic.apm.agent.opentelemetry.ArrayBasedContextInstrumentation$RootAdvice, co.elastic.apm.agent.opentelemetry.package-info, co.elastic.apm.agent.opentelemetry.metrics.bridge.BridgedElement, co.elastic.apm.agent.opentelemetry.metrics.bridge.BridgeFactoryLatest, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeLongGaugeBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeDoubleGaugeBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeDoubleCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeDoubleUpDownCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeBatchCallback, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeLongCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeLongUpDownCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.latest.BridgeMeter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleUpDownCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeMeterProvider, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleHistogram, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableLongGauge, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongGaugeBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableDoubleMeasurement, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleGaugeBuilder$1, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleCounterBuilder$1, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongCounterBuilder$1, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleGaugeBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongHistogram, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleUpDownCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongGaugeBuilder$1, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableLongUpDownCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableDoubleGauge, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleHistogramBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableLongMeasurement, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableDoubleUpDownCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableDoubleCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongUpDownCounterBuilder$1, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongUpDownCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongUpDownCounterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeObservableLongCounter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeMeterBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeMeter, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeLongHistogramBuilder, co.elastic.apm.agent.opentelemetry.metrics.bridge.v1_14.BridgeDoubleUpDownCounterBuilder$1, co.elastic.apm.agent.opentelemetry.metrics.bridge.AbstractBridgedElement, co.elastic.apm.agent.opentelemetry.metrics.bridge.BridgeFactoryV1_14$1, co.elastic.apm.agent.opentelemetry.metrics.bridge.BridgeFactory, co.elastic.apm.agent.opentelemetry.metrics.bridge.BridgeFactoryV1_14, co.elastic.apm.agent.opentelemetry.metrics.bridge.OtelMetricsBridge, co.elastic.apm.agent.opentelemetry.ArrayBasedContextInstrumentation, co.elastic.apm.agent.opentelemetry.context.OTelContextStorage, co.elastic.apm.agent.opentelemetry.context.package-info, co.elastic.apm.agent.opentelemetry.GlobalOpenTelemetryInstrumentation$GlobalOpenTelemetryAdvice, co.elastic.apm.agent.opentelemetry.ContextStorageInstrumentation, co.elastic.apm.agent.opentelemetry.AbstractOpenTelemetryInstrumentation, co.elastic.apm.agent.bci.classloading.LookupExposer]
2023-05-09 13:39:29,878 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation ArrayBasedContextInstrumentation: name(equals(io.opentelemetry.context.ArrayBasedContext)) matches class io.opentelemetry.context.ArrayBasedContext
2023-05-09 13:39:29,879 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation ArrayBasedContextInstrumentation: (name(equals(root)) and isStatic() and returns(erasure(hasSuperType(erasure(name(equals(io.opentelemetry.context.Context)))))) and hasParameter(ofSize(0)) and not(isAbstract())) matches static io.opentelemetry.context.Context io.opentelemetry.context.ArrayBasedContext.root()
2023-05-09 13:39:29,881 [reactor-tcp-nio-2] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'PatientRestController#getAllPatients' 00-21953cf40dec8b5df38075eb71c14d1a-e9f4a6bb93e3904f-01 (4f86b41e) (88)
2023-05-09 13:39:29.882  INFO 64681 --- [actor-tcp-nio-2] [default] i.h.r.service.PatientService             : OTel span in service: OtelSpan['PatientRestController#getAllPatients' 00-21953cf40dec8b5df38075eb71c14d1a-e9f4a6bb93e3904f-01 (4f86b41e)]

Which triggered me, so I tried to add a line where I accessed the OTel span at the very start of my controller method and the plugin is working as expected again! It looks like since 1.37 the OTel instrumentation isn't loaded anymore when a plugin is in use. But because the plugins depend on OTel those instrumentations should be loaded I think.

Edit:
Just checked when this instrumentation was loaded in 1.36:

2023-05-09 13:48:22.505 DEBUG 65716 --- [actor-tcp-nio-1] [] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Creating R2DBC span
2023-05-09 13:48:22.507 DEBUG 65716 --- [actor-tcp-nio-1] [] h.a.a.r.p.R2dbcPostgresqlInstrumentation : Found signature SHOW
2023-05-09 13:48:22,507 [reactor-tcp-nio-1] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation GlobalOpenTelemetryInstrumentation: name(equals(io.opentelemetry.api.GlobalOpenTelemetry)) matches class io.opentelemetry.api.GlobalOpenTelemetry
2023-05-09 13:48:22,508 [reactor-tcp-nio-1] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation GlobalOpenTelemetryInstrumentation: (name(equals(get)) and not(isAbstract())) matches public static io.opentelemetry.api.OpenTelemetry io.opentelemetry.api.GlobalOpenTelemetry.get()
2023-05-09 13:48:22,514 [reactor-tcp-nio-1] DEBUG co.elastic.apm.agent.bci.IndyPluginClassLoaderFactory - Creating plugin class loader for IndyPluginClassLoader{ parent=DiscriminatingMultiParentClassLoader{agentClassLoader = ExternalPluginClassLoader{pluginJar=/Users/svenrienstra/Documents/workspaces/h4h/apm-r2-plugin/target/apm-r2dbc-postgresql-plugin-1.1.0-SNAPSHOT.jar, parent =ShadedClassLoader{parent=ShadedClassLoader{parent=jdk.internal.loader.ClassLoaders$PlatformClassLoader@426ebfb9, customPrefix='cached-lookup-key/', manifest=java.util.jar.Manifest@694cf4bb, jarUrl=file:/private/var/folders/ds/xbpb_l816b73hbp9825k7jfw0000gn/T/elastic-apm-agent-6bb636343d7b71ccaa9fd7321da5cc2d-3be90268557494f88fe252caf6358d41.jar}, customPrefix='agent/', manifest=java.util.jar.Manifest@694cf4bb, jarUrl=file:/private/var/folders/ds/xbpb_l816b73hbp9825k7jfw0000gn/T/elastic-apm-agent-6bb636343d7b71ccaa9fd7321da5cc2d-3be90268557494f88fe252caf6358d41.jar}} discriminator = (not(co.elastic.apm.agent.bci.classloading.IndyPluginClassLoader$StartsWithElementMatcher@3c5bf071) and not(co.elastic.apm.agent.bci.classloading.IndyPluginClassLoader$StartsWithElementMatcher@3d66cb0a) and not(co.elastic.apm.agent.bci.classloading.IndyPluginClassLoader$StartsWithElementMatcher@1861ef52)), targetClassLoader =jdk.internal.loader.ClassLoaders$AppClassLoader@2aae9190 discriminator = true}} containing [co.elastic.apm.agent.opentelemetry.package-info, co.elastic.apm.agent.opentelemetry.sdk.package-info, co.elastic.apm.agent.opentelemetry.sdk.OTelBridgeContext, co.elastic.apm.agent.opentelemetry.sdk.OTelSpanBuilder, co.elastic.apm.agent.opentelemetry.sdk.OTelSpanContext, co.elastic.apm.agent.opentelemetry.sdk.OTelTracerProvider, co.elastic.apm.agent.opentelemetry.sdk.OTelSpan$1, co.elastic.apm.agent.opentelemetry.sdk.OTelSpan, co.elastic.apm.agent.opentelemetry.sdk.BehavioralAttributes, co.elastic.apm.agent.opentelemetry.sdk.OTelTracer, co.elastic.apm.agent.opentelemetry.sdk.ElasticOpenTelemetry, co.elastic.apm.agent.opentelemetry.ArrayBasedContextInstrumentation, co.elastic.apm.agent.opentelemetry.ContextStorageInstrumentation$ContextStorageAdvice, co.elastic.apm.agent.opentelemetry.ContextStorageInstrumentation, co.elastic.apm.agent.opentelemetry.ArrayBasedContextInstrumentation$RootAdvice, co.elastic.apm.agent.opentelemetry.GlobalOpenTelemetryInstrumentation$GlobalOpenTelemetryAdvice, co.elastic.apm.agent.opentelemetry.AbstractOpenTelemetryInstrumentation, co.elastic.apm.agent.opentelemetry.context.package-info, co.elastic.apm.agent.opentelemetry.context.OTelContextStorage, co.elastic.apm.agent.opentelemetry.GlobalOpenTelemetryInstrumentation, co.elastic.apm.agent.bci.classloading.LookupExposer]

It's loaded just after the first time the plugin triggered, I guess I just never noticed the first call to the service was missing some information. So the difference is that since 1.37 the OTel instrumentation isn't loaded based on activity by the plugin anymore.

Sylvain_Juge · May 12, 2023, 1:34pm

Thanks for your input here, I have successfully managed to reproduce your observed behavior.
So, it currently works as expected with 1.36.0 and fails with 1.37.0 and later.

I don't have much time to investigate this further today, so expect an update on this during next week.

Sylvain_Juge · May 16, 2023, 2:16pm

Hi !

I've been able to find the commit that introduced this regression, and I've filed an issue so we can track progress on this: OpenTelemetry regression in v1.37.0 for external plugins · Issue #3145 · elastic/apm-agent-java · GitHub.

Make sure to subscribe to the issue to get updates on this as forum discussions are automatically closed after a few weeks without activity, ideally I'd like to fix this quickly but life usually have other plans :-).

svenrienstra · May 17, 2023, 5:34am

Thanks again, I'll make sure to subscribe to the Github issue.

Jonas_Kunz · May 31, 2023, 9:10am

Hi @svenrienstra ,

We have a PR ready to fix the bug. Could you maybe try out the corresponding snapshot build and report whether it fixes the problem for you?

svenrienstra · May 31, 2023, 9:50am

Thanks @Jonas_Kunz ! This week I'm a bit busy, but I'll try to get back to you asap.

svenrienstra · June 5, 2023, 8:55am

Hi @Jonas_Kunz,

I can confirm the fix seems to be working as expected, OTEL instrumentation is being loaded again when using the fixed version.

Jonas_Kunz · June 5, 2023, 9:25am

Thanks for the Feedback! We'll include the fix in the next release.

system · June 26, 2023, 5:26am

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.