NullPointerException from reactornetty instrumentation introduced in version 1.29.0

[paul-kraftlauget]

Describe the bug

NullPointerException occurs from reactornetty instrumentation when issuing a HTTP GET request

Please note that 1.28.0 works fine. Versions 1.29.0, 1.30.0 and current 1.31.0-SNAPSHOT all fail.

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.

Here is the stacktrace (from sdk.version=1.29.0):

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]

Steps to reproduce

Create an netty HttpClient for a web service. When setting this client up, add 'headersWhen' which reactively calls another web service (a different httpclient instance).

Expected behavior

No NullPointerException.

Both REST web service calls should execute correctly when instrumentation is enabled.

Actual behavior

The inner REST web service call (the one invoken reactively inside 'headersWhen' works correctly. Then the outer original REST web service call fails with a NullPointerException.

Javaagent or library instrumentation version

1.29.0+

Environment

JDK: Java 17
OS: Both windows and unix fail

Additional context

I originally posted this bug on Microsoft's ApplicationInsights agent's github site:
microsoft/ApplicationInsights-Java#3295

[mateuszrzeszutek]

Looks like the current instrumentation does not handle this branch: https://github.com/reactor/reactor-netty/blob/c7ba195fe513df468d4ebffce61a49f9c09edaac/reactor-netty-http/src/main/java/reactor/netty/http/client/HttpClientConnect.java#L112-L115

Most likely the previous version worked "by accident" (if at all) because of the underlying netty instrumentation.