Spring WebFlux + Undertow + HTTP/2 is not working with a POST request [SPR-16632]

[spring-projects-issues]

Pascal Le Levier opened SPR-16632 and commented

Hello,

I'm currently trying to create a Spring Boot 2 project using webflux and the HTTP/2 protocol
While I was trying the Undertow server, I found that making a POST with some request body was always failing with a Stackoverflow error while a simple GET is working as expected.

This bug makes the use of Undertow as a reactive http/2 server almost impossible (unless we don't post a request body)

You can find a very simple test project to reproduce the bug in the reference URL of the issue.

Controller code :

@RestController
public class Example {

    @GetMapping("/")
    public Mono<Test> getTest() {
        Test test = new Test();
        test.name = "hello";
        return Mono.just(test);
    }

    @PostMapping("/")
    public Mono<Test> getTest(@RequestBody final Test test) {
        return Mono.just(test);
    }
}

public class Test {
    @NotNull
    public String name;
}

Request body :

{
  "name": "Pascal"
}

Server stack trace

23-03-2018 11:47:53.873 [XNIO-1 I/O-3] ERROR io.undertow.request.executeRootHandler - UT005071: Undertow request failed HttpServerExchange{ POST / request {accept=[*/*], accept-encoding=[gzip, deflate], user-agent=[nghttp2/1.31.0], content-length=[23], Host=[localhost:8443]} response HttpServerExchange{ POST / request {accept=[*/*], accept-encoding=[gzip, deflate], user-agent=[nghttp2/1.31.0], content-length=[23], Host=[localhost:8443]} response {}}}
java.lang.StackOverflowError: null
	at io.undertow.server.protocol.framed.AbstractFramedStreamSourceChannel.read(AbstractFramedStreamSourceChannel.java:496)
	at io.undertow.protocols.http2.Http2StreamSourceChannel.read(Http2StreamSourceChannel.java:147)
	at org.xnio.conduits.StreamSourceChannelWrappingConduit.read(StreamSourceChannelWrappingConduit.java:43)
	at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127)
	at io.undertow.channels.DetachableStreamSourceChannel.read(DetachableStreamSourceChannel.java:209)
	at io.undertow.server.HttpServerExchange$ReadDispatchChannel.read(HttpServerExchange.java:2332)
	at org.springframework.http.server.reactive.UndertowServerHttpRequest$RequestBodyPublisher.read(UndertowServerHttpRequest.java:172)
	at org.springframework.http.server.reactive.UndertowServerHttpRequest$RequestBodyPublisher.read(UndertowServerHttpRequest.java:128)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.readAndPublish(AbstractListenerReadPublisher.java:145)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.access$1000(AbstractListenerReadPublisher.java:47)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher$State$4.onDataAvailable(AbstractListenerReadPublisher.java:317)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.onDataAvailable(AbstractListenerReadPublisher.java:85)
	at org.springframework.http.server.reactive.UndertowServerHttpRequest$RequestBodyPublisher.checkOnDataAvailable(UndertowServerHttpRequest.java:156)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.changeToDemandState(AbstractListenerReadPublisher.java:177)
	[... SAME STACK TRACE OVER HUNDRED TIMES ...]
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.access$900(AbstractListenerReadPublisher.java:47)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher$State$4.onDataAvailable(AbstractListenerReadPublisher.java:319)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.onDataAvailable(AbstractListenerReadPublisher.java:85)
	at org.springframework.http.server.reactive.UndertowServerHttpRequest$RequestBodyPublisher.checkOnDataAvailable(UndertowServerHttpRequest.java:156)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.changeToDemandState(AbstractListenerReadPublisher.java:177)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.access$900(AbstractListenerReadPublisher.java:47)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher$State$4.onDataAvailable(AbstractListenerReadPublisher.java:319)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.onDataAvailable(AbstractListenerReadPublisher.java:85)
	at org.springframework.http.server.reactive.UndertowServerHttpRequest$RequestBodyPublisher.checkOnDataAvailable(UndertowServerHttpRequest.java:156)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.changeToDemandState(AbstractListenerReadPublisher.java:177)

After this error log, two new logs are written (client have already received a status code 500 at this moment), it seems only to be a side effect of the error, but we can clearly see that the problem is related to the request body, which is missing because of the previous error

23-03-2018 12:30:19.210 [XNIO-1 I/O-3] WARN  o.s.b.a.w.r.e.DefaultErrorWebExceptionHandler.log - Failed to handle request [POST https://localhost:8443/]: Response status 400 with reason "Request body is missing: public reactor.core.publisher.Mono<com.necoutezpas.springboottest.model.Test> com.necoutezpas.springboottest.controller.Example.getTest(com.necoutezpas.springboottest.model.Test)"
23-03-2018 12:30:19.242 [XNIO-1 I/O-3] ERROR o.s.w.s.a.HttpWebHandlerAdapter.handleFailure - Failed to handle request [POST https://localhost:8443/]
java.lang.IllegalStateException: UT000002: The response has already been started
	at io.undertow.server.HttpServerExchange.setStatusCode(HttpServerExchange.java:1406)
	at org.springframework.http.server.reactive.UndertowServerHttpResponse.applyStatusCode(UndertowServerHttpResponse.java:79)
	at org.springframework.http.server.reactive.AbstractServerHttpResponse.lambda$doCommit$4(AbstractServerHttpResponse.java:213)
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
	at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
	at org.springframework.http.server.reactive.AbstractServerHttpResponse.doCommit(AbstractServerHttpResponse.java:225)
	at org.springframework.http.server.reactive.AbstractServerHttpResponse.lambda$writeWith$1(AbstractServerHttpResponse.java:176)
	at org.springframework.http.server.reactive.ChannelSendOperator$WriteBarrier.onNext(ChannelSendOperator.java:158)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:115)
	at reactor.core.publisher.FluxJust$WeakScalarSubscription.request(FluxJust.java:91)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:156)
	at org.springframework.http.server.reactive.ChannelSendOperator$WriteBarrier.onSubscribe(ChannelSendOperator.java:140)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:90)
	at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68)
	at reactor.core.publisher.FluxMapFuseable.subscribe(FluxMapFuseable.java:63)
	at org.springframework.http.server.reactive.ChannelSendOperator.subscribe(ChannelSendOperator.java:74)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150)
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1069)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:198)
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:1626)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.request(FluxPeekFuseable.java:138)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onSubscribe(MonoFlatMap.java:230)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onSubscribe(FluxPeekFuseable.java:172)
	at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)
	at reactor.core.publisher.MonoPeekFuseable.subscribe(MonoPeekFuseable.java:74)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:1626)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:1440)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:1314)
	at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.Mono.subscribe(Mono.java:3080)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
	at reactor.core.publisher.Operators.complete(Operators.java:125)
	at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
	at reactor.core.publisher.MonoSwitchIfEmpty.subscribe(MonoSwitchIfEmpty.java:44)
	at reactor.core.publisher.MonoSwitchIfEmpty.subscribe(MonoSwitchIfEmpty.java:44)
	at reactor.core.publisher.MonoFlatMap.subscribe(MonoFlatMap.java:60)
	at reactor.core.publisher.MonoFlatMap.subscribe(MonoFlatMap.java:60)
	at reactor.core.publisher.Mono.subscribe(Mono.java:3080)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:97)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onError(MonoFlatMap.java:165)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:185)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:251)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:100)
	at reactor.core.publisher.Operators.error(Operators.java:175)
	at reactor.core.publisher.MonoError.subscribe(MonoError.java:52)
	at reactor.core.publisher.Mono.subscribe(Mono.java:3080)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:97)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onError(FluxPeekFuseable.java:222)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onError(FluxPeekFuseable.java:222)
	at reactor.core.publisher.Operators$MonoSubscriber.onError(Operators.java:1112)
	at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onError(MonoIgnoreThen.java:300)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onError(MonoFlatMap.java:165)
	at reactor.core.publisher.MonoZip$ZipInner.onError(MonoZip.java:337)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:207)
	at reactor.core.publisher.Operators$MonoSubscriber.onError(Operators.java:1112)
	at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:87)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onError(Operators.java:1309)
	at reactor.core.publisher.Operators.error(Operators.java:175)
	at reactor.core.publisher.MonoError.subscribe(MonoError.java:52)
	at reactor.core.publisher.Mono.subscribe(Mono.java:3080)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:75)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:245)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher$State.onAllDataRead(AbstractListenerReadPublisher.java:392)
	at org.springframework.http.server.reactive.AbstractListenerReadPublisher.onAllDataRead(AbstractListenerReadPublisher.java:94)
	at org.springframework.http.server.reactive.UndertowServerHttpRequest$RequestBodyPublisher.lambda$registerListeners$0(UndertowServerHttpRequest.java:144)
	at io.undertow.server.HttpServerExchange.invokeExchangeCompleteListeners(HttpServerExchange.java:1276)
	at io.undertow.server.HttpServerExchange.terminateResponse(HttpServerExchange.java:1558)
	at io.undertow.server.Connectors.terminateResponse(Connectors.java:143)
	at io.undertow.server.protocol.http2.Http2ReceiveListener$3.handleEvent(Http2ReceiveListener.java:189)
	at io.undertow.server.protocol.http2.Http2ReceiveListener$3.handleEvent(Http2ReceiveListener.java:186)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at io.undertow.protocols.http2.Http2DataStreamSinkChannel.flush(Http2DataStreamSinkChannel.java:292)
	at org.xnio.conduits.StreamSinkChannelWrappingConduit.flush(StreamSinkChannelWrappingConduit.java:123)
	at org.xnio.conduits.ConduitStreamSinkChannel.flush(ConduitStreamSinkChannel.java:162)
	at io.undertow.channels.DetachableStreamSinkChannel.flush(DetachableStreamSinkChannel.java:119)
	at io.undertow.server.HttpServerExchange.closeAndFlushResponse(HttpServerExchange.java:1714)
	at io.undertow.server.HttpServerExchange.access$000(HttpServerExchange.java:92)
	at io.undertow.server.HttpServerExchange$2.handleEvent(HttpServerExchange.java:1655)
	at io.undertow.server.HttpServerExchange$2.handleEvent(HttpServerExchange.java:1651)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at org.xnio.ChannelListeners$DrainListener.handleEvent(ChannelListeners.java:1145)
	at org.xnio.ChannelListeners$DrainListener.handleEvent(ChannelListeners.java:1125)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at io.undertow.channels.DetachableStreamSourceChannel$SetterDelegatingListener.handleEvent(DetachableStreamSourceChannel.java:231)
	at io.undertow.channels.DetachableStreamSourceChannel$SetterDelegatingListener.handleEvent(DetachableStreamSourceChannel.java:218)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at org.xnio.conduits.ReadReadyHandler$ChannelListenerHandler.readReady(ReadReadyHandler.java:66)
	at org.xnio.conduits.StreamSourceChannelWrappingConduit$1.handleEvent(StreamSourceChannelWrappingConduit.java:85)
	at org.xnio.conduits.StreamSourceChannelWrappingConduit$1.handleEvent(StreamSourceChannelWrappingConduit.java:83)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at io.undertow.server.protocol.framed.AbstractFramedStreamSourceChannel$1.run(AbstractFramedStreamSourceChannel.java:282)
	at io.undertow.server.protocol.framed.AbstractFramedChannel$FrameReadListener.handleEvent(AbstractFramedChannel.java:929)
	at io.undertow.server.protocol.framed.AbstractFramedChannel$FrameReadListener.handleEvent(AbstractFramedChannel.java:923)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at org.xnio.conduits.ReadReadyHandler$ChannelListenerHandler.readReady(ReadReadyHandler.java:66)
	at io.undertow.protocols.ssl.SslConduit$SslReadReadyHandler.readReady(SslConduit.java:1145)
	at io.undertow.protocols.ssl.SslConduit$1.run(SslConduit.java:168)
	at org.xnio.nio.WorkerThread.safeRun(WorkerThread.java:582)
	at org.xnio.nio.WorkerThread.run(WorkerThread.java:466)

Client trace

nghttp -v --data=test.json https://localhost:8443
[  0.012] Connected
[WARNING] Certificate verification failed: self signed certificate
The negotiated protocol: h2
[  0.133] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.133] send PRIORITY frame <length=5, flags=0x00, stream_id=3>
          (dep_stream_id=0, weight=201, exclusive=0)
[  0.133] send PRIORITY frame <length=5, flags=0x00, stream_id=5>
          (dep_stream_id=0, weight=101, exclusive=0)
[  0.133] send PRIORITY frame <length=5, flags=0x00, stream_id=7>
          (dep_stream_id=0, weight=1, exclusive=0)
[  0.133] send PRIORITY frame <length=5, flags=0x00, stream_id=9>
          (dep_stream_id=7, weight=1, exclusive=0)
[  0.133] send PRIORITY frame <length=5, flags=0x00, stream_id=11>
          (dep_stream_id=3, weight=1, exclusive=0)
[  0.133] send HEADERS frame <length=43, flags=0x24, stream_id=13>
          ; END_HEADERS | PRIORITY
          (padlen=0, dep_stream_id=11, weight=16, exclusive=0)
          ; Open new stream
          :method: POST
          :path: /
          :scheme: https
          :authority: localhost:8443
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.31.0
          content-length: 23
[  0.133] send DATA frame <length=23, flags=0x01, stream_id=13>
          ; END_STREAM
[  0.139] recv SETTINGS frame <length=24, flags=0x00, stream_id=0>
          (niv=4)
          [SETTINGS_HEADER_TABLE_SIZE(0x01):4096]
          [SETTINGS_MAX_FRAME_SIZE(0x05):16384]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):1000]
[  0.139] send SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.139] recv SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.256] recv (stream_id=13) :status: 500
[  0.256] recv (stream_id=13, sensitive) content-length: 0
[  0.256] recv (stream_id=13, sensitive) date: Fri, 23 Mar 2018 10:58:58 GMT
[  0.256] recv HEADERS frame <length=30, flags=0x05, stream_id=13>
          ; END_STREAM | END_HEADERS
          (padlen=0)
          ; First response header
[  0.256] send GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=0, error_code=NO_ERROR(0x00), opaque_data(0)=[])

Am I missing something or misconfiguring something?

Please note that I enable h2c in the UndertowConfig configuration class.
But the bug does not seem related since removing it does not fix the problem

---

Affects: 5.0.4

Reference URL: https://github.com/plelevier/spring-boot2-tests

Issue Links:

• StackOverflowError when using WebFlux multipart file data handler with Undertow [SPR-16545] #21088 StackOverflowError when using WebFlux multipart file data handler with Undertow ("duplicates")

[spring-projects-issues]

Sébastien Deleuze commented

Based on my tests with the provided repro project, this commit from #21088 also fixes this issue.