/health/ready intermittently fails, with no reason given #14551

benzitohhh · 2022-09-22T21:18:13Z

benzitohhh
Sep 22, 2022

Hi there,

calls to /health/ready mostly work fine.

But every few hours they return a 500 error. Then calls a few seconds later work fine again.

From looking at the source code in KeycloakReadyHealthCheck.java, it seems the health check is just verifying the connection to MySQL, which should be fine.

Weirdly, no details about the error is written to the log.

I tried to get more logging information by:

In keycloak.conf, setting log-level=debug
In conf/quarkus.properties, setting quarkus.http.access-log.enabled=true and quarkus.log.level=DEBUG

I would expect to see something in the logs like this:

keycloak-service    | 2022-09-22 14:04:08,578 INFO  [io.smallrye.health] (executor-thread-0) SRHCK01001: Reporting health down status: {"status":"DOWN","checks":[{"name":"Keycloak database connections health check","status":"DOWN","data":{"Failing since":"2022-09-22 14:04:08,576"}}]}

But there is no message like this (see full log excerpt below).

We are running Keycloak 19.0.1, on kubernetes, with 2 pods, behind a load balancer, connecting to MySQL.

Keycloak runs in http on the pods. A load balancer handles the https stuff.

And we access all endpoints using the /auth prefix (KC_HTTP_RELATIVE_PATH=/auth)

Weirdly, we have not seen this problem when we use the normal endpoints (i.e. no KC_HTTP_RELATIVE_PATH specified).

Our buildtime-config is:

    KC_DB=mysql
    KC_HEALTH_ENABLED=true
    KC_METRICS_ENABLED=true
    KC_HTTP_RELATIVE_PATH=/auth

Our runtime .conf file is:

    db=mysql
    db-url-port=3306
    db-username=xxxx
    db-password=xxxx
    db-url-host=xxx
    db-url-database=keycloak
    health-enabled=true
    metrics-enabled=true
    http-enabled=enabled
    hostname-strict=false
    hostname-strict-https=false
    log-level=debug
    proxy=edge
    cache=ispn
    cache-stack=kubernetes

And our runtime conf/quarkus.properties file is:

quarkus.http.access-log.enabled=true
quarkus.log.level=DEBUG

And we set the following environment variables:

        JGROUPS_DISCOVERY_PROTOCOL=dns.DNS_PING
        JGROUPS_DISCOVERY_PROPERTIES="dns_query=xxxx-xxxxxx-svc"
        CACHE_OWNERS_COUNT="2"
        CACHE_OWNERS_AUTH_SESSIONS_COUNT="2"
        PROXY_ADDRESS_FORWARDING="true"
        JAVA_OPTS="-Djgroups.dns.query=xxxx-xxxxxx-svc"

Here is an excerpt from our logs. Notice the first /auth/health/ready gives an HTTP 500 error, but the one 5 seconds later gives a 200 fine:

2022-09-22 15:49:31,034 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1307/0x0000000840bb6c40
2022-09-22 15:49:36,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) new JtaTransactionWrapper
2022-09-22 15:49:36,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) was existing? false
2022-09-22 15:49:36,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper  commit
2022-09-22 15:49:36,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper end
2022-09-22 15:49:36,034 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1307/0x0000000840bb6c40
2022-09-22 15:49:41,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) new JtaTransactionWrapper
2022-09-22 15:49:41,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) was existing? false
2022-09-22 15:49:41,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper  commit
2022-09-22 15:49:41,034 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper end
2022-09-22 15:49:41,034 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1307/0x0000000840bb6c40
2022-09-22 15:49:46,035 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) new JtaTransactionWrapper
2022-09-22 15:49:46,035 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) was existing? false
2022-09-22 15:49:46,035 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper  commit
2022-09-22 15:49:46,035 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper end
2022-09-22 15:49:46,035 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1307/0x0000000840bb6c40
2022-09-22 15:49:46,705 DEBUG [io.quarkus.vertx.http.runtime.ForwardedParser] (vert.x-eventloop-thread-0) Recalculated absoluteURI to http://10.30.4.231:8080/auth/health/ready
2022-09-22 15:49:46,706 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-7) new JtaTransactionWrapper
2022-09-22 15:49:46,706 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-7) was existing? true
2022-09-22 15:49:46,707 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Suspending transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:d84 status: ActionStatus.ABORTED >
2022-09-22 15:49:46,707 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Resuming transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:d84 status: ActionStatus.ABORTED >
2022-09-22 15:49:46,707 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Suspending transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:d84 status: ActionStatus.ABORTED >
2022-09-22 15:49:46,707 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Resuming transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:d84 status: ActionStatus.ABORTED >
2022-09-22 15:49:46,707 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Suspending transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:d84 status: ActionStatus.ABORTED >
2022-09-22 15:49:46,707 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Resuming transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:d84 status: ActionStatus.ABORTED >
2022-09-22 15:49:46,708 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-5) JtaTransactionWrapper  commit
2022-09-22 15:49:46,708 WARN  [com.arjuna.ats.arjuna] (executor-thread-5) ARJUNA012077: Abort called on already aborted atomic action 0:ffff0a1e04e7:afd3:632c6e74:d84
2022-09-22 15:49:46,708 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-5) JtaTransactionWrapper end
2022-09-22 15:49:46,708 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-5) JtaTransactionWrapper resuming suspended
2022-09-22 15:49:46,708 INFO  [io.quarkus.http.access-log] (executor-thread-5) 10.30.4.103 - - 22/Sep/2022:15:49:46 +0000 "GET /auth/health/ready HTTP/1.1" 500 159
2022-09-22 15:49:51,037 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) new JtaTransactionWrapper
2022-09-22 15:49:51,037 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) was existing? false
2022-09-22 15:49:51,037 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper  commit
2022-09-22 15:49:51,037 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper end
2022-09-22 15:49:51,037 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1307/0x0000000840bb6c40
2022-09-22 15:49:51,075 DEBUG [org.keycloak.models.cache.infinispan.UserCacheManager] (jgroups-114,cipher-login-03-0-23915) [cipher-login-03-0-23915] Invalidating 2 cache items after received event UserUpdatedEvent [ userId=3bcef9e9-5225-4b2b-b521-c1d78c24ece7, username=frontendserver, email=null ]
2022-09-22 15:49:51,089 DEBUG [org.keycloak.models.cache.infinispan.UserCacheManager] (jgroups-114,cipher-login-03-0-23915) [cipher-login-03-0-23915] Invalidating 2 cache items after received event UserUpdatedEvent [ userId=3bcef9e9-5225-4b2b-b521-c1d78c24ece7, username=frontendserver, email=null ]
2022-09-22 15:49:51,447 DEBUG [org.keycloak.models.cache.infinispan.UserCacheManager] (jgroups-114,cipher-login-03-0-23915) [cipher-login-03-0-23915] Invalidating 2 cache items after received event UserUpdatedEvent [ userId=3bcef9e9-5225-4b2b-b521-c1d78c24ece7, username=frontendserver, email=null ]
2022-09-22 15:49:51,476 DEBUG [org.keycloak.models.cache.infinispan.UserCacheManager] (jgroups-114,cipher-login-03-0-23915) [cipher-login-03-0-23915] Invalidating 2 cache items after received event UserUpdatedEvent [ userId=3bcef9e9-5225-4b2b-b521-c1d78c24ece7, username=frontendserver, email=null ]
2022-09-22 15:49:51,839 DEBUG [io.quarkus.vertx.http.runtime.ForwardedParser] (vert.x-eventloop-thread-1) Recalculated absoluteURI to http://10.30.4.103:30434/auth/health
2022-09-22 15:49:51,842 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-7) new JtaTransactionWrapper
2022-09-22 15:49:51,842 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-7) was existing? true
2022-09-22 15:49:51,843 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Suspending transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:9d8 status: ActionStatus.ABORTED >
2022-09-22 15:49:51,843 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-7) JtaTransactionWrapper  commit
2022-09-22 15:49:51,843 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Resuming transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:9d8 status: ActionStatus.ABORTED >
2022-09-22 15:49:51,843 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Suspending transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:9d8 status: ActionStatus.ABORTED >
2022-09-22 15:49:51,843 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Resuming transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:9d8 status: ActionStatus.ABORTED >
2022-09-22 15:49:51,843 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Suspending transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:9d8 status: ActionStatus.ABORTED >
2022-09-22 15:49:51,843 FINE  [io.smallrye.context.jta.context.propagation.JtaContextProvider] (executor-thread-5) Resuming transaction TransactionImple < ac, BasicAction: 0:ffff0a1e04e7:afd3:632c6e74:9d8 status: ActionStatus.ABORTED >
2022-09-22 15:49:51,843 INFO  [io.quarkus.http.access-log] (executor-thread-5) 10.30.4.103 - - 22/Sep/2022:15:49:51 +0000 "GET /auth/health HTTP/1.1" 200 159

Any ideas what could be causing this?

Or how I can add more logging to show what is going on?

@pedroigor Could it be related to this issue: #10575 (perhaps the blocking Health thread preventing a db transaction from finishing?)

Thanks!

Ben

Answered by pedroigor

Oct 17, 2022

@benzitohhh It might be related to #14227. Could you please try 19.0.3?

View full answer

pedroigor · 2022-10-17T14:13:00Z

pedroigor
Oct 17, 2022
Collaborator

@benzitohhh It might be related to #14227. Could you please try 19.0.3?

2 replies

thanks for letting us know @pedroigor - just checking now - will get back to you soon

benzitohhh Oct 19, 2022
Author

@pedroigor Ok so far seems really stable (it's been running about 2 days now) - thanks!

Answer selected by pedroigor

Navigation Menu

Repository navigation

/health/ready intermittently fails, with no reason given #14551

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 1 comment 2 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

/health/ready intermittently fails, with no reason given #14551

Uh oh!

Uh oh!

benzitohhh Sep 22, 2022

Replies: 1 comment · 2 replies

Uh oh!

pedroigor Oct 17, 2022 Collaborator

Uh oh!

benzitohhh Oct 17, 2022 Author

Uh oh!

benzitohhh Oct 19, 2022 Author

benzitohhh
Sep 22, 2022

Replies: 1 comment 2 replies

pedroigor
Oct 17, 2022
Collaborator

benzitohhh Oct 17, 2022
Author

benzitohhh Oct 19, 2022
Author