keycloak / keycloak

Open Source Identity and Access Management For Modern Applications and Services
https://www.keycloak.org
Apache License 2.0
23.45k stars 6.77k forks source link

NullPointerException in QuarkusRequestFilter #13911

Closed JPMoresmau closed 12 months ago

JPMoresmau commented 2 years ago

Describe the bug

The Keycloak log file shows the following error:

2022-08-22 09:23:49,229 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-80) Uncaught server error: java.lang.NullPointerException
        at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter$1.getRemoteAddr(QuarkusRequestFilter.java:160)
        at jdk.internal.reflect.GeneratedMethodAccessor69.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.jboss.resteasy.core.ContextParameterInjector$GenericDelegatingProxy.invoke(ContextParameterInjector.java:166)
        at com.sun.proxy.$Proxy58.getRemoteAddr(Unknown Source)
        at org.keycloak.events.EventBuilder.<init>(EventBuilder.java:79)
        at org.keycloak.services.resources.RealmsResource.getProtocol(RealmsResource.java:123)
        at jdk.internal.reflect.GeneratedMethodAccessor178.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.jboss.resteasy.core.ResourceLocatorInvoker.constructLocator(ResourceLocatorInvoker.java:107)
        at org.jboss.resteasy.core.ResourceLocatorInvoker.resolveTargetFromLocator(ResourceLocatorInvoker.java:87)
        at org.jboss.resteasy.core.ResourceLocatorInvoker.resolveTarget(ResourceLocatorInvoker.java:76)
        at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:137)
        at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:32)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
        at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
        at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
        at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:82)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:42)
        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:67)
        at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:55)
        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$5.handle(VertxHttpRecorder.java:380)
        at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:358)
        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 org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$1(QuarkusRequestFilter.java:90)
        at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
        at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
        at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:545)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:829)

Version

19.0.1

Expected behavior

No NullPointerException at runtime

Actual behavior

Keycloak logs show a NullPointerException

How to Reproduce?

I think that we have an issue in our UI and we issue multiple logout requests to Keycloak when the user fails to connect to our server, and I suspect we interrupt the requests before Keycloak has finished processing them. So this is not really a functional bug as anyway we didn't expect the logout to complete successfully, but it seems to point to maybe code that is not defensive enough on the Keycloak side.

Anything else?

No response

Thomasdezeeuw commented 2 years ago

Note that this is also present in version 18.x.

pedroigor commented 2 years ago

@JPMoresmau Interesting because a call to request.remoteAddress is expected to return null if the server is bound to a domain socket which I think is never the case.

It should be OK to add a check but I would like to reproduce it locally somehow. Do you have any pointers?

Thomasdezeeuw commented 2 years ago

@JPMoresmau Interesting because a call to request.remoteAddress is expected to return null if the server is bound to a domain socket which I think is never the case.

It should be OK to add a check but I would like to reproduce it locally somehow. Do you have any pointers?

It's a little hard to reproduce, but our frontend went a little haywire and send and cancelled/aborted a ~1000 (I believe) logout requests in a loop. Maybe that's a starting point? If not we can try and get some more info from the person this happened to.

pedroigor commented 2 years ago

@Thomasdezeeuw Sorry for the late reply. I tried to use wrk2 to load the server with requests but still not able to reproduce the error.

If you have more details or even a reproducer, I appreciate it.

Thomasdezeeuw commented 2 years ago

@Thomasdezeeuw Sorry for the late reply. I tried to use wrk2 to load the server with requests but still not able to reproduce the error.

Have you tried aborting requests mid-flight? I think that was happening a lot.

If you have more details or even a reproducer, I appreciate it.

I'll look into this.

pedroigor commented 2 years ago

Yeah, I tried. I got connection reset errors but no NPE :(

Thomasdezeeuw commented 2 years ago

@pedroigor I got this again locally (19.0.2), without a large number of requests. It really seems possible to get a null in the code, can some safeguards be put into place?

pedroigor commented 2 years ago

Definitely, I'll come up with a change.

pedroigor commented 1 year ago

FYI, this might be fixed by the resteasy reactive migration. See https://github.com/keycloak/keycloak/pull/15728.

shawkins commented 12 months ago

@mabartos @vmuzikar the resteasy reactive changes have removed the QuarkusRequestFilter, should this closed or do you want it still in consideration for 22.0.x?

vmuzikar commented 12 months ago

@shawkins Let's close this and re-open if it reappears again.

espgus commented 8 months ago

i get this on 23.0.6 :

[org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-3) Uncaught server error: java.lang.NullPointerException
        at io.vertx.core.net.impl.HostAndPortImpl.<init>(HostAndPortImpl.java:141)
        at io.vertx.core.net.HostAndPort.create(HostAndPort.java:20)
        at io.vertx.ext.web.impl.ForwardedParser.calculate(ForwardedParser.java:137)
        at io.vertx.ext.web.impl.ForwardedParser.remoteAddress(ForwardedParser.java:103)
        at io.vertx.ext.web.impl.HttpServerRequestWrapper.remoteAddress(HttpServerRequestWrapper.java:152)
        at org.keycloak.quarkus.runtime.integration.resteasy.QuarkusClientConnection.getRemoteAddr(QuarkusClientConnection.java:34)
        at org.keycloak.events.EventBuilder.<init>(EventBuilder.java:57)
        at org.keycloak.services.resources.RealmsResource.getProtocol(RealmsResource.java:113)
        at org.keycloak.services.resources.RealmsResource$quarkusrestinvoker$getProtocol_b2af2a2de155d6f3564a200a8d3634cdf6f57aa2.invoke(Unknown Source)
        at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
        at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:840)
shawkins commented 8 months ago

@espgus that exception matches #26671 - please move any further comments over to that open issue. In particular if you can provide the request headers that reproduce this, that would be great.