search

p2-inc / keycloak-events

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

java.util.ConcurrentModificationException with ext-event-http #31

Closed ebiiii closed 1 year ago

ebiiii commented 1 year ago

After adding the extension and configuring it for http callbacks on a system that was running fine so far we started seeing errors in various actions we do on the admin and in the login flow. Removing the listener stopped the errors, so it must be linked in a way or another.

How to reproduce on the latest Keycloak version:

Build an image that include the keycloak-events provider (I built the version from master, 0.19 at the time of writing this).

Dockerfile:

FROM quay.io/keycloak/keycloak:latest as builder
ENV KC_HEALTH_ENABLED=true
ENV KC_METRICS_ENABLED=true
WORKDIR /opt/keycloak
ADD --chown=keycloak:keycloak keycloak-events-0.19-SNAPSHOT.jar /opt/keycloak/providers/keycloak-events-0.19-SNAPSHOT.jar
# for demonstration purposes only, please make sure to use proper certificates in production instead
RUN keytool -genkeypair -storepass password -storetype PKCS12 -keyalg RSA -keysize 2048 -dname "CN=server" -alias server -ext "SAN:c=DNS:localhost,IP:127.0.0.1" -keystore conf/server.keystore
RUN /opt/keycloak/bin/kc.sh build
FROM quay.io/keycloak/keycloak:latest
COPY --from=builder /opt/keycloak/ /opt/keycloak/
ENV KC_HOSTNAME=localhost
ENTRYPOINT ["/opt/keycloak/bin/kc.sh"]

-> docker build . -t mykeycloak -> docker run --name mykeycloak -p 8443:8443 -e KEYCLOAK_ADMIN=admin -e KEYCLOAK_ADMIN_PASSWORD=change_me mykeycloak start --optimized

Login to the admin console and create a new realm using this template to setup the provider config (change the targetUri to your favorite callback testing tool):

{
  "id": "test",
  "realm": "test",
  "attributes": {
    "_providerConfig.ext-event-http": "{\"targetUri\": \"https://webhook.site/xxxxx\",\"sharedSecret\":\"abcd123\"}"
  },
  "keycloakVersion": "22.0.0"
}

In the realm settings, on the Events tab, add ext-event-http to the event listeners and save. Then in the Admin events settings sub-tab enable the "save events" switch and save, then enable the "Include representation" and save. From this point I disabled and re-enabled the switches several times (saving each time) and it started to fail with this stacktrace:

2023-07-17 09:44:30,066 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-10) Uncaught server error: java.util.ConcurrentModificationException
    at java.base/java.util.HashMap$Values.forEach(HashMap.java:1068)
    at org.keycloak.services.DefaultKeycloakSession.close(DefaultKeycloakSession.java:384)
    at org.keycloak.quarkus.runtime.transaction.TransactionalSessionHandler.close(TransactionalSessionHandler.java:56)
    at org.keycloak.quarkus.runtime.integration.jaxrs.TransactionalResponseFilter.filter(TransactionalResponseFilter.java:48)
    at org.jboss.resteasy.core.interception.jaxrs.ContainerResponseContextImpl.filter(ContainerResponseContextImpl.java:329)
    at org.jboss.resteasy.core.ServerResponseWriter.executeFilters(ServerResponseWriter.java:243)
    at org.jboss.resteasy.core.ServerResponseWriter.writeNomapResponse(ServerResponseWriter.java:100)
    at org.jboss.resteasy.core.ServerResponseWriter.writeNomapResponse(ServerResponseWriter.java:73)
    at org.jboss.resteasy.core.SynchronousDispatcher.writeResponse(SynchronousDispatcher.java:518)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:458)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:240)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:229)
    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:82)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:147)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:84)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:44)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:58)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:36)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$0(QuarkusRequestFilter.java:82)
    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:833)

From this point on, many other actions, like creating a client, also trigger the same stacktrace. There are maybe other scenario that lead to this state, but the above procedure is the shortest I found (and I hope easiest to reproduce).

Let me know if you need any additional information.

xgp commented 1 year ago

@ebiiii Thanks for the report. Working on reproducing. Just to verify, you built this from main and are getting 22.0.0 with the latest tag for the Keycloak image?

xgp commented 1 year ago

From this point I disabled and re-enabled the switches several times (saving each time) and it started to fail with this stacktrace

How many times did you have to do it? I've done it about 20, and I can't get the exception to happen.

ebiiii commented 1 year ago

Yes, it is built from main and the latest image for Keycloak is pulling version 22.0.0 .

I just wanted to retry now and did a typo in the targetUri, which triggered the retry mechanism and now when enabling Save events on the Admin events settings of my test realm and saving, I got the error instantly. I'll take some more time tomorrow to find a more reliable way to trigger this behavior.

xgp commented 1 year ago

I tried that and still no error.

Does it only happen for you on retry? That would be useful to know.

ebiiii commented 1 year ago

Thanks for your help :-)

It is not linked to the retry, but seems rather linked to the number of requests done. After around 9-10 http calls it happens.

I tried another scenario, by just creating clients after enabling the ext-event-http . And after the 8th client created it failed with the same exception. Here is the full output, maybe there is something of interest. (or is there a way to have more verbose debug?)

docker run --name mykeycloak -p 8443:8443  -e KEYCLOAK_ADMIN=admin -e KEYCLOAK_ADMIN_PASSWORD=change_me  mykeycloak  start --optimized
2023-07-18 06:31:32,356 INFO  [org.keycloak.quarkus.runtime.hostname.DefaultHostnameProvider] (main) Hostname settings: Base URL: <unset>, Hostname: localhost, Strict HTTPS: true, Path: <request>, Strict BackChannel: false, Admin URL: <unset>, Admin: <request>, Port: -1, Proxied: false
2023-07-18 06:31:34,080 WARN  [io.quarkus.agroal.runtime.DataSources] (main) Datasource <default> enables XA but transaction recovery is not enabled. Please enable transaction recovery by setting quarkus.transaction-manager.enable-recovery=true, otherwise data may be lost if the application is terminated abruptly
2023-07-18 06:31:35,035 WARN  [org.infinispan.PERSISTENCE] (keycloak-cache-init) ISPN000554: jboss-marshalling is deprecated and planned for removal
2023-07-18 06:31:35,131 INFO  [org.infinispan.CONTAINER] (keycloak-cache-init) ISPN000556: Starting user marshaller 'org.infinispan.jboss.marshalling.core.JBossUserMarshaller'
2023-07-18 06:31:35,290 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000088: Unable to use any JGroups configuration mechanisms provided in properties {}. Using default JGroups configuration!
2023-07-18 06:31:35,403 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000078: Starting JGroups channel `ISPN`
2023-07-18 06:31:35,405 INFO  [org.jgroups.JChannel] (keycloak-cache-init) local_addr: 808e054e-90b8-467e-a4ba-61609d64d0f5, name: 7f74e07bfbc4-54719
2023-07-18 06:31:35,417 INFO  [org.jgroups.protocols.FD_SOCK2] (keycloak-cache-init) server listening on *.18780
2023-07-18 06:31:37,106 INFO  [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Initializing database schema. Using changelog META-INF/jpa-changelog-master.xml
2023-07-18 06:31:37,426 INFO  [org.jgroups.protocols.pbcast.GMS] (keycloak-cache-init) 7f74e07bfbc4-54719: no members discovered after 2004 ms: creating cluster as coordinator
2023-07-18 06:31:37,439 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000094: Received new cluster view for channel ISPN: [7f74e07bfbc4-54719|0] (1) [7f74e07bfbc4-54719]
2023-07-18 06:31:37,451 INFO  [org.infinispan.CLUSTER] (keycloak-cache-init) ISPN000079: Channel `ISPN` local address is `7f74e07bfbc4-54719`, physical addresses are `[172.200.0.5:34316]`
2023-07-18 06:31:39,845 INFO  [org.keycloak.quarkus.runtime.storage.legacy.liquibase.QuarkusJpaUpdaterProvider] (main) Initializing database schema. Using changelog META-INF/jpa-changelog-events-main.xml
2023-07-18 06:31:40,049 INFO  [org.keycloak.connections.infinispan.DefaultInfinispanConnectionProviderFactory] (main) Node name: 7f74e07bfbc4-54719, Site name: null
2023-07-18 06:31:40,176 INFO  [org.keycloak.broker.provider.AbstractIdentityProviderMapper] (main) Registering class org.keycloak.broker.provider.mappersync.ConfigSyncEventListener
2023-07-18 06:31:40,243 INFO  [org.keycloak.services] (main) KC-SERVICES0050: Initializing master realm
2023-07-18 06:31:42,529 INFO  [io.quarkus] (main) Keycloak 22.0.0 on JVM (powered by Quarkus 3.2.0.Final) started in 11.359s. Listening on: https://0.0.0.0:8443
2023-07-18 06:31:42,529 INFO  [io.quarkus] (main) Profile prod activated. 
2023-07-18 06:31:42,529 INFO  [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-orm, jdbc-h2, jdbc-mariadb, jdbc-mssql, jdbc-mysql, jdbc-oracle, jdbc-postgresql, keycloak, logging-gelf, micrometer, narayana-jta, reactive-routes, resteasy, resteasy-jackson, smallrye-context-propagation, smallrye-health, vertx]
2023-07-18 06:31:42,715 INFO  [org.keycloak.services] (main) KC-SERVICES0009: Added user 'admin' to realm 'master'
2023-07-18 06:32:34,241 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-6) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:32:34,245 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-6) Retry is true [empty]
2023-07-18 06:32:34,251 WARN  [org.keycloak.connections.httpclient.DefaultHttpClientFactory] (pool-3-thread-1) TruststoreProvider is disabled
2023-07-18 06:32:39,147 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-6) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:32:50,706 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-6) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:32:50,746 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-6) Retry is true [empty]
2023-07-18 06:32:51,072 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:32:53,513 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:32:58,598 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:32:58,624 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-4) Retry is true [empty]
2023-07-18 06:32:58,710 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:00,417 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:05,585 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:05,603 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-4) Retry is true [empty]
2023-07-18 06:33:05,846 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:07,245 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:12,159 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:12,171 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-4) Retry is true [empty]
2023-07-18 06:33:12,215 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:13,718 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:18,260 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:18,271 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-4) Retry is true [empty]
2023-07-18 06:33:18,482 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:19,850 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:25,866 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:25,879 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-4) Retry is true [empty]
2023-07-18 06:33:26,136 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:27,153 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:33,949 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:33,964 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-4) Retry is true [empty]
2023-07-18 06:33:34,115 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:36,399 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:41,393 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-4) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-18 06:33:41,405 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-4) Retry is true [empty]
2023-07-18 06:33:41,406 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-4) Uncaught server error: java.util.ConcurrentModificationException
    at java.base/java.util.HashMap$Values.forEach(HashMap.java:1068)
    at org.keycloak.services.DefaultKeycloakSession.close(DefaultKeycloakSession.java:384)
    at org.keycloak.quarkus.runtime.transaction.TransactionalSessionHandler.close(TransactionalSessionHandler.java:56)
    at org.keycloak.quarkus.runtime.integration.jaxrs.TransactionalResponseFilter.filter(TransactionalResponseFilter.java:48)
    at org.jboss.resteasy.core.interception.jaxrs.ContainerResponseContextImpl.filter(ContainerResponseContextImpl.java:329)
    at org.jboss.resteasy.core.ServerResponseWriter.executeFilters(ServerResponseWriter.java:243)
    at org.jboss.resteasy.core.ServerResponseWriter.writeNomapResponse(ServerResponseWriter.java:100)
    at org.jboss.resteasy.core.ServerResponseWriter.writeNomapResponse(ServerResponseWriter.java:73)
    at org.jboss.resteasy.core.SynchronousDispatcher.writeResponse(SynchronousDispatcher.java:518)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:458)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:240)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:229)
    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:82)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:147)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:84)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:44)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:58)
    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:36)
    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
    at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$0(QuarkusRequestFilter.java:82)
    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:833)

Could this be linked to the way I build the jar? 

mvn --version
Apache Maven 3.6.3
Maven home: /usr/share/maven
Java version: 17.0.7, vendor: Private Build, runtime: /usr/lib/jvm/java-17-openjdk-amd64
Default locale: en_US, platform encoding: UTF-8
OS name: "linux", version: "5.19.0-46-generic", arch: "amd64", family: "unix"

Here it the jar file, if it helps reproducing the behavior: keycloak-events-0.19-SNAPSHOT.zip

I'll also ask a colleague to build and run in another environment, maybe it's something broken on my setup.

xgp commented 1 year ago

Another question. Is it always after a certain number of failed attempts at sending an event over HTTP? I wonder if something like the thread pool that is used for retries getting exhausted, and no timeout set on the requests.

xgp commented 1 year ago

@ebiiii I think the issue is the use of the KeycloakSession inside the send(..) method. Can you checkout the xgp/issue-31 branch, build and try your same procedure? I added some logging and removed the use of the session from that method.

xgp commented 1 year ago

@ebiiii I was finally able to reproduce using the version from main. Seems intermittent. However, with the branch I sent https://github.com/p2-inc/keycloak-events/tree/xgp/issue-31 I have not been able to reproduce. Let me know what you observe.

ebiiii commented 1 year ago

@xgp Thanks a lot, it seems indeed to fix the issue. With the new branch, I wasn't able to reproduce it no matter how many times I created clients/changed settings. ( Meanwhile I also got feedback from my colleagues that were able to reproduce the issue from main on a mac and Windows (WSL2). )

Maybe of interest, in the logs I have such sequences:

2023-07-19 18:57:02,589 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-7) Retry is true [empty]
2023-07-19 18:57:02,589 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (pool-3-thread-5) attempting send to https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29
2023-07-19 18:57:02,626 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProviderFactory] (executor-thread-7) Configuring io.phasetwo.keycloak.events.HttpSenderEventListenerProvider with [targetUri=https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29,sharedSecret=abcd123]
2023-07-19 18:57:02,628 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (executor-thread-7) Retry is true [empty]
2023-07-19 18:57:02,629 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (pool-3-thread-3) attempting send to https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29
2023-07-19 18:57:02,948 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (pool-3-thread-5) sent to https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29 (200)
2023-07-19 18:57:02,951 INFO  [io.phasetwo.keycloak.events.HttpSenderEventListenerProvider] (pool-3-thread-3) sent to https://webhook.site/705ede69-982e-4059-8a8f-32bca35e3f29 (200)

Where two threads from the pool are sending events simultaneously (it seems some actions in the admin console, like changing realm parameters are generating two different events). Could it be that if they use the Keycloak Session for obtaining the provider that might be triggering the concurrency issue? (I'm not an expert, it's rather a guess here)

xgp commented 1 year ago

What is the concurrency issue? Are there duplicate events?

ebiiii commented 1 year ago

Ah, I meant the exception ConcurrentModificationException that could be caused by the fact that keycloak generates two events (they have a different content, so I don't think they are really duplicates) simultaneously and the HttpSenderEventListener sends both events in parallel. If your callback endpoint is fast enough, they might get sequential, possibly causing the difficulty in the reproducibility of this issue.

All in all, I'm not sure it's worth to dig deeper. Your solution works. :-)

xgp commented 1 year ago

fixed by #32