search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.58k stars 2.63k forks source link

RESTEasy Reactive does not handle non-blocking method with blocking ServerRequestFilter correctly. #27534

Open rvansa opened 2 years ago

rvansa commented 2 years ago

Describe the bug

I have a non-blocking method in my API:

public CompletionStage<List<User>> users() { ... }

and I use a custom ServerRequestFilter that invokes a potentially blocking call to SecurityIdentity.isAnonymous(). The filter is blocking (default value for the annotation):

@Inject SecurityIdentity identity;

@ServerRequestFilter(priority = Priorities.HEADER_DECORATOR + 20)
public void filter(ContainerRequestContext containerRequestContext) {
  if (identity.isAnonymous()) {
     return;
  }
 /* ... */
}

Since the method is non-blocking RESTEasy decides to invoke the method on I/O thread and I get an exception:

A blocking operation occurred on the IO thread. This likely means you need to annotate io.my.svc.UserServiceImpl#users() with @io.smallrye.common.annotation.Blocking ...

Workaround of marking the method @Blocking works.

Expected behavior

The operation is invoked on a blocking thread and is successful.

Actual behavior

The operation is executed on I/O thread. Message is a bit confusing since it speaks about the method, but the stack trace shows clearly that the blocking call happens in the filter.

Full stack trace:

2022-08-26 14:47:50,009 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (vert.x-eventloop-thread-21) HTTP Request to /api/user/administrators failed, error id: 8ef66050-6907-4396-a30d-22182cab857f-1: io.quarkus.runtime.BlockingOperationNotAllowedException: Cannot call getIdentity() from the IO thread when lazy authentication is in use, as resolving the identity may block the thread. Instead you should inject the CurrentIdentityAssociation, call CurrentIdentityAssociation#getDeferredIdentity() and subscribe to the Uni.
    at io.quarkus.security.runtime.SecurityIdentityAssociation.getIdentity(SecurityIdentityAssociation.java:68)
    at io.quarkus.security.runtime.SecurityIdentityAssociation_Subclass.getIdentity$$superforward1(Unknown Source)
    at io.quarkus.security.runtime.SecurityIdentityAssociation_Subclass$$function$$1.apply(Unknown Source)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at io.quarkus.security.runtime.SecurityIdentityAssociation_Subclass.getIdentity(Unknown Source)
    at io.quarkus.security.runtime.SecurityIdentityAssociation_ClientProxy.getIdentity(Unknown Source)
    at io.quarkus.security.runtime.SecurityIdentityProxy.isAnonymous(SecurityIdentityProxy.java:28)
    at io.quarkus.security.runtime.SecurityIdentityProxy_Subclass.isAnonymous$$superforward1(Unknown Source)
    at io.quarkus.security.runtime.SecurityIdentityProxy_Subclass$$function$$5.apply(Unknown Source)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at io.quarkus.security.runtime.SecurityIdentityProxy_Subclass.isAnonymous(Unknown Source)
    at io.quarkus.security.runtime.SecurityIdentityProxy_ClientProxy.isAnonymous(Unknown Source)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter.filter(UserTeamsFilter.java:33)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter_Subclass.filter$$superforward1(Unknown Source)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter_Subclass$$function$$1.apply(Unknown Source)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter_Subclass.filter(Unknown Source)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter$GeneratedServerRequestFilter$filter.filter(Unknown Source)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter$GeneratedServerRequestFilter$filter_Subclass.filter$$superforward1(Unknown Source)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter$GeneratedServerRequestFilter$filter_Subclass$$function$$1.apply(Unknown Source)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at io.hyperfoil.tools.horreum.server.UserTeamsFilter$GeneratedServerRequestFilter$filter_Subclass.filter(Unknown Source)
    at org.jboss.resteasy.reactive.server.handlers.ResourceRequestFilterHandler.handle(ResourceRequestFilterHandler.java:47)
    at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:98)
    at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:141)
    at org.jboss.resteasy.reactive.server.handlers.RestInitialHandler.beginProcessing(RestInitialHandler.java:49)
    at org.jboss.resteasy.reactive.server.vertx.ResteasyReactiveVertxHandler.handle(ResteasyReactiveVertxHandler.java:17)
    at org.jboss.resteasy.reactive.server.vertx.ResteasyReactiveVertxHandler.handle(ResteasyReactiveVertxHandler.java:7)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:83)
    at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:67)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkiverse.quinoa.QuinoaRecorder.next(QuinoaRecorder.java:72)
    at io.quarkiverse.quinoa.QuinoaDevProxyHandler.handle(QuinoaDevProxyHandler.java:43)
    at io.quarkiverse.quinoa.QuinoaDevProxyHandler.handle(QuinoaDevProxyHandler.java:22)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.hyperfoil.tools.horreum.server.RouteFilter.lambda$init$0(RouteFilter.java:24)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$6.handle(VertxHttpRecorder.java:412)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$6.handle(VertxHttpRecorder.java:390)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer.doPermissionCheck(HttpAuthorizer.java:117)
    at io.quarkus.vertx.ntime.security.HttpAuthorizer.checkPermission(HttpAuthorizer.java:100)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer_Subclass.checkPermission$$superforward1(Unknown Source)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer_Subclass$$function$$1.apply(Unknown Source)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:51)
    at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at io.quarkus.vertx.http.runtime.security.HttpAuthorizer_Subclass.checkPermission(Unknown Source)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$3.handle(HttpSecurityRecorder.java:227)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$3.handle(HttpSecurityRecorder.java:219)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:200)
    at io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:60)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.cors.CORSFilter.handle(CORSFilter.java:137)
    at io.quarkus.vertx.http.runtime.cors.CORSFilter.handle(CORSFilter.java:18)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup.handleHotReplacementRequest(VertxHttpHotReplacementSetup.java:135)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$11.handle(VertxHttpRecorder.java:492)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$11.handle(VertxHttpRecorder.java:488)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:67)
    at io.vertx.ext.web.impl.RouterImpl.handle(RouterImpl.java:37)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$15.handle(VertxHttpRecorder.java:584)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$15.handle(VertxHttpRecorder.java:567)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:168)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder$1.handle(VertxHttpRecorder.java:143)
    at io.vertx.core.http.impl.Http1xServerRequestHandler.handle(Http1xServerRequestHandler.java:67)
    at io.vertx.core.http.impl.Http1xServerRequestHandler.handle(Http1xServerRequestHandler.java:30)
    at io.vertx.core.impl.EventLoopContext.emit(EventLoopContext.java:50)
    at io.vertx.core.impl.DuplicatedContext.emit(DuplicatedContext.java:168)
    at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:145)
    at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:155)
    at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
    at io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:99)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.vertx.core.http.impl.Http1xUpgradeToH2CHandler.channelRead(Http1xUpgradeToH2CHandler.java:116)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:995)
    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:829)

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

No response

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.9.2

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

No response

Additional information

No response

quarkus-bot[bot] commented 2 years ago

/cc @FroMage, @geoand, @stuartwdouglas

rvansa commented 2 years ago

Reading through ServerRequestFilter javadocs it looks like I should not do any blocking operation in that filter anyway.

geoand commented 2 years ago

Thanks for reporting.

I'll have a look on Monday

geoand commented 2 years ago

So this is actually the expected behavior - the filter uses the same thread as the resource method. As you mention, to explicitly control the behavior of the filter, you can use @Blocking and @NonBlocking.

geoand commented 2 years ago

Do you mind adding the entire stacktrace to the description? I was not able to reproduce the issue with an example application I have.

rvansa commented 2 years ago

@geoand Added stacktrace.

You are probably right that the behaviour is more predictable when a non-blocking method is executed by the I/O thread regardless of the filter. Had you transparently switched to blocking thread when the filter is added there would be a non-obvious performance drop.

The problem (except error reporting) then is that the default value for the filter is blocking while you treat it as non-blocking, and IIUC setting blocking = false actually means to force running on I/O thread and then switch to pooled thread if needed. So there are in fact 3 possible options how to run it:

a) same thread as target method b) force I/O thread c) force pooled thread

a) as the default makes sense to me. There's no option right now for c) - you could consider using @Blocking on the filter. You could select b) through a property of @ServerRequestFilter. However I would drop the blocking with default true as this is confusing.

geoand commented 2 years ago

You are probably right that the behaviour is more predictable when a non-blocking method is executed by the I/O thread regardless of the filter. Had you transparently switched to blocking thread when the filter is added there would be a non-obvious performance drop.

Yeah, that's the idea.

However I would drop the blocking with default true as this is confusing.

Completely agreed, it's currently very confusing. We should probably introduce some kind of enum for handling this (and deprecate the current boolean field).

@Sgitario how do you feel about this one? Would you be interested in it (fair warning: it's probably requires a little more work than one thinks when first looking at it)?