Quarkus: Keycloak with Reactive Routes Error: Request has already been read

Created on 27 Nov 2019  路  28Comments  路  Source: quarkusio/quarkus

I've tried to run a quarkus with keyckoak policy enforcer and reactive routes (no resteasy at all). It fails with the following error:
ERROR: HTTP Request to /fhir/test failed, error id: f92ad12f-7a15-4fc4-b1cd-7d99ab09df0d-1 java.lang.IllegalStateException: Request has already been read
at io.vertx.core.http.impl.HttpServerRequestImpl.checkEnded(HttpServerRequestImpl.java:600)
at io.vertx.core.http.impl.HttpServerRequestImpl.handler(HttpServerRequestImpl.java:307)

This is my config:

quarkus.keycloak.policy-enforcer.enable=true
quarkus.keycloak.policy-enforcer.enforcement-mode=PERMISSIVE
quarkus.keycloak.policy-enforcer.path-cache.lifespan=36000000
quarkus.keycloak.policy-enforcer.paths.0.path=${quarkus.http.root-path}/test
quarkus.keycloak.policy-enforcer.paths.0.enforcement-mode=DISABLED
quarkus.keycloak.policy-enforcer.paths.999.path=/*
quarkus.keycloak.policy-enforcer.paths.999.enforcement-mode=ENFORCING

The paths where it fails is the path disabled for policy enforcing. I guess the same error will occur and for secured paths

Sample project : keycloak-with-reactive-routes-error

areoidc kinbug triagrequires-stuart
Source
picture tpenakov

All 28 comments

@tpenakov any chance you could put together a small reproducer?

gsmet picture gsmet on 27 Nov 2019

No problem - added in bug description.

tpenakov picture tpenakov on 27 Nov 2019

CC @pedroigor @stianst

sberyozkin picture sberyozkin on 27 Nov 2019

@tpenakov Can you please confirm that disabling the policy enforcer 'fixes' it ?

sberyozkin picture sberyozkin on 27 Nov 2019

Hi @sberyozkin ,
You mean this:
quarkus.keycloak.policy-enforcer.enable=false
Right?
Now I've got NPE:
Nov 27, 2019 6:13:40 PM io.quarkus.vertx.http.runtime.QuarkusErrorHandler handle
ERROR: HTTP Request to /fhir/test failed, error id: d7186528-0b82-4a0f-91ae-fe2f731f2edd-1
java.lang.NullPointerException
at io.quarkus.keycloak.pep.KeycloakPolicyEnforcerAuthorizer.apply(KeycloakPolicyEnforcerAuthorizer.java:44)
at io.quarkus.keycloak.pep.KeycloakPolicyEnforcerAuthorizer.apply(KeycloakPolicyEnforcerAuthorizer.java:28)
at io.quarkus.vertx.http.runtime.security.HttpAuthorizer$1$1.run(HttpAuthorizer.java:65)

tpenakov picture tpenakov on 27 Nov 2019

@tpenakov well, at least we'll fix several issues around it :-), thanks

sberyozkin picture sberyozkin on 27 Nov 2019

@sberyozkin @tpenakov The NPE should not happen anymore in latest releases due to this fix https://github.com/quarkusio/quarkus/pull/5456.

Not sure about the route though, need to investigate.

pedroigor picture pedroigor on 29 Nov 2019
👍1

@tpenakov Can you please try with Quarkus 1.1.0.CR1 ? There were some possibly related updates to this extension.

sberyozkin picture sberyozkin on 12 Dec 2019

@sberyozkin - do I need to add some repositories to my pom.xml?
I've got this error so far:
[ERROR] Non-resolvable import POM: Failure to find io.quarkus:quarkus-universe-bom:pom:1.1.0.CR1 in https://repo.maven.apache.org/maven2

Also I am unable to create a project:

mvn io.quarkus:quarkus-maven-plugin:1.1.0.CR1:create \
    -DprojectGroupId=com.elmediko.bma.services.fhir.wrapper \
    -DprojectArtifactId=elmediko-bma-fhir-wrapper \
    -DclassName="com.elmediko.bma.services.fhir.wrapper.web.controller.RestController" \
    -Dpath="/test" \
    -Dextensions="vertx,vertx-web,oidc,keycloak-authorization"

It fails with:

[ERROR] Failed to execute goal io.quarkus:quarkus-maven-plugin:1.1.0.CR1:create (default-cli) on project standalone-pom: Execution default-cli of goal io.quarkus:quarkus-maven-plugin:1.1.0.CR1:create failed: Failed to load templates/README.maven.ftl: Failed to locate templates/README.maven.ftl in /home/triphon/.m2/repository/io/quarkus/quarkus-platform-descriptor-json/1.0.1.Final/quarkus-platform-descriptor-json-1.0.1.Final.jar -> [Help 1]

tpenakov picture tpenakov on 12 Dec 2019

@tpenakov Hi, sorry for a delay, not that I'm aware of, it is in Central. can you retry please ? CC @gsmet

sberyozkin picture sberyozkin on 16 Dec 2019

You need to use the quarkus-bom instead of the quarkus-universe-bom. We haven't released the latter for the CR.

gsmet picture gsmet on 16 Dec 2019

Thank you @gsmet - now I am able to work with 1.1.0.CR1

@sberyozkin - If I disable the policy enforcer:
quarkus.keycloak.policy-enforcer.enable=false
It works fine - there is no more NPE
However if I enable it the error is still there:
quarkus.keycloak.policy-enforcer.enable=true
and the error is:

2019-12-17 09:20:51,771 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /fhir/test failed, error id: 258774b7-853a-496d-bbe4-eeacc3eee59f-1: java.lang.IllegalStateException: Request has already been read
    at io.vertx.core.http.impl.HttpServerRequestImpl.checkEnded(HttpServerRequestImpl.java:600)
    at io.vertx.core.http.impl.HttpServerRequestImpl.handler(HttpServerRequestImpl.java:307)
    at io.vertx.ext.web.impl.HttpServerRequestWrapper.handler(HttpServerRequestWrapper.java:78)
    at io.vertx.ext.web.handler.impl.BodyHandlerImpl.handle(BodyHandlerImpl.java:86)
    at io.vertx.ext.web.handler.impl.BodyHandlerImpl.handle(BodyHandlerImpl.java:42)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$9.handle(VertxHttpRecorder.java:660)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$9.handle(VertxHttpRecorder.java:656)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:131)
    at io.vertx.ext.web.impl.RoutingContextWrapper.next(RoutingContextWrapper.java:160)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer.doPermissionCheck(HttpAuthorizer.java:120)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer.access$000(HttpAuthorizer.java:24)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer$3.apply(HttpAuthorizer.java:139)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer$3.apply(HttpAuthorizer.java:126)
    at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
    at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
    at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
    at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer$1$1.run(HttpAuthorizer.java:66)
    at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
    at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2011)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1535)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1395)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at java.base/java.lang.Thread.run(Thread.java:834)
    at org.jboss.threads.JBossThread.run(JBossThread.java:479)
tpenakov picture tpenakov on 17 Dec 2019

@tpenakov OK, thanks, so we can now be certain it is isolated to the use of quarkus-keycloak-authorization alongside the reactive routes.

sberyozkin picture sberyozkin on 18 Dec 2019

@sberyozkin - please have in mind that body can be read more than once. In my real project I am using a custom 'Claim Information Provider SPI' which also will read the body

tpenakov picture tpenakov on 18 Dec 2019

@sberyozkin - I am not sure is this #5959 issue is relevant to the case

tpenakov picture tpenakov on 18 Dec 2019

@tpenakov It might be, please check now that #5959 has been fixed

sberyozkin picture sberyozkin on 17 Jan 2020

@tpenakov never mind, #5959 was fixed for 1.1.0.CR1 which you've already tried

sberyozkin picture sberyozkin on 17 Jan 2020

Hi, I just ran into the same issue (IllegalStateException: "Request has already been read") with a vert.x route secured by basic auth based on quarkus-elytron-security-properties-file. Here's a minimal working example: https://github.com/schulzp/quarkus-vertx-body-already-read (run the ReactiveRoutesTest).

schulzp picture schulzp on 20 Jan 2020
👍1

I am encountering this issue in 1.2.0.CR1 with the combination of the oidc and graphql extensions. Here is my stack trace:

2020-01-22 21:24:58,271 INFO  [io.quarkus] (main) Installed features: [cdi, oidc, resteasy, resteasy-jsonb, security, smallrye-health, vertx-graphql]
2020-01-22 21:25:12,996 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-3) HTTP Request to /graphql failed, error id: 2b82f17d-cf5c-4141-bc39-c5534dd9aef9-1: java.lang.IllegalStateException: Request has already been read
    at io.vertx.core.http.impl.HttpServerRequestImpl.checkEnded(HttpServerRequestImpl.java:600)
    at io.vertx.core.http.impl.HttpServerRequestImpl.handler(HttpServerRequestImpl.java:307)
    at io.vertx.core.http.HttpServerRequest.bodyHandler(HttpServerRequest.java:215)
    at io.vertx.ext.web.impl.HttpServerRequestWrapper.bodyHandler(HttpServerRequestWrapper.java:245)
    at io.vertx.ext.web.handler.graphql.impl.GraphQLHandlerImpl.handle(GraphQLHandlerImpl.java:86)
    at io.vertx.ext.web.handler.graphql.impl.GraphQLHandlerImpl.handle(GraphQLHandlerImpl.java:48)
    at io.quarkus.vertx.http.runtime.ResumeHandler.handle(ResumeHandler.java:19)
    at io.quarkus.vertx.http.runtime.ResumeHandler.handle(ResumeHandler.java:6)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:131)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:130)
    at io.vertx.ext.web.handler.graphql.impl.ApolloWSHandlerImpl.handle(ApolloWSHandlerImpl.java:113)
    at io.vertx.ext.web.handler.graphql.impl.ApolloWSHandlerImpl.handle(ApolloWSHandlerImpl.java:49)
    at io.quarkus.vertx.http.runtime.ResumeHandler.handle(ResumeHandler.java:19)
    at io.quarkus.vertx.http.runtime.ResumeHandler.handle(ResumeHandler.java:6)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:131)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:130)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer.doPermissionCheck(HttpAuthorizer.java:120)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer.access$000(HttpAuthorizer.java:24)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer$3.apply(HttpAuthorizer.java:139)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer$3.apply(HttpAuthorizer.java:126)
    at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
    at java.base/java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:946)
    at java.base/java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2337)
    at java.base/java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:143)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer.doPermissionCheck(HttpAuthorizer.java:126)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer.checkPermission(HttpAuthorizer.java:93)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:84)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:76)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1034)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:131)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:130)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$1$1.apply(HttpSecurityRecorder.java:67)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$1$1.apply(HttpSecurityRecorder.java:36)
    at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
    at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
    at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
    at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2144)
    at io.quarkus.security.runtime.QuarkusIdentityProviderManagerImpl$1$1.run(QuarkusIdentityProviderManagerImpl.java:55)
    at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
    at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2011)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1535)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1426)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at java.base/java.lang.Thread.run(Thread.java:830)
    at org.jboss.threads.JBossThread.run(JBossThread.java:479)
aaronanderson picture aaronanderson on 23 Jan 2020

Something similar has been reported before in Vertx itself, https://github.com/vert-x3/vertx-web/issues/729, with the main issue being A handler on a router can be called twice.
Hi Stuart @stuartwdouglas, I'm not sure if it is related to the issues you were dealing with before, to do with the security and Vertx, when combined, causing few problems ?
CC @pmlopes, @cescoffier

sberyozkin picture sberyozkin on 23 Jan 2020

Hi, I just ran into the same issue (IllegalStateException: "Request has already been read") with a vert.x route secured by basic auth based on quarkus-elytron-security-properties-file. Here's a minimal working example: https://github.com/schulzp/quarkus-vertx-body-already-read (run the ReactiveRoutesTest).

In this example the request is ended because it is a GET request so there is no body.

stuartwdouglas picture stuartwdouglas on 23 Jan 2020

@aaronanderson can you provide a reproducer?

stuartwdouglas picture stuartwdouglas on 23 Jan 2020

In this example the request is ended because it is a GET request so there is no body.

Thanks @stuartwdouglas, technically that shouldn't make a difference since vert.x does not prevent you from sending a body. I updated my MWE to use POST, however, and the error remains. Originally I tried the same as @aaronanderson: using graphql via graphql-java based on vert.x + quarkus basic auth.

schulzp picture schulzp on 24 Jan 2020

Related Zulip thread: https://quarkusio.zulipchat.com/#narrow/stream/187030-users/topic/Vertx.3A.20java.2Elang.2EIllegalStateException.3A.20Request.20has.20alrea.2E.2E.2E

sberyozkin picture sberyozkin on 24 Jan 2020

Reproducer from @tpenakov: https://github.com/tpenakov/keycloak-with-reactive-routes-error

sberyozkin picture sberyozkin on 24 Jan 2020

Here is my reproducer as well https://github.com/aaronanderson/quarkus-oidc-graphql

aaronanderson picture aaronanderson on 25 Jan 2020

I also have similar issue, but I don't have the Keycloak authentication enabled in Quarkus. I observed the issue only when I deployed the service in a Kubernetes cluster with Istio/Envoy/ proxy.@sberyozkin pointed me here, I am not sure if I am in the correct thread. It is described here - https://quarkusio.zulipchat.com/#narrow/stream/187030-users/topic/Vertx.3A.20java.2Elang.2EIllegalStateException.3A.20Request.20has.20alrea.2E.2E.2E

svilenvul picture svilenvul on 27 Jan 2020

Thanks @stuartwdouglas, I applied the commit patch to 1.2.0.Final and now both proxy address forwarding, OIDC, and GraphQL are all working together in my application that is behind a loadbalancer and deployed in the Cloud.

aaronanderson picture aaronanderson on 29 Jan 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

enbohm picture enbohm  路  3Comments
rsvoboda picture rsvoboda  路  3Comments
pipinet picture pipinet  路  3Comments
mswiderski picture mswiderski  路  3Comments
gsmet picture gsmet  路  3Comments