search

p2-inc / keycloak-events

Useful Keycloak event listener implementations and utilities.
https://phasetwo.io
Other
181 stars 34 forks source link

java.util.ConcurrentModificationException when requesting access token with Keycloak Events plugin enabled. KC25.0.1 #76

Open Jack-Hazelden-Blackdot opened 4 days ago

Jack-Hazelden-Blackdot commented 4 days ago

Upon enabling the Keycloak Events plugin we see errors consistently raised in our tests when setting up the realms for our testing environment causing them to fail with a java.util.ConcurrentModificationException in the logs.

All instances of the error appear to be when Keycloak.Net.KeycloakClient in our backend requests an access token from POST http://keycloak:8080/realms/tests/protocol/openid-connect/token as part of the authentication flow causing Keycloak to return a 500. Note that prior to enabling the Keycloak Events plugin this did not occur, and disabling it allows the tests to pass with no issues.

For our test runs we stand up Keycloak using docker compose in Github Actions and configure it to use the jboss-logging and ext-event-http event listeners via a bootstrapper - we then stand up our backend using docker run on the same network where it hits the Keycloak endpoints. Section of the docker compose configuring Keycloak:

  keycloak:
    image: quay.io/keycloak/keycloak:25.0.1
    command: start-dev
    restart: always
    environment:
      KEYCLOAK_ADMIN: <admin_name>
      KEYCLOAK_ADMIN_PASSWORD: <admin_password>
      JAVA_OPTS_APPEND: "-server -Xms128m -Xmx256m"
    ports:
      - "8081:8080"
    volumes:
      - ../../src/keycloak/keycloak-events-plugin/keycloak-events-0.32-SNAPSHOT.jar:/opt/keycloak/providers/keycloak-events-0.32-SNAPSHOT.jar:ro

Versions used and logs are below - any assistance is greatly appreciated. Let me know if any additional information is required. Quite possibly related to https://github.com/p2-inc/keycloak-events/issues/73

Keycloak version: 25.0.1 Keycloak Events plugin version: 0.32 Keycloak.Net.Core version: 1.0.26 Keycloak.AuthServices.Authentication version: 2.5.1

From our backend logs calling Keycloak:

>    at Flurl.Http.FlurlRequest.HandleExceptionAsync(FlurlCall call, Exception ex, CancellationToken token)
>    at Flurl.Http.FlurlRequest.SendAsync(HttpMethod verb, HttpContent content, CancellationToken cancellationToken, HttpCompletionOption completionOption)
> {"Timestamp":"2024-10-07 12:01:26Z","EventId":0,"LogLevel":"Error","Category":"Bds.Common.Mediator.RequestLoggingBehaviour","Message":"Error handling UpdateOrganisationLicenceCommand","Exception":"Flurl.Http.FlurlHttpException: Call failed with status code 500 (Internal Server Error): POST http://keycloak:8080/realms/tests/protocol/openid-connect/token
>    at Flurl.Http.FlurlRequest.SendAsync(HttpMethod verb, HttpContent content, CancellationToken cancellationToken, HttpCompletionOption completionOption)
>    at Flurl.Http.ResponseExtensions.ReceiveJson(Task\u00601 response)
>    at [Keycloak.Net](http://keycloak.net/).Common.Extensions.FlurlRequestExtensions.GetAccessTokenAsync(String url, String realm, String clientSecret, KeycloakOptions options)
>    at [Keycloak.Net](http://keycloak.net/).Common.Extensions.FlurlRequestExtensions.GetAccessToken(String url, String realm, String clientSecret, KeycloakOptions options)
>    at [Keycloak.Net](http://keycloak.net/).Common.Extensions.FlurlRequestExtensions.WithAuthentication(IFlurlRequest request, Func\u00601 getToken, String url, String realm, String userName, String password, String clientSecret, KeycloakOptions options)
>    at [Keycloak.Net](http://keycloak.net/).KeycloakClient.GetBaseUrl(String authenticationRealm)
>    at [Keycloak.Net](http://keycloak.net/).KeycloakClient.GetUsersWithRoleNameAsync(String realm, String roleName, Nullable\u00601 first, Nullable\u00601 max, CancellationToken cancellationToken)

From the Keycloak logs at the same point in time:

> keycloak-1  | 2024-10-07 12:01:26,543 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-2) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=http://audit:8080/keycloak]
> keycloak-1  | 2024-10-07 12:01:26,559 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-2) Uncaught server error: java.util.ConcurrentModificationException
> keycloak-1  |     at java.base/java.util.HashMap$Values.forEach(HashMap.java:1076)
> keycloak-1  |     at org.keycloak.services.DefaultKeycloakSession.close(DefaultKeycloakSession.java:385)
> keycloak-1  |     at org.keycloak.models.KeycloakBeanProducer_ProducerMethod_getKeycloakSession_XoSEUTXOsE3bpqXlGMAykCiECUM_ClientProxy.close(Unknown Source)
> keycloak-1  |     at org.keycloak.quarkus.runtime.transaction.TransactionalSessionHandler.close(TransactionalSessionHandler.java:60)
> keycloak-1  |     at org.keycloak.quarkus.runtime.integration.jaxrs.CloseSessionFilter.closeSession(CloseSessionFilter.java:67)
> keycloak-1  |     at org.keycloak.quarkus.runtime.integration.jaxrs.CloseSessionFilter.filter(CloseSessionFilter.java:63)
> keycloak-1  |     at org.jboss.resteasy.reactive.server.handlers.ResourceResponseFilterHandler.handle(ResourceResponseFilterHandler.java:25)
> keycloak-1  |     at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:150)
> keycloak-1  |     at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147)
> keycloak-1  |     at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:582)
> keycloak-1  |     at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
> keycloak-1  |     at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
> 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:1583)
> keycloak-1  |
xgp commented 4 days ago

@Jack-Hazelden-Blackdot Can you also provide information on how you are configuring the ext-event-http listener (i.e. what realm attributes you are setting, and how)? We'll try to reproduce.

The code the exception points to seems to indicate that the internal Map of providers kept by the DefaultKeycloakSession implementation is somehow getting changed while it is looping through the providers to call close. That's strange because we don't make any changes (nor do I think we can) to that Map.

https://github.com/keycloak/keycloak/blob/25.0.1/services/src/main/java/org/keycloak/services/DefaultKeycloakSession.java#L385C1-L386C1

Jack-Hazelden-Blackdot commented 4 days ago

@xgp For the realm attribute configuration of the ext-event-http listener we set the _providerConfig.ext-event-http with the targetUri to our auditing service endpoint (http://audit:8080/keycloak) as part of the bootstrapping by calling the Keycloak API - this service is stood up using docker run in the same network. Example of the code:

private async Task AddProviderConfigurationAsync(string auditEventServiceName)
    {
        await _realmsAdminApi.PutAsync(_realm, new RealmRepresentation
        {
            Attributes = new Dictionary<string, string>()
            {
                {"_providerConfig.ext-event-http", $"{{\"targetUri\":\"{auditEventServiceName}\"}}"}
            }
        });
    }

The logs from the audit service indicate that Keycloak is able to connect and push events through:

[11:59:58 INF] Application started. Press Ctrl+C to shut down. [11:59:58 INF] Hosting environment: CucumberCi [11:59:58 INF] Content root path: /app [12:01:26 INF] Request starting HTTP/1.1 POST http://audit:8080/keycloak - application/json 514 [12:01:26 INF] Request starting HTTP/1.1 POST http://audit:8080/keycloak - application/json 514 [12:01:26 WRN] Failed to determine the https port for redirect. [12:01:26 INF] Executing endpoint 'HTTP: POST /keycloak' [12:01:26 INF] Executing endpoint 'HTTP: POST /keycloak' [12:01:26 INF] Setting HTTP status code 200. [12:01:26 INF] Setting HTTP status code 200. [12:01:26 INF] Executed endpoint 'HTTP: POST /keycloak' [12:01:26 INF] Executed endpoint 'HTTP: POST /keycloak' [12:01:26 INF] HTTP POST /keycloak responded 200 in 36.8933 ms [12:01:26 INF] HTTP POST /keycloak responded 200 in 29.3713 ms [12:01:26 INF] Request finished HTTP/1.1 POST http://audit:8080/keycloak - 200 0 null 122.9871ms [12:01:26 INF] Request finished HTTP/1.1 POST http://audit:8080/keycloak - 200 0 null 123.1193ms