search

ivangfr / keycloak-clustered

Keycloak-Clustered extends quay.io/keycloak/keycloak official Keycloak Docker image by adding JDBC_PING discovery protocol.
172 stars 57 forks source link

HA problem #11

Closed whitepiratebaku closed 2 years ago

whitepiratebaku commented 2 years ago

When one Keycloak goes down other side restarts, is it normal behaviour? can we make other stay up and do not restart?

Note: I have healtcheck and autoheal container, will check it maybe because of health endpoint it restarts Note2: No actually autoheal helps here, like it restarts kc2 and it becomes available in like 1-2 mins, if you dont restart it, it hangs because cant connect ispn1

ivangfr commented 2 years ago

What is the Keycloak version you are using? Are you using ivanfranchin/keycloak-clustered Docker image?

whitepiratebaku commented 2 years ago

Actually no, I use https://github.com/vzakharchenko/keycloak-radius-plugin but also include your infinispan (version 17.0.0) cache config from github(the one on docker image is a bit different for example JGROUPS_DISCOVERY_EXTERNAL_IP env not used in the config from your 17.0.0 docker image)

ivangfr commented 2 years ago

About the restart of a Keycloak instance after another being down, I don't think it's a normal behaviour. Maybe, you can see some logs appearing in the instance still up, but it might be related to the cluster changes (one of the instances going down)

whitepiratebaku commented 2 years ago

This is the debug log

`2022-03-16 10:53:12,556 ERROR [org.jgroups.protocols.JDBC_PING] (VERIFY_SUSPECT.TimerThread-16,ubuntu-58067) JGRP000115: Could not open connection to database: org.postgresql.util.PSQLException: FATAL: failed to create a backend 0 connection Detail: not executing failover because failover_on_backend_error is off at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:623) at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:163) at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:215) at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51) at org.postgresql.jdbc.PgConnection.(PgConnection.java:225) at org.postgresql.Driver.makeConnection(Driver.java:466) at org.postgresql.Driver.connect(Driver.java:265) at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:677) at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:228) at org.jgroups.protocols.JDBC_PING.getConnection(JDBC_PING.java:290) at org.jgroups.protocols.JDBC_PING.clearTable(JDBC_PING.java:353) at org.jgroups.protocols.JDBC_PING.removeAll(JDBC_PING.java:182) at org.jgroups.protocols.FILE_PING.handleView(FILE_PING.java:184) at org.jgroups.protocols.FILE_PING.down(FILE_PING.java:116) at org.jgroups.protocols.MERGE3.down(MERGE3.java:251) at org.jgroups.protocols.FD_SOCK.down(FD_SOCK.java:378) at org.jgroups.protocols.FailureDetection.down(FailureDetection.java:152) at org.jgroups.protocols.VERIFY_SUSPECT.down(VERIFY_SUSPECT.java:102) at org.jgroups.protocols.pbcast.NAKACK2.down(NAKACK2.java:555) at org.jgroups.protocols.UNICAST3.down(UNICAST3.java:595) at org.jgroups.protocols.pbcast.STABLE.down(STABLE.java:341) at org.jgroups.protocols.pbcast.GMS.installView(GMS.java:714) at org.jgroups.protocols.pbcast.ServerGmsImpl.handleViewChange(ServerGmsImpl.java:65) at org.jgroups.protocols.pbcast.GMS.castViewChangeAndSendJoinRsps(GMS.java:592) at org.jgroups.protocols.pbcast.CoordGmsImpl.handleMembershipChange(CoordGmsImpl.java:198) at org.jgroups.protocols.pbcast.GMS.process(GMS.java:1296) at org.jgroups.protocols.pbcast.ViewHandler.removeAndProcess(ViewHandler.java:286) at org.jgroups.protocols.pbcast.ViewHandler.process(ViewHandler.java:250) at org.jgroups.protocols.pbcast.ViewHandler.add(ViewHandler.java:71) at org.jgroups.protocols.pbcast.GMS.up(GMS.java:853) at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:247) at org.jgroups.stack.Protocol.up(Protocol.java:299) at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:583) at org.jgroups.protocols.VERIFY_SUSPECT.run(VERIFY_SUSPECT.java:191) at java.base/java.lang.Thread.run(Thread.java:829)

2022-03-16 10:53:12,558 ERROR [org.jgroups.protocols.pbcast.GMS] (VERIFY_SUSPECT.TimerThread-16,ubuntu-58067) failed processing requests: java.lang.NullPointerException at org.jgroups.protocols.JDBC_PING.clearTable(JDBC_PING.java:354) at org.jgroups.protocols.JDBC_PING.removeAll(JDBC_PING.java:182) at org.jgroups.protocols.FILE_PING.handleView(FILE_PING.java:184) at org.jgroups.protocols.FILE_PING.down(FILE_PING.java:116) at org.jgroups.protocols.MERGE3.down(MERGE3.java:251) at org.jgroups.protocols.FD_SOCK.down(FD_SOCK.java:378) at org.jgroups.protocols.FailureDetection.down(FailureDetection.java:152) at org.jgroups.protocols.VERIFY_SUSPECT.down(VERIFY_SUSPECT.java:102) at org.jgroups.protocols.pbcast.NAKACK2.down(NAKACK2.java:555) at org.jgroups.protocols.UNICAST3.down(UNICAST3.java:595) at org.jgroups.protocols.pbcast.STABLE.down(STABLE.java:341) at org.jgroups.protocols.pbcast.GMS.installView(GMS.java:714) at org.jgroups.protocols.pbcast.ServerGmsImpl.handleViewChange(ServerGmsImpl.java:65) at org.jgroups.protocols.pbcast.GMS.castViewChangeAndSendJoinRsps(GMS.java:592) at org.jgroups.protocols.pbcast.CoordGmsImpl.handleMembershipChange(CoordGmsImpl.java:198) at org.jgroups.protocols.pbcast.GMS.process(GMS.java:1296) at org.jgroups.protocols.pbcast.ViewHandler.removeAndProcess(ViewHandler.java:286) at org.jgroups.protocols.pbcast.ViewHandler.process(ViewHandler.java:250) at org.jgroups.protocols.pbcast.ViewHandler.add(ViewHandler.java:71) at org.jgroups.protocols.pbcast.GMS.up(GMS.java:853) at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:247) at org.jgroups.stack.Protocol.up(Protocol.java:299) at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:583) at org.jgroups.protocols.VERIFY_SUSPECT.run(VERIFY_SUSPECT.java:191) at java.base/java.lang.Thread.run(Thread.java:829)

2022-03-16 10:53:14,799 WARN [io.agroal.pool] (agroal-11) Datasource '': Closing connection in incorrect state VALIDATION 2022-03-16 10:53:14,801 WARN [io.agroal.pool] (agroal-11) Datasource '': Closing connection in incorrect state VALIDATION 2022-03-16 10:53:14,801 WARN [io.agroal.pool] (agroal-11) Datasource '': Closing connection in incorrect state VALIDATION 2022-03-16 10:53:14,802 WARN [io.agroal.pool] (agroal-11) Datasource '': Closing connection in incorrect state VALIDATION 2022-03-16 10:53:14,802 WARN [io.agroal.pool] (agroal-11) Datasource '': Closing connection in incorrect state VALIDATION 2022-03-16 10:53:26,956 WARN [io.agroal.pool] (agroal-11) Datasource '': FATAL: failed to create a backend 0 connection Detail: not executing failover because failover_on_backend_error is off 2022-03-16 10:53:26,958 INFO [io.smallrye.health] (executor-thread-22) SRHCK01001: Reporting health down status: {"status":"DOWN","checks":[{"name":"Keycloak database connections health check","status":"DOWN","data":{"Failing since":"2022-03-16 10:53:26,957"}}]} 2022-03-16 10:53:33,075 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p4-t1) ISPN000136: Error executing command TouchCommand on Cache 'sessions', writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 92 from consul1-43722 at org.infinispan.remoting.transport.impl.SingleTargetRequest.onTimeout(SingleTargetRequest.java:85) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

2022-03-16 10:53:33,076 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p4-t1) ISPN000136: Error executing command GetKeyValueCommand on Cache 'sessions', writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 92 from consul1-43722 at org.infinispan.remoting.transport.impl.SingleTargetRequest.onTimeout(SingleTargetRequest.java:85) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

2022-03-16 10:53:33,078 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-23) Uncaught server error: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 92 from consul1-43722 at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:258) at org.infinispan.cache.impl.InvocationHelper.doInvoke(InvocationHelper.java:297) at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:101) at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:542) at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:536) at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:439) at org.infinispan.cache.impl.EncoderCache.get(EncoderCache.java:683) at org.keycloak.models.sessions.infinispan.changes.InfinispanChangelogBasedTransaction.get(InfinispanChangelogBasedTransaction.java:128) at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider.getUserSessionEntity(InfinispanUserSessionProvider.java:328) at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider.getUserSession(InfinispanUserSessionProvider.java:261) at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider.getUserSessionWithPredicate(InfinispanUserSessionProvider.java:464) at org.keycloak.services.managers.UserSessionCrossDCManager.lambda$getUserSessionIfExistsRemotely$3(UserSessionCrossDCManager.java:72) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195) at java.base/java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1632) at java.base/java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:127) at java.base/java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:502) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:488) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) at java.base/java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:150) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:543) at org.keycloak.services.managers.UserSessionCrossDCManager.getUserSessionIfExistsRemotely(UserSessionCrossDCManager.java:82) at org.keycloak.protocol.AuthorizationEndpointBase.createAuthenticationSession(AuthorizationEndpointBase.java:189) at org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint.process(AuthorizationEndpoint.java:178) at org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint.buildGet(AuthorizationEndpoint.java:112) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170) at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130) at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660) at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524) at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474) at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364) at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476) at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434) at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:192) at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:152) at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:183) at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:141) at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:32) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492) at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261) at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161) at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364) at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247) at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73) at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151) at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:82) at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:42) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141) at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:67) at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:55) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:362) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:340) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141) at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$1(QuarkusRequestFilter.java:66) 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) Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 92 from consul1-43722 at org.infinispan.remoting.transport.impl.SingleTargetRequest.onTimeout(SingleTargetRequest.java:85) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ... 1 more Suppressed: org.infinispan.commons.util.logging.TraceException at org.infinispan.interceptors.impl.SimpleAsyncInvocationStage.get(SimpleAsyncInvocationStage.java:39) at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:249) at org.infinispan.cache.impl.InvocationHelper.doInvoke(InvocationHelper.java:297) at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:101) at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:542) at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:536) at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:439) at org.infinispan.cache.impl.EncoderCache.get(EncoderCache.java:683) at org.keycloak.models.sessions.infinispan.changes.InfinispanChangelogBasedTransaction.get(InfinispanChangelogBasedTransaction.java:128) at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider.getUserSessionEntity(InfinispanUserSessionProvider.java:328) at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider.getUserSession(InfinispanUserSessionProvider.java:261) at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProvider.getUserSessionWithPredicate(InfinispanUserSessionProvider.java:464) at org.keycloak.services.managers.UserSessionCrossDCManager.lambda$getUserSessionIfExistsRemotely$3(UserSessionCrossDCManager.java:72) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195) at java.base/java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1632) at java.base/java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:127) at java.base/java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:502) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:488) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) at java.base/java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:150) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:543) at org.keycloak.services.managers.UserSessionCrossDCManager.getUserSessionIfExistsRemotely(UserSessionCrossDCManager.java:82) at org.keycloak.protocol.AuthorizationEndpointBase.createAuthenticationSession(AuthorizationEndpointBase.java:189) at org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint.process(AuthorizationEndpoint.java:178) at org.keycloak.protocol.oidc.endpoints.AuthorizationEndpoint.buildGet(AuthorizationEndpoint.java:112) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170) at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130) at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660) at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524) at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474) at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364) at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476) at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434) at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:192) at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:152) at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:183) at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:141) at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:32) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492) at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261) at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161) at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364) at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247) at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73) at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151) at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:82) at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:42) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141) at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:67) at io.quarkus.vertx.http.runtime.StaticResourcesRecorder$2.handle(StaticResourcesRecorder.java:55) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:362) at io.quarkus.vertx.http.runtime.VertxHttpRecorder$5.handle(VertxHttpRecorder.java:340) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141) at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$1(QuarkusRequestFilter.java:66) 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) ... 1 more

2022-03-16 10:53:33,515 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p4-t1) ISPN000136: Error executing command PutKeyValueCommand on Cache 'work', writing keys [task::RadiusLogout$$Lambda$810/0x0000000840970440]: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 93 from consul1-43722 at org.infinispan.remoting.transport.impl.SingleTargetRequest.onTimeout(SingleTargetRequest.java:85) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

2022-03-16 10:53:48,521 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p4-t1) ISPN000136: Error executing command PutKeyValueCommand on Cache 'work', writing keys [task::RadiusLogout$$Lambda$810/0x0000000840970440]: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 94 from consul1-43722 at org.infinispan.remoting.transport.impl.SingleTargetRequest.onTimeout(SingleTargetRequest.java:85) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

2022-03-16 10:54:03,561 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p4-t1) ISPN000136: Error executing command PutKeyValueCommand on Cache 'work', writing keys [task::RadiusLogout$$Lambda$810/0x0000000840970440]: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 95 from consul1-43722 at org.infinispan.remoting.transport.impl.SingleTargetRequest.onTimeout(SingleTargetRequest.java:85) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)`

whitepiratebaku commented 2 years ago

kc.log added log file

ivangfr commented 2 years ago

Could not open connection to database: org.postgresql.util.PSQLException .. Are the creds to access the DB ok?

whitepiratebaku commented 2 years ago

Sorry, it is not related to Keycloak but Postgresql, I use repmgr replicated postgresql+pg-pool and there is some issues . Sorry for taking your time.

whitepiratebaku commented 2 years ago

JDBC_PING causes this, it tries to ping other database right?

ivangfr commented 2 years ago

If you are using JDBC_PING, it will try to access JGROUPSPING table in the DB you configured.

whitepiratebaku commented 2 years ago

yes, I having strange behaviour despite I have set JGROUPS_DISCOVERY_EXTERNAL_IP differently on both docker-compose files in database they use one ip address, address of primary. Let me do some tests to understand what is going on, do you have implementation for TCPPING too?

whitepiratebaku commented 2 years ago

Is it normal behaviour? both getting same IP, the first one wins everytime. I even tried adding harcoded IP addresses but it is like replicated from first keycloak. "667eaa34-72ec-478e-ac6d-ad125f041ed2" "ISPN" "172.16.81.192" "2022-03-16 13:38:20.049917" "binary data" "02efe9e9-2896-4a07-9c55-10a9e7a1a0c6" "ISPN" "172.16.81.192" "2022-03-16 13:38:20.164684" "binary data"

Note: my setup uses replicated postgresql+pg-pool , keycloaks are connecting to pg-pool on their site, so kc1 connects pgpool1 and kc2 connects pgpool2 but on database first one wins

zdykstra commented 2 years ago

Is it normal behaviour? both getting same IP, the first one wins everytime. I even tried adding harcoded IP addresses but it is like replicated from first keycloak. "667eaa34-72ec-478e-ac6d-ad125f041ed2" "ISPN" "172.16.81.192" "2022-03-16 13:38:20.049917" "binary data" "02efe9e9-2896-4a07-9c55-10a9e7a1a0c6" "ISPN" "172.16.81.192" "2022-03-16 13:38:20.164684" "binary data"

Note: my setup uses replicated postgresql+pg-pool , keycloaks are connecting to pg-pool on their site, so kc1 connects pgpool1 and kc2 connects pgpool2 but on database first one wins

Yes, the first one that connects marks itself as the controller/master instance. It then (by default) takes control of the table and re-inserts any new peers. The IP column isn't needed; and more importantly the values written in it are always the IP of the master instance in the cluster.

Below is a working postgres jgroups section for the cache XML document:

    <jgroups>
        <stack name="postgres-jdbc-ping-tcp" extends="tcp">
            <TCP use_ip_addrs="true"
                 bind_addr="match-interface:eth0" />
            <JDBC_PING connection_driver="org.postgresql.Driver"
                       connection_username="${env.KC_DB_USERNAME}" connection_password="${env.KC_DB_PASSWORD}"
                       connection_url="jdbc:postgresql://${env.KC_DB_URL_HOST}/${env.KC_DB_URL_DATABASE}"
                       initialize_sql="CREATE SCHEMA IF NOT EXISTS ${env.KC_DB_SCHEMA:public}; CREATE TABLE IF NOT EXISTS ${env.KC_DB_SCHEMA:public}.JGROUPSPING (own_addr varchar(200) NOT NULL, cluster_name varchar(200) NOT NULL, updated timestamp default current_timestamp, ping_dat
a BYTEA, constraint PK_JGROUPSPING PRIMARY KEY (own_addr, cluster_name));"
                       info_writer_sleep_time="500"
                       remove_all_data_on_view_change="true"
                       stack.combine="REPLACE"
                       stack.position="MPING" />
        </stack>
    </jgroups>

Note the two additional keys - use_ip_addrs will cause it to insert a variation of the containers hostname instead of a UUID-encoded hostname value. match_addr specifies to which interface it should bind AND send to the jgroupsping table. Adjust eth0 to line up with your hardware.

whitepiratebaku commented 2 years ago

Thanks, so that is not the source of problem then, why when this master goes down I get following errors and other keycloak cant recover himself. But if Secondary keycloak goes down master works fine.

Note: you mean that changes will fix it?

Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 56 from consul1-38657

whitepiratebaku commented 2 years ago

So, I think I got it. It happens when primary postgresql goes down, when primary goes down there is like 30 seconds time interval when others choose new primary doring that time looks like keycloak cant update jgroupsping table and tries to connect master ISPN(which is down but because db was unavailable keycloak was not able to update jgroupsping table). Looks like I need active/active db or maybe tcp ping can help.

whitepiratebaku commented 2 years ago

Can I make keycloak jdpc ping to retry a couple of times if it cant update table?