First request after fresh start always fails on clustered setup
Closed this issue · 10 comments
gryffus commented
Hello,
privacyIDEA 3.8.1
PrivacyIDEA-Provider v1.2.0.KC21
Keycloak 21.1.1
Steps to reproduce:
- Start multiple instances of keycloak in load-balancer setup, with keycloak-provider configured.
- Try to authenticate
- If privacyIDEA reply is transmitted to different keycloak instance than origin, authentication fails
Request:
keycloak_2 | 2023-05-23 12:26:47,132 INFO [org.privacyidea.authenticator.PrivacyIDEAAuthenticator] (pool-9-thread-1) PrivacyIDEA Client: POST /auth
keycloak_2 | 2023-05-23 12:26:47,133 INFO [org.privacyidea.authenticator.PrivacyIDEAAuthenticator] (pool-9-thread-1) PrivacyIDEA Client: username=privacyidea
keycloak_2 | 2023-05-23 12:26:47,133 INFO [org.privacyidea.authenticator.PrivacyIDEAAuthenticator] (pool-9-thread-1) PrivacyIDEA Client: password=******************
keycloak_2 | 2023-05-23 12:26:47,133 INFO [org.privacyidea.authenticator.PrivacyIDEAAuthenticator] (pool-9-thread-1) PrivacyIDEA Client: realm=administrators
keycloak_2 | 2023-05-23 12:26:48,397 INFO [org.privacyidea.authenticator.PrivacyIDEAAuthenticator] (pool-9-thread-1) PrivacyIDEA Client: POST /validate/triggerchallenge
keycloak_2 | 2023-05-23 12:26:48,397 INFO [org.privacyidea.authenticator.PrivacyIDEAAuthenticator] (pool-9-thread-1) PrivacyIDEA Client: user=test
keycloak_2 | 2023-05-23 12:26:48,609 INFO [org.privacyidea.authenticator.PrivacyIDEAAuthenticator] (OkHttp https://<fqdn>/...) PrivacyIDEA Client: /validate/triggerchallenge:
keycloak_2 | {
keycloak_2 | "detail": {
keycloak_2 | "client_mode": "interactive",
keycloak_2 | "message": "Enter your TOTP:",
keycloak_2 | "messages": [
keycloak_2 | "Enter your TOTP:"
keycloak_2 | ],
keycloak_2 | "multi_challenge": [
keycloak_2 | {
keycloak_2 | "client_mode": "interactive",
keycloak_2 | "message": "Enter your TOTP:",
keycloak_2 | "serial": "TOTP0000C103",
keycloak_2 | "transaction_id": "01941994498686029549",
keycloak_2 | "type": "totp"
keycloak_2 | }
keycloak_2 | ],
keycloak_2 | "serial": "TOTP0000C103",
keycloak_2 | "threadid": 139737688266496,
keycloak_2 | "transaction_id": "01941994498686029549",
keycloak_2 | "transaction_ids": [
keycloak_2 | "01941994498686029549"
keycloak_2 | ],
keycloak_2 | "type": "totp",
keycloak_2 | "preferred_client_mode": "interactive"
keycloak_2 | },
keycloak_2 | "id": 2,
keycloak_2 | "jsonrpc": "2.0",
keycloak_2 | "result": {
keycloak_2 | "authentication": "ACCEPT",
keycloak_2 | "status": true,
keycloak_2 | "value": 1
keycloak_2 | },
keycloak_2 | "time": 1684844808.5248022,
keycloak_2 | "version": "privacyIDEA 3.8.1",
keycloak_2 | "versionnumber": "3.8.1",
keycloak_2 | "signature": "rsa_sha256_pss:<signature>"
keycloak_2 | }
Response:
keycloak_1 | 2023-05-23 12:27:00,625 WARN [org.keycloak.services] (executor-thread-4) KC-SERVICES0013: Failed authentication: org.keycloak.authentication.AuthenticationFlowException: No privacyIDEA configuration found for kc-realm test
keycloak_1 | at org.privacyidea.authenticator.PrivacyIDEAAuthenticator.action(PrivacyIDEAAuthenticator.java:302)
keycloak_1 | at org.keycloak.authentication.DefaultAuthenticationFlow.processAction(DefaultAuthenticationFlow.java:154)
keycloak_1 | at org.keycloak.authentication.AuthenticationProcessor.authenticationAction(AuthenticationProcessor.java:986)
keycloak_1 | at org.keycloak.services.resources.LoginActionsService.processFlow(LoginActionsService.java:323)
keycloak_1 | at org.keycloak.services.resources.LoginActionsService.processAuthentication(LoginActionsService.java:294)
keycloak_1 | at org.keycloak.services.resources.LoginActionsService.authenticateInternal(LoginActionsService.java:286)
keycloak_1 | at org.keycloak.services.resources.LoginActionsService.access$100(LoginActionsService.java:111)
keycloak_1 | at org.keycloak.services.resources.LoginActionsService$1.runInternal(LoginActionsService.java:266)
keycloak_1 | at org.keycloak.common.util.ResponseSessionTask.run(ResponseSessionTask.java:67)
keycloak_1 | at org.keycloak.common.util.ResponseSessionTask.run(ResponseSessionTask.java:44)
keycloak_1 | at org.keycloak.models.utils.KeycloakModelUtils.runJobInRetriableTransaction(KeycloakModelUtils.java:299)
keycloak_1 | at org.keycloak.services.resources.LoginActionsService.authenticate(LoginActionsService.java:259)
keycloak_1 | at org.keycloak.services.resources.LoginActionsService.authenticateForm(LoginActionsService.java:351)
keycloak_1 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
keycloak_1 | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
keycloak_1 | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
keycloak_1 | at java.base/java.lang.reflect.Method.invoke(Method.java:568)
keycloak_1 | at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
keycloak_1 | at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
keycloak_1 | at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
keycloak_1 | at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
keycloak_1 | at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
keycloak_1 | at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
keycloak_1 | at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
keycloak_1 | at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
keycloak_1 | at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:192)
keycloak_1 | at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:141)
keycloak_1 | at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:32)
keycloak_1 | at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
keycloak_1 | at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
keycloak_1 | at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
keycloak_1 | at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
keycloak_1 | at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
keycloak_1 | at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
keycloak_1 | at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
keycloak_1 | at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
keycloak_1 | at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:82)
keycloak_1 | at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:42)
keycloak_1 | at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
keycloak_1 | at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:173)
keycloak_1 | at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
keycloak_1 | at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:84)
keycloak_1 | at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:71)
keycloak_1 | at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
keycloak_1 | at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:173)
keycloak_1 | at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
keycloak_1 | at io.quarkus.vertx.http.runtime.VertxHttpRecorder$6.handle(VertxHttpRecorder.java:430)
keycloak_1 | at io.quarkus.vertx.http.runtime.VertxHttpRecorder$6.handle(VertxHttpRecorder.java:408)
keycloak_1 | at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
keycloak_1 | at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:173)
keycloak_1 | at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:140)
keycloak_1 | at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$0(QuarkusRequestFilter.java:82)
keycloak_1 | at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
keycloak_1 | at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
keycloak_1 | at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
keycloak_1 | at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
keycloak_1 | at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
keycloak_1 | at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
keycloak_1 | at java.base/java.lang.Thread.run(Thread.java:833)
keycloak_1 |
keycloak_1 | 2023-05-23 12:27:00,628 WARN [org.keycloak.events] (executor-thread-4) type=LOGIN_ERROR, realmId=1c385ee1-c0a8-4442-9ad0-302d7430e247, clientId=account-console, userId=null, ipAddress=10.253.10.91, error=invalid_user_credentials, auth_method=openid-connect, auth_type=code, redirect_uri=https://<FQDN>/#/, code_id=a86ca714-4c70-4ac2-a1fb-1428b873b0a3
After each of the instances sends at least one request, everything works as expected.
nilsbehlen commented
Good catch. The problem is
Failed authentication: org.keycloak.authentication.AuthenticationFlowException: No privacyIDEA configuration found for kc-realm test
So we need to add the createInstance from config stuff for the second keycloak function too, which is here:
https://github.com/privacyidea/keycloak-provider/blob/df005a7e076cf0c860ec7e06853e29a534988194/src/main/java/org/privacyidea/authenticator/PrivacyIDEAAuthenticator.java#LL288C11-L288C12
(Currently the config for a keycloak instance is only created in the first step, which is skipped in this scenario)
nilsbehlen commented
It should work. It is just not very elegant, because it is duplicated code. You can open a pull request and i can refactor it (or you do it), then you can test it. I do not have a clustered setup available, so i would only test for regression.
gryffus commented
I have refactored the code and moved the functionality to createInstance() method. Also, I have renamed createInstance() to loadConfiguration() to align with the change.
I have tested it with Keycloak 21 (with KC21 dependencies) and everything seems to work correctly.
The branch with the fix is located here: https://github.com/gryffus/keycloak-provider/tree/fix-load-configuration
gryffus commented
I can provide a docker-compose file for testing the clustered setup too, if you are interested. But according to my tests everything seems to be fine.
arozmarin commented
Hi guys,
I install cluster with:
privacyIDEA 3.9.2
PrivacyIDEA-Provider v1.4
Keycloak 23.0.7
And I have same issues, is this bug come back in later versions.
nilsbehlen commented
Can you post your log?
arozmarin commented
Thank you for quick replay. I got answer from Cornelius, what could potentially causing this. I'll research that fist and update here.
arozmarin commented
Just an update, we found the problem. Time on both servers was out of sync for 20s and that caused issues.
nilsbehlen commented
good to hear, thanks for the update