Vertx Reactive routes not working with HTTP2 and POST methods

chevaris commented 1 year ago

Describe the bug

I have implemented a Reactive REST endpoint that exposes POST HTTP method. The implementation includes a Vertx Route that is applied to POST method calls and the endpoint path.

@Path("/hello")
public class GreetingResource {

    @POST
    @Produces(MediaType.APPLICATION_JSON)
    public Uni<QueryResponse> query(final HttpHeaders reqHeaders, final Query query) {
        QueryResponse queryRespose = new QueryResponse();
        queryRespose.message = "Hello from RESTEasy Reactive " + query.name;
        return Uni.createFrom().item(queryRespose);
    }
}

@Singleton
public class OverloadRoute {

  private static final Logger LOG = Logger.getLogger(OverloadRoute.class);

  @Route(methods = HttpMethod.POST, path = "/hello")
  public void post(RoutingContext rc) {

    rc.next();
    LOG.info("here");
  }
}

When sending an HTTP 1.1 request it works fine

curl  -d '{"name": "juan"}'  -H "Content-Type: application/json"    -X POST  http://localhost:8080/hello

the result is

{"message":"Hello from RESTEasy Reactive juan"}

When sending with HTTP 2 (clear text) it does throw an exception

curl --http2 -d '{"name": "juan"}'  -H "Content-Type: application/json"    -X POST  http://localhost:8080/hello

the following exception is thrown:

2023-06-29 13:34:14,153 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-0) HTTP Request to /hello failed, error id: 1ff2eb50-7fa0-4a52-8541-b359563a6d0a-1: java.lang.IllegalStateException: Request has already been read
        at io.vertx.core.http.impl.Http2ServerRequest.checkEnded(Http2ServerRequest.java:217)
        at io.vertx.core.http.impl.Http2ServerRequest.pause(Http2ServerRequest.java:269)
        at io.quarkus.vertx.http.runtime.ResumingRequestWrapper.pause(ResumingRequestWrapper.java:30)
        at io.vertx.core.http.impl.HttpServerRequestWrapper.pause(HttpServerRequestWrapper.java:67)
        at io.vertx.core.http.impl.HttpServerRequestWrapper.pause(HttpServerRequestWrapper.java:67)
        at org.jboss.resteasy.reactive.server.vertx.VertxResteasyReactiveRequestContext.<init>(VertxResteasyReactiveRequestContext.java:83)
        at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.<init>(QuarkusResteasyReactiveRequestContext.java:31)
        at io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder$5.createContext(ResteasyReactiveRecorder.java:174)
        at org.jboss.resteasy.reactive.server.handlers.RestInitialHandler.beginProcessing(RestInitialHandler.java:45)
        at org.jboss.resteasy.reactive.server.vertx.ResteasyReactiveVertxHandler.handle(ResteasyReactiveVertxHandler.java:23)
        at org.jboss.resteasy.reactive.server.vertx.ResteasyReactiveVertxHandler.handle(ResteasyReactiveVertxHandler.java:10)
        at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
        at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
        at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
        at org.acme.OverloadRoute.get(OverloadRoute.java:18)
        at org.acme.OverloadRoute_RouteHandler_get_1a9f4d138a4ed3dbe3b937adf723bc32eb42ec9f.invoke(Unknown Source)
        at io.quarkus.vertx.web.runtime.RouteHandler.handle(RouteHandler.java:97)
        at io.quarkus.vertx.web.runtime.RouteHandler.handle(RouteHandler.java:22)
        at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
        at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:140)
        at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
        at io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.doEnd(BodyHandlerImpl.java:361)
        at io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.end(BodyHandlerImpl.java:338)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:246)
        at io.vertx.core.http.impl.HttpEventHandler.handleEnd(HttpEventHandler.java:76)
        at io.vertx.core.http.impl.Http2ServerRequest.handleEnd(Http2ServerRequest.java:198)
        at io.vertx.core.http.impl.Http2ServerStream.handleEnd(Http2ServerStream.java:198)
        at io.vertx.core.http.impl.VertxHttp2Stream.lambda$new$1(VertxHttp2Stream.java:62)
        at io.vertx.core.streams.impl.InboundBuffer.handleEvent(InboundBuffer.java:255)
        at io.vertx.core.streams.impl.InboundBuffer.drain(InboundBuffer.java:242)
        at io.vertx.core.streams.impl.InboundBuffer.lambda$fetch$0(InboundBuffer.java:295)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:246)
        at io.vertx.core.impl.EventLoopContext.lambda$runOnContext$0(EventLoopContext.java:43)
        at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:1583)

There are no issues when route is not included

Expected behavior

Both HTTP 1.1 and HTTP2 should work the same and provide the right output (200 OK and the response JSON)

Actual behavior

HTTP 2 does not work (HTTP status code 500)

How to Reproduce?

code-with-quarkus.zip

unzip reproducer

start in dev mode mvn quearkus:dev

Query with HTTP2 curl --http2 -d '{"name": "juan"}' -H "Content-Type: application/json" -X POST http://localhost:8080/hello

Query with HTTP1/1 curl -d '{"name": "juan"}' -H "Content-Type: application/json" -X POST http://localhost:8080/hello

Output of `uname -a` or `ver`

Linux cheva-virtualmachine 5.15.112-1-MANJARO #1 SMP PREEMPT Wed May 17 11:11:32 UTC 2023 x86_64 GNU/Linux

Output of `java -version`

openjdk version "17.0.7" 2023-04-18 OpenJDK Runtime Environment (build 17.0.7+7) OpenJDK 64-Bit Server VM (build 17.0.7+7, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.1.2.Final

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

Apache Maven 3.8.7 (b89d5959fcde851dcb1c8946a785a163f14e1e29) Maven home: /opt/maven Java version: 17.0.7, vendor: N/A, runtime: /usr/lib/jvm/java-17-openjdk Default locale: en_US, platform encoding: UTF-8 OS name: "linux", version: "5.15.112-1-manjaro", arch: "amd64", family: "unix"

Additional information

No response

geoand commented 1 year ago

cc @mkouba @cescoffier

cescoffier commented 1 year ago

we will need to debug, but I suspect that the body has been already read by Resteasy reactive. What I don't get is why it's different with HTTP 1.1. I don't see pipelining in the descriptor.

mkouba commented 1 year ago

It seems that the io.vertx.core.http.impl.Http1xServerRequest.pause() method does not call checkEnded() but io.vertx.core.http.impl.Http2ServerRequest.pause() does...

cescoffier commented 1 year ago

good catch @mkouba ! (maybe it should not work with HTTP 1.1 after all :-D)

@vietj any idea?

chevaris commented 1 year ago

I tested with a GET endpoint and if I remember well it worked fine

mkouba commented 1 year ago

I tested with a GET endpoint and if I remember well it worked fine

Hm yes, because for GET there's no request body that must be read... it could be that for HTTP2 it's not possible to read the body and then call Http2ServerRequest.pause().

chevaris commented 1 year ago

I tested with a @RouteFilter and works fine for both HTTP 1.1 and HTTP2. This is fine for my use case, because basically I am after intercepting the query and rejecting it under certain circunstances (overload)

Still it is hard for me to assess if the what I explained in the bug (using a @Route) should work or NOT. I was reading Quarkus documentation again, and my understanding is that Routes can mixed with REST Easy. Anyhow looks not consistent that HTTP 1.1 and HTTP2 show different behaviour (leading to confusion). I think you can decide better than me if the bug should be kept open and requires some fixing or not

mkouba commented 1 year ago

I tested with a @RouteFilter and works fine for both HTTP 1.1 and HTTP2. This is fine for my use case, because basically I am after intercepting the query and rejecting it under certain circunstances (overload)

Yes, @RouteFilters do not have a body handler attached.

Still it is hard for me to assess if the what I explained in the bug (using a @route) should work or NOT. I was reading Quarkus documentation again, and my understanding is that Routes can mixed with REST Easy. Anyhow looks not consistent that HTTP 1.1 and HTTP2 show different behaviour (leading to confusion). I think you can decide better than me if the bug should be kept open and requires some fixing or not

We will definitely need a Vert.x expert here...

vietj commented 1 year ago

I think the main difference comes from the fact that with HTTP/1 we have two HTTP messages and with HTTP/2 we only get one HEADERS frame with the flag ended=true, the request might be paused too late in the case of HTTP/2.

I suggest adding a breakpoint in the pause method of HttpServerRequest and in the end handler callback and check the sequentiality of the events to be sure.

mkouba commented 1 year ago

Ok, so the sequence seems to be:

1.

Thread [vert.x-eventloop-thread-0] (Suspended (breakpoint at line 268 in Http2ServerRequest))   
    owns: Http2ServerConnection  (id=265)   
    Http2ServerRequest.pause() line: 268    
    VertxHttpRecorder$1.handle(HttpServerRequest) line: 177 
    VertxHttpRecorder$1.handle(Object) line: 156    
    EventLoopContext.emit(ContextInternal, T, Handler<T>) line: 55  
    DuplicatedContext.emit(T, Handler<T>) line: 158 
    Http2ServerRequest.dispatch(Handler<HttpServerRequest>) line: 108   
    Http2ServerStream.onHeaders(Http2Headers, StreamPriority) line: 111 
    Http2ServerConnection.onHeadersRead(int, Http2Headers, StreamPriority, boolean) line: 171   
    Http2ServerConnection(Http2ConnectionBase).onHeadersRead(ChannelHandlerContext, int, Http2Headers, int, boolean) line: 213  
    Http2ServerConnection.onHeadersRead(ChannelHandlerContext, int, Http2Headers, int, boolean) line: 44

2.

Thread [vert.x-eventloop-thread-0] (Suspended (breakpoint at line 75 in HttpEventHandler))  
    HttpEventHandler.handleEnd() line: 75   
    Http2ServerRequest.handleEnd(MultiMap) line: 198    
    Http2ServerStream.handleEnd(MultiMap) line: 198 
    Http2ServerStream(VertxHttp2Stream<C>).lambda$new$1(Http2ConnectionBase, Object) line: 62   
    0x00000008017375a0.handle(Object) line: not available   
    InboundBuffer<E>.handleEvent(Handler<T>, T) line: 255   
    InboundBuffer<E>.drain() line: 242  
    InboundBuffer<E>.lambda$fetch$0(Void) line: 295 
    0x000000080174fa38.handle(Object) line: not available   
    DuplicatedContext(ContextInternal).dispatch(E, Handler<E>) line: 264    
    DuplicatedContext(ContextInternal).dispatch(Handler<Void>) line: 246

3.

Thread [vert.x-eventloop-thread-0] (Suspended (breakpoint at line 268 in Http2ServerRequest))   
    Http2ServerRequest.pause() line: 268    
    ResumingRequestWrapper.pause() line: 30 
    QuarkusRequestWrapper(HttpServerRequestWrapper).pause() line: 67    
    HttpServerRequestWrapper(HttpServerRequestWrapper).pause() line: 67 
    QuarkusResteasyReactiveRequestContext(VertxResteasyReactiveRequestContext).<init>(Deployment, RoutingContext, ThreadSetupAction, ServerRestHandler[], ServerRestHandler[], ClassLoader) line: 83    
    QuarkusResteasyReactiveRequestContext.<init>(Deployment, RoutingContext, ThreadSetupAction, ServerRestHandler[], ServerRestHandler[], ClassLoader, CurrentIdentityAssociation) line: 31 
    ResteasyReactiveRecorder$5.createContext(Deployment, Object, ThreadSetupAction, ServerRestHandler[], ServerRestHandler[]) line: 174 
    RestInitialHandler.beginProcessing(Object) line: 45 
    ResteasyReactiveVertxHandler.handle(RoutingContext) line: 23    
    ResteasyReactiveVertxHandler.handle(Object) line: 10    
    RouteState.handleContext(RoutingContextImplBase) line: 1284 
    RoutingContextImpl(RoutingContextImplBase).iterateNext() line: 177  
    RoutingContextImpl.next() line: 141

vietj commented 1 year ago

Something called fetch in step 2 : InboundBuffer<E>.lambda$fetch$0(Void) which triggers the event to be sent.

mkouba commented 1 year ago

Something called fetch in step 2 : InboundBuffer<E>.lambda$fetch$0(Void) which triggers the event to be sent.

Yes, it was called here: https://github.com/quarkusio/quarkus/blob/3.1.2.Final/extensions/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/VertxHttpRecorder.java#L1408

Thread [vert.x-eventloop-thread-0] (Suspended (breakpoint at line 295 in InboundBuffer))    
    owns: Http2ServerConnection  (id=160)   
    InboundBuffer<E>.fetch(long) line: 295  
    Http2ServerStream(VertxHttp2Stream<C>).doFetch(long) line: 160  
    Http2ServerRequest.fetch(long) line: 284    
    Http2ServerRequest.resume() line: 277   
    ResumingRequestWrapper.resume() line: 37    
    QuarkusRequestWrapper(HttpServerRequestWrapper).resume() line: 72   
    HttpServerRequestWrapper(HttpServerRequestWrapper).resume() line: 72    
    VertxHttpRecorder$16.handle(RoutingContext) line: 1408  <<<<<<<<<<<<<<<<<<<<<<<<<<
    VertxHttpRecorder$16.handle(Object) line: 1382  
    RouteState.handleContext(RoutingContextImplBase) line: 1284 
    RoutingContextImpl(RoutingContextImplBase).iterateNext() line: 177  
    RoutingContextImpl.next() line: 141 
    HttpServerCommonHandlers$1.handle(RoutingContext) line: 58  
    HttpServerCommonHandlers$1.handle(Object) line: 36  
    RouteState.handleContext(RoutingContextImplBase) line: 1284 
    RoutingContextImpl(RoutingContextImplBase).iterateNext() line: 177  
    RoutingContextImpl.next() line: 141 
    ResteasyReactiveRecorder$13.handle(RoutingContext) line: 380    
    ResteasyReactiveRecorder$13.handle(Object) line: 373    
    RouteState.handleContext(RoutingContextImplBase) line: 1284

cescoffier commented 1 year ago

Hum, we have this code which may be problematic with HTTP/2:

return new Handler<RoutingContext>() {
            @Override
            public void handle(RoutingContext event) {
                if (!Context.isOnEventLoopThread()) {
                    ((ConnectionBase) event.request().connection()).channel().eventLoop().execute(new Runnable() {
                        @Override
                        public void run() {
                            try {
                                //this can happen if blocking authentication is involved for get requests
                                if (!event.request().isEnded()) {
                                    event.request().resume();
                                    if (CAN_HAVE_BODY.contains(event.request().method())) {
                                        bodyHandler.handle(event);
                                    } else {
                                        event.next();
                                    }
                                } else {
                                    event.next();
                                }
                            } catch (Throwable t) {
                                event.fail(t);
                            }
                        }
                    });
                } else {
                    if (!event.request().isEnded()) {
                        event.request().resume();
                    }
                    if (CAN_HAVE_BODY.contains(event.request().method())) {
                        bodyHandler.handle(event);
                    } else {
                        event.next();
                    }
                }
            }
        };

mkouba commented 1 year ago

CC @stuartwdouglas

stuartwdouglas commented 1 year ago

So this is kinda yuck, but the code is intended to deal with blocking security providers by dispatching them back to the IO thread. Normally HTTP requests are resumed, so this code path also resumes so that downstream code should all work the same way.

mkouba commented 1 year ago

Hm, the fetch is triggered by event.request().resume() which is executed in the else branch, i.e. when Context.isOnEventLoopThread() == true. In any case, I have no idea how this works so I can't really help here :shrug:.

vietj commented 1 year ago

The question is : why does the code tries to pause the request while it has been read fully already ?

mkouba commented 1 year ago

The question is : why does the code tries to pause the request while it has been read fully already ?

@geoand maybe knows?

geoand commented 1 year ago

I don't remember, I would need to check

cescoffier commented 1 year ago

I need to check what it breaks (because I'm sure it will), but there is an unconditional call to pause when RestEasy reactive creates its context. This method is called from the event loop, thus, we can safely check if the request has been read (isEnded()) before calling pause()

stuartwdouglas commented 1 year ago

@cescoffier what you are proposing sounds safe. We always pause before dispatching to a worker thread so that you don't receive IO events on the IO thread at the same time and end up with two threads working on the request. The assumption would have been that calling pause() after everything was read was a noop, which sounds like an incorrect assumption.

cescoffier commented 1 year ago

Unfortunately, that's not enough. Once I do that (which I believe is correct), resume is called, while the request is not paused. I would need more time to dig into that (so, won't be this week).

quarkusio / quarkus