session loader worker timeout

[Christian Becker]

I'm currently migrating a cluster from 3.4.3 to 4.8.18 and as this requires a cold start of the full cluster including session load from the database, I'm heavily optimizing the startup process.

I was playing with the sessionsPerSegment value to reduce the number of seqments (due to the expensive query on PostgreSQL). However there seems to be a timeout connected to the tasks in InfinispanCacheInitializer. Unfortunately the stack trace is cut short exactly at the interesting part, but maybe somebody can tell me what value I'm looking for.

2020-04-03 14:50:59,369 ERROR [org.keycloak.models.sessions.infinispan.initializer.InfinispanCacheInitializer] (ServerService Thread Pool -- 63) ExecutionException when computed future. Errors: 1: java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException

        at org.infinispan.distexec.DefaultExecutorService$DistributedTaskPart.get(DefaultExecutorService.java:853)

        at org.keycloak.models.sessions.infinispan.initializer.InfinispanCacheInitializer.startLoadingImpl(InfinispanCacheInitializer.java:156)

        at org.keycloak.models.sessions.infinispan.initializer.InfinispanCacheInitializer.startLoading(InfinispanCacheInitializer.java:100)

        at org.keycloak.models.sessions.infinispan.initializer.DBLockBasedCacheInitializer.startLoading(DBLockBasedCacheInitializer.java:75)

        at org.keycloak.models.sessions.infinispan.initializer.CacheInitializer.loadSessions(CacheInitializer.java:41)

        at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory$2.run(InfinispanUserSessionProviderFactory.java:186)

        at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)

        at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory.loadPersistentSessions(InfinispanUserSessionProviderFactory.java:172)

        at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory$1.lambda$onEvent$0(InfinispanUserSessionProviderFactory.java:126)

        at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)

        at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransactionWithTimeout(KeycloakModelUtils.java:267)

        at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory$1.onEvent(InfinispanUserSessionProviderFactory.java:122)

        at org.keycloak.services.DefaultKeycloakSessionFactory.publish(DefaultKeycloakSessionFactory.java:69)

        at org.keycloak.services.resources.KeycloakApplication.<init>(KeycloakApplication.java:174)

        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)

        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)

        at org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:154)

        at org.jboss.resteasy.spi.ResteasyProviderFactory.createProviderInstance(ResteasyProviderFactory.java:2757)

        at org.jboss.resteasy.spi.ResteasyDeployment.createApplication(ResteasyDeployment.java:363)

        at org.jboss.resteasy.spi.ResteasyDeployment.startInternal(ResteasyDeployment.java:276)

        at org.jboss.resteasy.spi.ResteasyDeployment.start(ResteasyDeployment.java:88)

        at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.init(ServletContainerDispatcher.java:119)

        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.init(HttpServletDispatcher.java:36)

        at io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:117)

        at org.wildfly.extension.undertow.security.RunAsLifecycleInterceptor.init(RunAsLifecycleInterceptor.java:78)

        at io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:103)

        at io.undertow.servlet.core.ManagedServlet$DefaultInstanceStrategy.start(ManagedServlet.java:305)

        at io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:145)

        at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:585)

        at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:556)

        at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:42)

        at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)

        at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)

        at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)

        at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)

        at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)

        at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)

        at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:598)

        at org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:97)

        at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:78)

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

        at java.util.concurrent.FutureTask.run(FutureTask.java:266)

        at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)

        at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1985)

        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487)

        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378)

        at java.lang.Thread.run(Thread.java:748)

        at org.jboss.threads.JBossThread.run(JBossThread.java:485)

Caused by: java.util.concurrent.TimeoutException

        at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1784)

        at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1928)

        at org.infinispan.distexec.DefaultExecutorService$DistributedTaskPart.getResult(DefaultExecutorService.java:896)

        at org.infinispan.distexec.DefaultExecutorService$DistributedTaskPart.innerGet(DefaultExecutorService.java:870)

        at org.infinispan.distexec.DefaultExecutorService$DistributedTaskPart.get(DefaultExecutorService.java:851)

        ... 49 more

In this case the SQL queries are taking ~6 seconds, so the timeout must be smaller than that. I'm well aware, that it might not be recommended to change that value, but I'm looking for any option, that will allow me to speed up the startup phase. (I would only change that value temporarily).

Due to the fact, that the session retrieval from the database scans the whole database eventually, my thought was doing that in as few segments as possible. I need to load ~1 Million sessions from the database and I've got only a very short maintenance window where keycloak can be completely unavailable.

So my main question would be: What setting can i change to increase this timeout and which would allow me to use huge segments with multiple thousand records.

Alternatively: any hints for a quick upgrade are highly appreciated.

Thank you,

Cheers,

Christian

[Mariusz Pacek]

Hi

We face similar problem like you. We don't have any clue how to resolve that but might you can take a look on our findings: https://groups.google.com/forum/#!topic/keycloak-user/HT2Hq6OcHOo

Mariusz