Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NullPointerException from reactornetty instrumentation introduced in version 3.4.16 #3295

Closed
paul-kraftlauget opened this issue Sep 15, 2023 · 9 comments

Comments

@paul-kraftlauget
Copy link

Expected behavior

No failures

Actual behavior

NullPointerException occurs from reactornetty instrumentation when issuing a HTTP GET request

Please note that 3.4.15 works fine. 3.4.16 fails.

The culprit seems to be when our application reaches out to obtain a security token through another HTTP GET before invoking the actual HTTP GET. Consider this code when we setup the netty HttpClient:

import reactor.netty.http.client.HttpClient;
...
HttpClient httpClient = HttpClient.create()...;

httpClient = httpClient.headersWhen(headers -> context.getBean(TokenIntegrationService.class).getSecurityToken()
                        .map(token -> headers.set(HttpHeaders.AUTHORIZATION, token.getTokenType() + " " + token.getAccessToken())));

So we have one HTTP client request started, then reactively, we add the authorization header by calling an oauth2 endpoint. The oauth2 endpoint HTTP request and response is successful, but the client request using the header/token fails.

I would guess that the context is cleared somehow when the first nested request/response finishes, leaving a NullPointerException when primary request is issued.

System information

Please provide the following information:

  • SDK Version: 3.4.16
  • OS type and version: Reproducible both as java app service in Azure as well as running application locally on Windows with app insights connection string
  • Application Server type and version (if applicable): embedded tomcat on spring boot version 3.1.3
  • Using spring-boot? Yes
  • Additional relevant libraries (with version, if applicable):

Logs

2023-09-15T13:57:54.594+02:00  WARN 115804 --- [  reactor-http-nio-3][64d16ca4-582a-416e-90d0-e39246b59399] r.n.h.c.HttpClientConnect                : [4e1eb107-1, L:/127.0.0.1:57907 - R:localhost/127.0.0.1:8082] The connection observed an error

java.lang.NullPointerException: Cannot invoke "io.opentelemetry.javaagent.shaded.io.opentelemetry.context.Context.get(io.opentelemetry.javaagent.shaded.io.opentelemetry.context.ContextKey)" because "context" is null
	at io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SpanKey.fromContextOrNull(SpanKey.java:85) ~[?:?]
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Assembly trace from producer [reactor.core.publisher.MonoError] :
	reactor.core.publisher.Mono.error
	reactor.netty.http.client.HttpClientConnect$HttpClientHandler.requestWithBody(HttpClientConnect.java:607)
Error has been observed at the following site(s):
	*____________Mono.error ⇢ at reactor.netty.http.client.HttpClientConnect$HttpClientHandler.requestWithBody(HttpClientConnect.java:607)
	|_      Mono.fromDirect ⇢ at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.lambda$onStateChange$0(HttpClientConnect.java:444)
	*____________Mono.defer ⇢ at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:444)
	*___________Mono.create ⇢ at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect.subscribe(HttpClientConnect.java:210)
	|_       Mono.retryWhen ⇢ at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect.subscribe(HttpClientConnect.java:275)
	*________Flux.concatMap ⇢ at reactor.util.retry.RetrySpec.lambda$generateCompanion$6(RetrySpec.java:360)
	|_     Flux.onErrorStop ⇢ at reactor.util.retry.RetrySpec.lambda$generateCompanion$6(RetrySpec.java:379)
	*__Flux.deferContextual ⇢ at reactor.util.retry.RetrySpec.generateCompanion(RetrySpec.java:357)
	*__________Mono.flatMap ⇢ at reactor.netty.http.client.HttpClientConnect.connect(HttpClientConnect.java:114)
	|_                      ⇢ at reactor.netty.http.client.HttpClientFinalizer._connect(HttpClientFinalizer.java:159)
	|_     Mono.flatMapMany ⇢ at reactor.netty.http.client.HttpClientFinalizer.responseConnection(HttpClientFinalizer.java:102)
	|_            Flux.next ⇢ at org.springframework.http.client.reactive.ReactorClientHttpConnector.connect(ReactorClientHttpConnector.java:119)
	|_      Mono.doOnCancel ⇢ at org.springframework.http.client.reactive.ReactorClientHttpConnector.connect(ReactorClientHttpConnector.java:120)
	|_     Mono.doOnRequest ⇢ at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:103)
	|_      Mono.doOnCancel ⇢ at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:104)
Original Stack Trace:
		at io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SpanKey.fromContextOrNull(SpanKey.java:85) ~[?:?]
		at io.opentelemetry.javaagent.shaded.instrumentation.api.instrumenter.SpanSuppressors$BySpanKey.shouldSuppress(SpanSuppressors.java:81) ~[?:?]
		at io.opentelemetry.javaagent.shaded.instrumentation.api.instrumenter.Instrumenter.shouldStart(Instrumenter.java:113) ~[?:?]
		at io.opentelemetry.javaagent.instrumentation.reactornetty.v1_0.InstrumentationContexts.startClientSpan(InstrumentationContexts.java:48) ~[agent.jar:?]
		at io.opentelemetry.javaagent.instrumentation.reactornetty.v1_0.HttpResponseReceiverInstrumenter$StartOperation.accept(HttpResponseReceiverInstrumenter.java:94) ~[agent.jar:?]
		at io.opentelemetry.javaagent.instrumentation.reactornetty.v1_0.HttpResponseReceiverInstrumenter$StartOperation.accept(HttpResponseReceiverInstrumenter.java:84) ~[agent.jar:?]
		at io.opentelemetry.javaagent.instrumentation.reactornetty.v1_0.DecoratorFunctions$OnMessageDecorator.accept(DecoratorFunctions.java:40) ~[agent.jar:?]
		at io.opentelemetry.javaagent.instrumentation.reactornetty.v1_0.DecoratorFunctions$OnMessageDecorator.accept(DecoratorFunctions.java:24) ~[agent.jar:?]
		at reactor.netty.http.client.HttpClientConfig$HttpClientDoOn.onStateChange(HttpClientConfig.java:1009) ~[reactor-netty-http-1.1.10.jar:1.1.10]
		at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:710) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onStateChange(DefaultPooledConnectionProvider.java:195) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnection.onStateChange(DefaultPooledConnectionProvider.java:456) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at reactor.netty.http.client.HttpClientConnect$HttpClientHandler.requestWithBody(HttpClientConnect.java:567) ~[reactor-netty-http-1.1.10.jar:1.1.10]
		at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.lambda$onStateChange$0(HttpClientConnect.java:444) ~[reactor-netty-http-1.1.10.jar:1.1.10]
		at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:45) ~[reactor-core-3.5.9.jar:3.5.9]
		at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.5.9.jar:3.5.9]
		at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:445) ~[reactor-netty-http-1.1.10.jar:1.1.10]
		at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:710) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onStateChange(DefaultPooledConnectionProvider.java:195) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnection.onStateChange(DefaultPooledConnectionProvider.java:456) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at reactor.netty.channel.ChannelOperationsHandler.channelActive(ChannelOperationsHandler.java:62) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:262) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelActive(CombinedChannelDuplexHandler.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.ChannelInboundHandlerAdapter.channelActive(ChannelInboundHandlerAdapter.java:69) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.CombinedChannelDuplexHandler.channelActive(CombinedChannelDuplexHandler.java:211) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:260) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelActive(CombinedChannelDuplexHandler.java:412) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.ChannelInboundHandlerAdapter.channelActive(ChannelInboundHandlerAdapter.java:69) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.CombinedChannelDuplexHandler.channelActive(CombinedChannelDuplexHandler.java:211) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:260) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at reactor.netty.channel.AbstractChannelMetricsHandler.channelActive(AbstractChannelMetricsHandler.java:65) ~[reactor-netty-core-1.1.10.jar:1.1.10]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:260) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.handler.logging.LoggingHandler.channelActive(LoggingHandler.java:198) ~[netty-handler-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:260) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.DefaultChannelPipeline$HeadContext.channelActive(DefaultChannelPipeline.java:1398) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:258) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:238) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:895) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:305) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:335) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:776) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
		at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.97.Final.jar:4.1.97.Final]
@trask
Copy link
Member

trask commented Sep 15, 2023

hi @paul-kraftlauget, thanks for reporting this!

my guess is that this regression came from open-telemetry/opentelemetry-java-instrumentation#8111

I'm curious if this PR will resolve the issue for you: open-telemetry/opentelemetry-java-instrumentation#9286

'm working on getting you a build for that PR and will post back here with link and instructions how to test using the upstream OpenTelemetry Java agent.

@trask
Copy link
Member

trask commented Sep 18, 2023

@paul-kraftlauget can you test with this upstream java agent SNAPSHOT build? https://github.com/open-telemetry/opentelemetry-java-instrumentation/suites/16262373066/artifacts/928504346

you can run with

-Dotel.traces.exporter=logging -Dotel.metrics.exporter=logging -Dotel.logging.exporter=logging

this will cause telemetry to be logged instead of sent anywhere

the key is whether this upstream version still exhibits the NPE

if it doesn't exhibit the NPE, can you also test the latest upstream release to verify that does exhibit the NPE? https://github.com/open-telemetry/opentelemetry-java-instrumentation/releases/download/v1.30.0/opentelemetry-javaagent.jar

thanks!

@paul-kraftlauget
Copy link
Author

paul-kraftlauget commented Sep 18, 2023

Thank you for your quick responses. I think the opentelemetry stuff is shaded (repackaged) inside the app insights agent runtime. So I would remove app insights runtime dependency, and run my application with the opentelemetry-javaagent instead? I'll give it a try. :-)

@paul-kraftlauget
Copy link
Author

@trask - I have now tested and see the issue unfortunately still exists in opentelemetry-javaagent version 1.31.0-SNAPSHOT.

I have tested with different versions of opentelemetry-javaagent:
1.28.0 - working
1.29.0 - fails
1.30.0 - fails
1.31.0-SNAPSHOT - fails

@paul-kraftlauget
Copy link
Author

Shall I register a bug directly on opentelemetry then since the issue appears to be due to that library and not the appinsights agent?

@trask
Copy link
Member

trask commented Sep 18, 2023

Shall I register a bug directly on opentelemetry then since the issue appears to be due to that library and not the appinsights agent?

sure, that would be great, you can leave this one open as well to track including the fix into Application Insights as well

@trask
Copy link
Member

trask commented Sep 21, 2023

hi @paul-kraftlauget, thanks for reporting this upstream! the fix is merged upstream and will go out in the upstream Oct release, and then in the Application Insights Java Oct release which usually follows the upstream release by a week.

@paul-kraftlauget
Copy link
Author

I have verified that the upstream opentelemetry-javaagent 1.31.0 works as expected. Thanks for your help!

@trask
Copy link
Member

trask commented Oct 31, 2023

Should be resolved now in Application Insights Java 3.4.18

@trask trask closed this as completed Oct 31, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants