Quarkus: Concurrent requests result in IllegalStateException: Request has already been read

[rvansa]

Describe the bug
I have a service annotated like this:

   @RolesAllowed("tester")
   @POST
   @Path("extractor")
   @Consumes(MediaType.APPLICATION_JSON)
   @Transactional
   public Response addOrUpdateExtractor(Json json) { ... }

The permissions are checked using OIDC to Keycloak instance (if this matters). When firing 6 concurrent requests to this endpoint (from browser) most of them fail with status 400 and body java.lang.IllegalStateException: Request has already been read. There's nothing in the server log. Sometimes some of these requests succeed (I've repeated this couple of times).

Expected behavior
All request run independently.

Configuration
Connected over TLS, negotiated to use HTTP 2.0. OIDC runs over TLS as well.

Environment (please complete the following information):

• Output of java -version: openjdk version "11.0.5" 2019-10-15
• GraalVM version (if different from Java):
• Quarkus version or git rev: master (f90e910b014f34354d7927031e91e197bc203ea7)

Additional context
Looks like a dupe of https://github.com/vert-x3/vertx-web/issues/729 though here we're using Vert.x 3.9.2

[sberyozkin]

@rvansa
There have been a few issues related to Request has already been read.
Can you please try to narrow down to where this exception is thrown from ?
Please also try Quarkus 1.7.0.Final unless you are already using it.
Reproducer can help too. CC @stuartwdouglas

[rvansa]

@sberyozkin I don't see that as an exception thrown - java.lang.IllegalStateException: Request has already been read is only written in the response body.
I am running on master (with fix for https://github.com/quarkusio/quarkus/pull/11596) already.
I'll see if I can set an exception breakpoint in my dev environment.

[rvansa]

Hmm, I can't reproduce this in dev setup which is running over plaintext HTTP 1.1 (OIDC over plaintext, too).

[sberyozkin]

@rvansa Have you done these concurrent tests before or is it the 1st time you have done them ? i wonder if it can make sense to isolate the Vertx 3.9.2 update back to 3.9.1 and see if it makes a difference. A few similar issues have been reported specifically against quarkus-keycloak-authorization

[stuartwdouglas]

Maybe we have an SSL issue, but I created https://github.com/quarkusio/quarkus/pull/11629 and ran it locally and there was no issues.

This is not quite the same, as it is not OIDC auth and requests are not run concurrently, but basically just changes the existing tests we had for this problem to use SSL.

[rvansa]

@sberyozkin I haven't really tried that before, I don't think it makes sense to check old versions.

@stuartwdouglas I would be also surprised if this would be failing in the general case; There's certainly been tons of performance tests with TLS hitting the same endpoint. That's also why I've stressed out OIDC. Another thing worth mention would be that the request body (Json) is converted using a custom JsonbDeserializer (nothing fancy about that, though).

It seems I'll have to set up TLS locally and test if I could reproduce.

[sberyozkin]

@rvansa thanks, you are right. Indeed, having some reproducer would be good, even trying to comment out JsonbDeserializer, etc

[rvansa]

So I've been able to reproduce this locally quite reliably. The triggering factor might not be TLS per se but HTTP2 negotiated when TLS is in use.
It seems that this happens when our custom MessageBodyReader.readFrom(...) invokes entityStream.lines().collect(...). This is the stack trace:

checkEnded:215, Http2ServerRequestImpl (io.vertx.core.http.impl)
fetch:255, Http2ServerRequestImpl (io.vertx.core.http.impl)
fetch:42, ResumingRequestWrapper (io.quarkus.vertx.http.runtime)
fetch:97, HttpServerRequestWrapper (io.vertx.ext.web.impl)
readBlocking:487, VertxHttpExchange (io.undertow.vertx)
readBlocking:937, HttpServerExchange (io.undertow.server)
readIntoBuffer:178, ServletInputStreamImpl (io.undertow.servlet.spec)
read:158, ServletInputStreamImpl (io.undertow.servlet.spec)
readBytes:284, StreamDecoder (sun.nio.cs)
implRead:326, StreamDecoder (sun.nio.cs)
read:178, StreamDecoder (sun.nio.cs)
read:184, InputStreamReader (java.io)
fill:161, BufferedReader (java.io)
readLine:324, BufferedReader (java.io)
readLine:389, BufferedReader (java.io)
hasNext:571, BufferedReader$1 (java.io)
forEachRemaining:115, Iterator (java.util)
forEachRemaining:1801, Spliterators$IteratorSpliterator (java.util)
copyInto:482, AbstractPipeline (java.util.stream)
wrapAndCopyInto:472, AbstractPipeline (java.util.stream)
evaluateSequential:708, ReduceOps$ReduceOp (java.util.stream)
evaluate:234, AbstractPipeline (java.util.stream)
collect:566, ReferencePipeline (java.util.stream)
readFrom:41, JsonProvider (io.hyperfoil.tools.horreum.entity.converter)
... rest of stack truncated ...

Note that I am sending a JSON with no line at the end. What happens here is that VertxHttpExchange.readBlocking is called twice: the first time input1 != null so the loop is skipped, input1 is set to null and returned and request.fetch(1) is invoked.
The second time VertxHttpExchange.readBlocking is invoked with input1 == null, we enter the loop (eof is false), wait until the connection is drained (setting eof and Http2ServerRequestImpl.end to true) and therefore the loop is exited, however calling request.fetch(1); again. Since the Http2ServerRequestImpl.end is true now the call results in an exception.

I don't know the code and its intentions so I can't say what part should be fixed (or file a PR) but I guess that guarding the request.fetch(1) with if (!request.isEnded()) ... would help.

[rvansa]

@stuartwdouglas It would be great if you could check my findings above.

I've used quarkus 1.8.2, vert.x 3.9.1 and quarkus-http-vertx-backend 3.0.15 to reproduce this.

[stuartwdouglas]

Can you test out https://github.com/quarkusio/quarkus-http/pull/44

[rvansa]

@stuartwdouglas Yes, that works for me. Thanks!