OpenTelemetry Context is null in Rest Client filter (using Azure App Insights agent)

[Orbifoldt]

Describe the bug

The OpenTelemetryClientFilter is causing a NullPointerException. In particular, the spanContext as retrieved from the client request context is null:

quarkus/extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/tracing/intrumentation/restclient/OpenTelemetryClientFilter.java

Line 121 in 8f0e94e

Context spanContext = (Context) request.getProperty(REST_CLIENT_OTEL_SPAN_CLIENT_CONTEXT);

This issue seems only to occur when using the Microprofile Rest Client (resteasy classic) in order to invoke some other service. The server itself does not have this issue when it is called, nor do the autoinstrumented sdks that we use.

I am using the Azure Application Insights Java Agent and the Quarkus OpenTelemetry extension. Project is written in Kotlin. I was using a customized propagator, but also with the default ones this error occurs. This issue started occurring after we upgraded from Quarkus 2.16 to 3.2.

Full stack trace:

java.lang.NullPointerException: Cannot invoke "io.opentelemetry.context.Context.get(io.opentelemetry.context.ContextKey)" because "context" is null
	at io.opentelemetry.instrumentation.api.instrumenter.http.HttpClientResend.getAndIncrement(HttpClientResend.java:36)
	at io.opentelemetry.instrumentation.api.instrumenter.http.HttpClientAttributesExtractor.onEnd(HttpClientAttributesExtractor.java:161)
	at io.opentelemetry.instrumentation.api.instrumenter.Instrumenter.doEnd(Instrumenter.java:224)
	at io.opentelemetry.instrumentation.api.instrumenter.Instrumenter.end(Instrumenter.java:144)
	at io.quarkus.opentelemetry.runtime.tracing.intrumentation.restclient.OpenTelemetryClientFilter.filter(OpenTelemetryClientFilter.java:123)
	at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterResponse(ClientInvocation.java:667)
	at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:428)
	at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:134)
	at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:103)
	at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:61)
	at jdk.proxy3/jdk.proxy3.$Proxy175.getCaptureResults(Unknown Source)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.jboss.resteasy.microprofile.client.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:168)
	at jdk.proxy3/jdk.proxy3.$Proxy178.getCaptureResults(Unknown Source)
	at [... my application classes which invoke the rest client ...]
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:73)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext$NextAroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:97)
	at io.quarkus.hibernate.validator.runtime.interceptor.AbstractMethodValidationInterceptor.validateMethodInvocation(AbstractMethodValidationInterceptor.java:71)
	at io.quarkus.hibernate.validator.runtime.jaxrs.JaxrsEndPointValidationInterceptor.validateMethodInvocation(JaxrsEndPointValidationInterceptor.java:38)
	at io.quarkus.hibernate.validator.runtime.jaxrs.JaxrsEndPointValidationInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:70)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext$NextAroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:97)
	at io.quarkus.resteasy.runtime.QuarkusRestPathTemplateInterceptor.restMethodInvoke(QuarkusRestPathTemplateInterceptor.java:39)
	at io.quarkus.resteasy.runtime.QuarkusRestPathTemplateInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:70)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:62)
	at io.quarkus.security.runtime.interceptor.SecurityHandler.handle(SecurityHandler.java:47)
	at io.quarkus.security.runtime.interceptor.RolesAllowedInterceptor.intercept(RolesAllowedInterceptor.java:29)
	at io.quarkus.security.runtime.interceptor.RolesAllowedInterceptor_Bean.intercept(Unknown Source)
	at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:42)
	at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:30)
	at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:27)
	at [... my application classes ...]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:118)
	at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:560)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:452)
	at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:413)
	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:415)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:378)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:356)
	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:70)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:429)
	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:240)
	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
	at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:229)
	at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:82)
	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:147)
	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:93)
	at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)

Expected behavior

Rest client is instrumented and does not throw exceptions

Actual behavior

NullPointerException is thrown

How to Reproduce?

I haven't been able to reproduce this locally using the Azure app insights agent, there are some network/proxy settings that seem to prohibit me from getting it to work.
Using the jaeger-all-in-one docker container (as described in the documentation) locally did not give above error.

Output of uname -a or ver

Linux 5.4.0-1111-azure #117~18.04.1-Ubuntu SMP Wed Jun 21 15:44:28 UTC 2023 x86_64 Linux

Output of java -version

openjdk version "17.0.8" 2023-07-18 LTS

GraalVM version (if different from Java)

n/a

Quarkus version or git rev

3.2.1.Final

Build tool (ie. output of mvnw --version or gradlew --version)

No response

Additional information

No response

[quarkus-bot]

/cc @Sgitario (rest-client), @brunobat (opentelemetry), @cescoffier (rest-client), @geoand (rest-client), @radcortez (opentelemetry)

[geoand]

cc @jamezp

[brunobat]

This instrumentation is quite old. There might be something going on in the propagation of REST_CLIENT_OTEL_SPAN_CLIENT_CONTEXT

[jamezp]

It definitely looks like something is likely not being propagated. I'm not too sure how we'd figure that out without a reproducer. Or I should say maybe I'm not sure how I would :)

[Orbifoldt]

Thanks for your replies @brunobat and @jamezp . I'll try working on some minimal reproducer.

In the mean time, could you maybe point me to where the REST_CLIENT_OTEL_SPAN_CLIENT_CONTEXT should be initialized? Then I can attach a debugger and try to find where it goes wrong

[jamezp]

@Orbifoldt Awesome, thanks!

It looks like in the ClientRequestFilter portion

quarkus/extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/tracing/intrumentation/restclient/OpenTelemetryClientFilter.java

Line 99 in 8f0e94e

request.setProperty(REST_CLIENT_OTEL_SPAN_CLIENT_CONTEXT, spanContext);

.

[Orbifoldt]

The spanContext is not properly initialized, it's already null when its added as a property to the request. This seems to originate from persisting the span into the OpenTelemetry Context.

In debugging I didn't get very far in finding the root cause of this. But maybe this means something to someone, so this is what I found:

• the spanContext is being created here:

  quarkus/extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/tracing/intrumentation/restclient/OpenTelemetryClientFilter.java

  Line 91 in 8f0e94e

  Context spanContext = instrumenter.start(parentContext, request);

• this invokes OpenTelemetry Instrumenters start method, which simply calls the doStart method: https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/dc5d76af68299c1cf517360f47125bce4ca6467d/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java#L162
• In the doStart a new Span is created correctly, so this works fine.
• Then the spanSuppressor is called to store this span into the context https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/dc5d76af68299c1cf517360f47125bce4ca6467d/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java#L208
• This then invokes the DelegateBySpanKind span suppressor's storeInContext method: https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/dc5d76af68299c1cf517360f47125bce4ca6467d/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/SpanSuppressors.java#L73
• Here, spanKeys contains a single SpanKey namely "opentelemetry-traces-span-key-http-client". Then this storeInContext method of the SpanKey is called: https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/dc5d76af68299c1cf517360f47125bce4ca6467d/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/internal/SpanKey.java#L80
• This method returns a null Context. So this is where it goes wrong. However, here the trail goes cold :( It invokes some shaded OpenTelemetry package, and I am unable to see from my remote debugger why null is returned

[Orbifoldt]

@jamezp I've set up a reproducer here: https://github.com/Orbifoldt/quarkus-otel-azure-npe-reproduction
Seems like you don't even need a valid Applicaiton Insights resource to have this error happen

[franden]

we have the same issue with Azure Fuctions + JAXRS client + OpenTelemetry. Any idea if this bug will be fixed in near future?

[brunobat]

It's scheduled for next quarter but is open for grabs.