java.lang.NullPointerException: null occurs in HttpExchangeTracer

[BalasDev]

When we are doing performance test for our endpoint, time to time happens the exception:

java.lang.NullPointerException: null
	at java.util.HashMap.merge(HashMap.java:1225) ~[?:1.8.0_191]
	at java.util.stream.Collectors.lambda$toMap$58(Collectors.java:1320) ~[?:1.8.0_191]
	at java.util.stream.ReduceOps$3ReducingSink.accept(ReduceOps.java:169) ~[?:1.8.0_191]
	at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:1.8.0_191]
	at java.util.Iterator.forEachRemaining(Iterator.java:116) ~[?:1.8.0_191]
	at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801) ~[?:1.8.0_191]
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:1.8.0_191]
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:1.8.0_191]
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:1.8.0_191]
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:1.8.0_191]
	at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499) ~[?:1.8.0_191]
	at org.springframework.boot.actuate.trace.http.HttpExchangeTracer.getHeadersIfIncluded(HttpExchangeTracer.java:107) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.boot.actuate.trace.http.HttpExchangeTracer.access$200(HttpExchangeTracer.java:38) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.boot.actuate.trace.http.HttpExchangeTracer$FilteredTraceableResponse.getHeaders(HttpExchangeTracer.java:170) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.boot.actuate.trace.http.HttpTrace$Response.<init>(HttpTrace.java:185) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.boot.actuate.trace.http.HttpExchangeTracer.sendingResponse(HttpExchangeTracer.java:76) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.boot.actuate.web.trace.reactive.HttpTraceWebFilter.lambda$filter$3(HttpTraceWebFilter.java:103) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onComplete(MonoPeekTerminal.java:325) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete(MonoFlatMap.java:189) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete(MonoFlatMap.java:260) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:1713) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete(MonoFlatMap.java:189) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete(MonoFlatMap.java:260) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete(MonoFlatMap.java:189) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete(MonoFlatMap.java:260) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:252) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at org.springframework.http.server.reactive.ChannelSendOperator$WriteCompletionBarrier.onComplete(ChannelSendOperator.java:374) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:81) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxConcatIterable$ConcatIterableSubscriber.onComplete(FluxConcatIterable.java:120) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoNext$NextSubscriber.onComplete(MonoNext.java:96) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at org.springframework.http.server.reactive.WriteResultPublisher$State.publishComplete(WriteResultPublisher.java:244) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.WriteResultPublisher.publishComplete(WriteResultPublisher.java:84) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.AbstractListenerWriteFlushProcessor$State$3.writeComplete(AbstractListenerWriteFlushProcessor.java:291) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.AbstractListenerWriteFlushProcessor$State$WriteResultSubscriber.onComplete(AbstractListenerWriteFlushProcessor.java:415) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.WriteResultPublisher$State.publishComplete(WriteResultPublisher.java:244) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.WriteResultPublisher.publishComplete(WriteResultPublisher.java:84) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.AbstractListenerWriteProcessor.changeStateToComplete(AbstractListenerWriteProcessor.java:269) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.AbstractListenerWriteProcessor.access$400(AbstractListenerWriteProcessor.java:45) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.AbstractListenerWriteProcessor$State$2.onComplete(AbstractListenerWriteProcessor.java:341) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.AbstractListenerWriteProcessor.onComplete(AbstractListenerWriteProcessor.java:131) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.http.server.reactive.ChannelSendOperator$WriteBarrier.onComplete(ChannelSendOperator.java:221) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at reactor.core.publisher.FluxJust$WeakScalarSubscription.request(FluxJust.java:101) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at org.springframework.http.server.reactive.ChannelSendOperator$WriteBarrier.onSubscribe(ChannelSendOperator.java:164) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:70) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at org.springframework.http.server.reactive.ChannelSendOperator.subscribe(ChannelSendOperator.java:75) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at reactor.core.publisher.MonoPeek.subscribe(MonoPeek.java:71) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2041) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:162) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:1849) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:1723) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:90) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoMapFuseable.subscribe(MonoMapFuseable.java:59) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoSwitchIfEmpty.subscribe(MonoSwitchIfEmpty.java:44) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap.subscribe(MonoFlatMap.java:60) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1476) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:92) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1476) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoCollect$CollectSubscriber.onComplete(MonoCollect.java:142) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:794) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:560) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxFlatMap$FlatMapMain.innerComplete(FluxFlatMap.java:863) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.FluxFlatMap$FlatMapInner.onComplete(FluxFlatMap.java:957) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1463) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoZip$ZipCoordinator.signal(MonoZip.java:247) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoZip$ZipInner.onNext(MonoZip.java:329) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:147) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at org.springframework.boot.actuate.health.HealthIndicatorReactiveAdapter.invoke(HealthIndicatorReactiveAdapter.java:49) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.boot.actuate.health.HealthIndicatorReactiveAdapter.lambda$null$0(HealthIndicatorReactiveAdapter.java:43) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at reactor.core.scheduler.ElasticScheduler$DirectScheduleTask.run(ElasticScheduler.java:291) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) ~[reactor-core-3.2.3.RELEASE.jar!/:3.2.3.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_191]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_191]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_191]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_191]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_191]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]

Spring Boot version is 2.1.2.RELEASE

[BalasDev]

It hard to reproduce on the local machine.
But time to time error occurs on /health, /info endpoints when kubernates requested them.
Happened after request was submitted successfully.

[wilkinsona]

Assuming that the line numbers match up, the NPE from HashMap.merge(HashMap.java:1225) means that there's an entry in the map with a null value. The map's contents are created from an instance of org.springframework.http.HttpHeaders.

@bclozel, is it expected that HttpHeaders may contain an entry with a null value?

[BalasDev]

@wilkinsona When I investigated stacktrace I found different errors, one of that when HttpExchangeTracer got response headers method size() from TomcatHeadersAdapter
The method checks MimeHeaders and empty MimeHeaders returns true in names.hasMoreElements()
but names.nextElement() occurs NPE
Also for the same error I have a stacktrace
NPE.txt

[BalasDev]

Very strange behavior of MimeHeaders

[bclozel]

@wilkinsona @BalasDev Let me take a look.
This might be a problem with the adapters implementation in Spring Framework, or the Trace feature keeping a reference to headers that have been recycled by Tomcat. Since recent Spring Framework versions, we're not copying headers anymore but adapting to the native implementation.

We might need to adapt things in our actuator support there.

[PradeepJoam]

This is problem is can't created object
MonoFlatMap.java that means map getting null value from an instance of at org.springframework.boot.actuate.health.HealthIndicatorReactiveAdapter.lambda$null$0(HealthIndicatorReactiveAdapter.java

[4ernookiy]

@bclozel @wilkinsona
We have switched from Tomcat to Netty. And issue is gone. (we don't see any similar issue in Kibana and pod console)

[bclozel]

@wilkinsona HttpHeaders are dealing with null values, but things have been tightened a bit since in spring-projects/spring-framework#22120.

I managed to reproduce the problem by:

• Creating a Spring Boot WebFlux application with Tomcat and Actuator
• Sending a lot of traffic to the application, to any endpoint
• Hit the /actuator/trace endpoint

Here's what's happening, as suspected:

1. An incoming request is intercepted by the HttpTraceWebFilter, and the filter chain is executed
2. Once the filter chain is done, there's no strong guarantee anymore about the HTTP resources, including the exchange itself. In the case of Tomcat (and a lot of traffic), the HTTP headers are pooled and recycled quickly enough
3. In the doAfterSuccessOrError operator, which happens after the filter chain processing, we're trying to extract the headers information but it's too late. In some cases the HTTP headers have been recycled by the time the operator is executed

I don't think we can easily move that part off of doAfterSuccessOrError, because we need to make sure that all filters have been invoked. On the other hand, the HttpTraceRepository contract is blocking, so I guess that custom implementations aren't supposed to deal with I/O and that this is pretty much a best effort mechanism.

With that in mind, I think the best move here would be to protect against such cases in the HttpTraceWebFilter itself and skip those traces. Given the amount of incoming traffic, it would be wise to disable tracing altogether because the InMemoryHttpTraceRepository is not tailored for that.

@BalasDev Did you leave the HTTP tracing enabled by choice, or just because this is the default behavior? Just so you know, this is being considered in #15039 for exactly this type of use cases.

[wilkinsona]

Thanks for investigating, @bclozel

3. In the doAfterSuccessOrError operator, which happens after the filter chain processing, we're trying to extract the headers information but it's too late. In some cases the HTTP headers have been recycled by the time the operator is executed

This sounds like a bit of a flaw to me. In the servlet case we capture the headers in a filter and use ordering so that it's called at a defined point in the chain. Perhaps we should consider a similar approach in the reactive case. I would prefer to predictably miss header changes made by certain filters that run later than unpredictably get the wrong headers due to the object being recycled.

[BalasDev]

Thank you @bclozel,
we left HTTP tracing because it enabled by default, but now it is disabled and everything runs smoothly.
Also we switched to Netty and error did not occur.

[bclozel]

@wilkinsona I think we could capture the status and response headers right before the response is committed with: exchange.getResponse().beforeCommit(() -> { // capture here });. It might require some changes, I'll take a look into it.