Healthcheck error flooding the log: ERROR [io.quarkus.vertx.http.runtime.QuarkusErrorHandler] on health check

[Dill-Dall]

Version: Keycloak 17.0.0
Environment: Container/Pod running in k8s

Keycloaks logs gets flooded with vertx errors from health check, although health checks seem to work fine.

The health works fine when k8 does runs it. Both locally from the pod and externally. So I dont actually understand where the error is coming from.

I think this is part of the quarkusio/quarkus#5809. But shouldn't it then have been fixed?

2022-03-03 15:55:35,222 ERROR [io.quarkus.vertx.http.runtime.QuarkusErrorHandler] (vert.x-eventloop-thread-0) HTTP Request to /auth/q/health/live failed, error id: cb292e62-eee9-4c9b-b003-6cfca2b9d8b4-2: java.lang.IllegalStateException: Result is already complete at io.vertx.core.Promise.fail(Promise.java:90) at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$configureEndHandler$2(QuarkusRequestFilter.java:92) at io.vertx.ext.web.impl.RoutingContextImpl.lambda$null$0(RoutingContextImpl.java:545) at io.vertx.ext.web.impl.SparseArray.forEachInReverseOrder(SparseArray.java:40) at io.vertx.ext.web.impl.RoutingContextImpl.lambda$getHeadersEndHandlers$1(RoutingContextImpl.java:545) at io.vertx.core.http.impl.Http1xServerResponse.prepareHeaders(Http1xServerResponse.java:707) at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:411) at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:391) at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase.doHandle(SmallRyeHealthHandlerBase.java:52) at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase.handle(SmallRyeHealthHandlerBase.java:31) at io.quarkus.smallrye.health.runtime.SmallRyeLivenessHandler.handle(SmallRyeLivenessHandler.java:7) at io.quarkus.smallrye.health.runtime.SmallRyeHealthHandlerBase.handle(SmallRyeHealthHandlerBase.java:19) at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48) 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:543) 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)

I dont know if this is linked but I also get these arjuna warnings

2022-03-03 16:00:05,280 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check processing TX 0:ffff0a90239e:a563:6220e44b:69 in state RUN 2022-03-03 16:00:05,281 INFO [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012404: Action id 0:ffff0a90239e:a563:6220e44b:69 - thread executor-thread-2 at time 15:58:05.279 had stackTrace 2022-03-03 16:00:05,282 INFO [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012404: Action id 0:ffff0a90239e:a563:6220e44b:69 - thread executor-thread-2 at time 15:58:35.279 had stackTrace 2022-03-03 16:00:05,282 INFO [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012404: Action id 0:ffff0a90239e:a563:6220e44b:69 - thread executor-thread-2 at time 15:59:05.279 had stackTrace 2022-03-03 16:00:05,282 INFO [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012404: Action id 0:ffff0a90239e:a563:6220e44b:69 - thread executor-thread-2 at time 15:59:35.279 had stackTrace 2022-03-03 16:00:05,283 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff0a90239e:a563:6220e44b:69 invoked while multiple threads active within it. 2022-03-03 16:00:05,284 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff0a90239e:a563:6220e44b:69 completed with multiple threads - thread executor-thread-2 was in progress with 2022-03-03 16:00:05,284 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff0a90239e:a563:6220e44b:69 aborting with 1 threads active! 2022-03-03 16:00:05,284 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff0a90239e:a563:6220e44b

[kkcmadhu]

yes i too keep seeing such errors, and i also see high cpu usage duing this time.

[pedroigor]

@ThomasDahll @kkcmadhu This should be fixed by #11507.

Basically, there was an issue in our health endpoints preventing transactions from completing. FYI, the root cause is due to the fact that MP Health always runs in a separate (blocking) thread even though the request was previously dispatched to run in a worker thread.

[kkcmadhu]

Thanks @pedroigor , also for my keycloak pods i have allocated 2 core in k8s, and i have 4 pods ..
even when there is no traffic or load on keycloak (idle), i see that there is something which runs every 20 mins and keeps running for almost 10 mins and peaks to 50% cpu (1 core).. not sure if this is related.. but this pattern looks little weird.

I suspect it to be some backgroud job (session or offline token or event).. i tried disabling events in my realms and that too did not help.. Any idea what could this be ?

[pedroigor]

The best guess I have is exactly what you suggested: background jobs like those related to sessions.

And that makes a bit more sense if you have offline sessions persisted into the database.

You can try to change the spi-scheduled-interval option and set a value there to see if it has an impact on that graph.

[kkcmadhu]

What worries me is i don see the same in keycloak17, i see these pattern only after keycloak18 upgrade. Sent from Yahoo Mail on Android On Wed, 17 Aug 2022 at 12:54 am, Pedro ***@***.***> wrote: The best guess I have is exactly what you suggested: background jobs like those related to sessions. And that makes a bit more sense if you have offline sessions persisted into the database. You can try to change the spi-scheduled-interval option and set a value there to see if it has an impact on that graph. — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.Message ID: ***@***.***>

[pedroigor]

@kkcmadhu Would you mind sharing more details about your deployment:

• If using offline sessions and how many persisted
• If events are enabled and how many events

I would like to see if we can somehow reproduce here.

[kkcmadhu]

events, i keep the out of box keycloak event listener not persist anything to event tables. I always see events db cleanup threads taking too much time resource and blocks a lot of stuff (especailly when i have 200 + realms).. In my setting i have a custom event listener which publishes events to an http endpoint, and persists in seperate db... so i dont suspect events at this point.

offline tokens i dont have any to best of my knoweldge,.

I will double check on both of these and confirm.