title: Keycloak: Persisted Cache Sync Timeouts to Infinispan Cluster on Rebuild From Embedded to Remote Infinispan
body: <p>I'm working on switching keycloak (v.3.4.0 final) from using embedded infinispan to a dedicated remote infinispan cluster (v8.2.8.final). I've gone through the upgrade process to use infinispan cluster as remote-store in lower environments without issues. In my production setting I am running into a timeout exception on InfinispanCacheInitializer</p>
  <p>Where error is happening on Keycloak: <a href="https://github.com/keycloak/keycloak/blob/3.4.2.Final/model/infinispan/src/main/java/org/keycloak/models/sessions/infinispan/initializer/InfinispanCacheInitializer.java#L117" rel="nofollow noreferrer">https://github.com/keycloak/keycloak/blob/3.4.2.Final/model/infinispan/src/main/java/org/keycloak/models/sessions/infinispan/initializer/InfinispanCacheInitializer.java#L117</a></p>
  <pre><code>ERROR [org.keycloak.models.sessions.infinispan.initializer.InfinispanCacheInitializer] (ServerService Thread Pool -- 54) ExecutionException when computed future. Errors: 13: java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutExc
  eption                                                                                                                                                                                                                                                                      
          at org.infinispan.distexec.DefaultExecutorService$DistributedTaskPart.get(DefaultExecutorService.java:850)                                                                                                                                                          
          at org.keycloak.models.sessions.infinispan.initializer.InfinispanCacheInitializer.startLoading(InfinispanCacheInitializer.java:102)                                                                                                                                 
          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:150)                                                                                                                                
          at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)                                                                                                                                                                    
          at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory.loadPersistentSessions(InfinispanUserSessionProviderFactory.java:137)                                                                                                               
          at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory$1.onEvent(InfinispanUserSessionProviderFactory.java:108)                                                                                                                            
          at org.keycloak.services.DefaultKeycloakSessionFactory.publish(DefaultKeycloakSessionFactory.java:68)                                                                                                                                                               
          at org.keycloak.services.resources.KeycloakApplication$2.run(KeycloakApplication.java:165)                                                                                                                                                                          
          at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)                                                                                                                                                                    
          at org.keycloak.services.resources.KeycloakApplication.&lt;init&gt;(KeycloakApplication.java:158)                                                                                                                                                                         
          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:150)                                                                                                                                                                      
          at org.jboss.resteasy.spi.ResteasyProviderFactory.createProviderInstance(ResteasyProviderFactory.java:2298)                                                                                                                                                         
          at org.jboss.resteasy.spi.ResteasyDeployment.createApplication(ResteasyDeployment.java:340)                                                                                                                                                                         
          at org.jboss.resteasy.spi.ResteasyDeployment.start(ResteasyDeployment.java:253)                                                                                                                                                                                     
          at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.init(ServletContainerDispatcher.java:120)                                                                                                                                                   
          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:250)                                                                                                                                                                   
          at io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:133)                                                                                                                                                                                   
          at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:565)                                                                                                                                                                            
          at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:536)                                                                                                                                                                            
          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:1508)                                                                                                       
          at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)                                                                                                       
          at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)                                                                                                       
          at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508)                                                                                                       
          at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:578)                                                                                                                                                                             
          at org.wildfly.extension.undertow.deployment.UndertowDeploymentService.startContext(UndertowDeploymentService.java:100)                                                                                                                                             
          at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:81)                                                                                                                                                     
          at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)                                                                                                                                                                                          
          at java.util.concurrent.FutureTask.run(FutureTask.java:266)                                                                                                                                                                                                         
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)                                                                                                                                                                                  
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)                                                                                                                                                                                  
          at java.lang.Thread.run(Thread.java:748)                                                                                                                                                                                                                            
          at org.jboss.threads.JBossThread.run(JBossThread.java:320)                                                                                                                                                                                                          
  Caused by: java.util.concurrent.TimeoutException                                                                                                                                                                                                                            
          at java.util.concurrent.FutureTask.get(FutureTask.java:205)                                                                                                                                                                                                         
          at org.infinispan.commons.util.concurrent.NotifyingFutureImpl.get(NotifyingFutureImpl.java:88)                                                                                                                                                                      
          at org.infinispan.distexec.DefaultExecutorService$LocalDistributedTaskPart.getResult(DefaultExecutorService.java:1083)                                                                                                                                              
          at org.infinispan.distexec.DefaultExecutorService$DistributedTaskPart.innerGet(DefaultExecutorService.java:868)                                                                                                                                                     
          at org.infinispan.distexec.DefaultExecutorService$DistributedTaskPart.get(DefaultExecutorService.java:848)                                                                                                                                                          
          ... 44 more
  </code></pre>
  <p><strong>Overview</strong></p>
  <ul>
  <li>Keycloak version: 3.4.0.final (aware this is an older version - and in use with custom
  implementation -  not easy to upgrade)
  <ul>
  <li>startup script: <code>ExecStart={{ keycloak_jboss_home }}/bin/standalone.sh -b</code> using standalone.xml</li>
  </ul>
  </li>
  <li>Infinispan version: 8.2.8.final</li>
  <li>Switching from embedded local cache to remote store configuration for the following caches:
  <ul>
  <li>users (distributed)</li>
  <li>sessions (replicated)</li>
  <li>authenticationSessions (replicated)</li>
  <li>offlineSessions (replicated)</li>
  <li>loginFailures (replicated)</li>
  <li>authorization (replicated)</li>
  </ul>
  </li>
  <li>offline_user_session count: ~3 million</li>
  </ul>
  <p>In an attempt to test out this sized cache sync from database, I've updated the configuration for timeouts in standalone.xml and standalone.conf files</p>
  <p><strong>keycloak/keycloak-3.4.0.Final/standalone/configuration/standalone.xml</strong>
  Updated coordinator timeout to be 3 hours and commented out query-timeout</p>
  <pre><code>&lt;subsystem xmlns=&quot;urn:jboss:domain:transactions:4.0&quot;&gt;                                                                                                                                                                                             
      &lt;core-environment&gt;                                                                                                                                                                                                                            
          &lt;process-id&gt;                                                                                                                                                                                                                              
              &lt;uuid/&gt;                                                                                                                                                                                                                               
           &lt;/process-id&gt;                                                                                                                                                                                                                             
      &lt;/core-environment&gt;                                                                                                                                                                                                                           
      &lt;recovery-environment socket-binding=&quot;txn-recovery-environment&quot; status-socket-binding=&quot;txn-status-manager&quot;/&gt;                                                                                                                                  
      &lt;object-store path=&quot;tx-object-store&quot; relative-to=&quot;jboss.server.data.dir&quot;/&gt;                                                                                                                                                                    
      &lt;coordinator-environment default-timeout=&quot;10800&quot;/&gt;                                                                                                                                                                                            
   &lt;/subsystem&gt; 
  
  ....
  ....
  ..
  
  &lt;!-- &lt;timeout&gt;                                                                                                                                                                                                                        
      &lt;query-timeout&gt;15&lt;/query-timeout&gt;                                                                                                                                                                                                 
  &lt;/timeout&gt;--&gt;   
  
  </code></pre>
  <p><strong>/keycloak/keycloak-3.4.0.Final/bin/standalone.conf</strong>
  add blocking timeout to JAVA_OPTS</p>
  <pre><code>JAVA_OPTS=&quot;$JAVA_OPTS -Djboss.modules.system.pkgs=$JBOSS_MODULES_SYSTEM_PKGS -Djava.awt.headless=true -Djboss.as.management.blocking.timeout=10800&quot;  
  </code></pre>
  <p>I'd like to note that after the first few attempts at getting this to work, when reverting back to using the embedded cache on the keycloak nodes, the data synced fine without any timeout errors in around 1.5 hours.</p>
  <p>After startup of keycloak it takes about 60 minutes before it starts to sync offline user sessions. Taking a look at the queries being run by keycloak, I can see that the timeout errors occur about 5-10 minutes after it starts syncing offline_user_session records to offlineSessions cache</p>
  <p><a href="https://i.stack.imgur.com/awDoV.png" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/awDoV.png" alt="enter image description here" /></a></p>
  <p>The queries being run before it times out are:</p>
  <ol>
  <li><p><code>delete from OFFLINE_CLIENT_SESSION where not (exists (select persistent1_.USER_SESSION_ID from OFFLINE_USER_SESSION persistent1_ where persistent1_.USER_SESSION_ID=OFFLINE_CLIENT_SESSION.USER_SESSION_ID))</code></p>
  </li>
  <li><p><code>update OFFLINE_USER_SESSION set LAST_SESSION_REFRESH=$1</code></p>
  </li>
  <li><p><code>DELETE FROM JGROUPSPING WHERE own_addr=$1 AND cluster_name=$2</code></p>
  </li>
  <li><p><code>select count(persistent0_.OFFLINE_FLAG) as col_0_0_ from OFFLINE_USER_SESSION persistent0_ where persistent0_.OFFLINE_FLAG=$1</code></p>
  </li>
  <li><p><code>select userrolema0_.ROLE_ID as col_0_0_ from USER_ROLE_MAPPING userrolema0_ where userrolema0_.USER_ID=$1</code></p>
  </li>
  <li><p><code>select userentity0_.ID as ID1_76_, userentity0_.CREATED_TIMESTAMP as CREATED_2_76_, userentity0_.EMAIL as EMAIL3_76_, userentity0_.EMAIL_CONSTRAINT as EMAIL_CO4_76_, userentity0_.EMAIL_VERIFIED as EMAIL_VE5_76_, userentity0_.ENABLED as ENABLED6_76_, userentity0_.FEDERATION_LINK as FEDERATI7_76_, userentity0_.FIRST_NAME as FIRST_NA8_76_, userentity0_.LAST_NAME as LAST_NAM9_76_, userentity0_.NOT_BEFORE as NOT_BEF10_76_, userentity0_.REALM_ID as REALM_I11_76_, userentity0_.SERVICE_ACCOUNT_CLIENT_LI</code></p>
  </li>
  <li><p><code>select attributes0_.USER_ID as USER_ID4_72_0_, attributes0_.ID as ID1_72_0_, attributes0_.ID as ID1_72_1_, attributes0_.NAME as NAME2_72_1_, attributes0_.USER_ID as USER_ID4_72_1_, attributes0_.VALUE as VALUE3_72_1_ from USER_ATTRIBUTE attributes0_ where attributes0_.USER_ID=$1</code></p>
  </li>
  <li><p><code>select persistent0_.OFFLINE_FLAG as OFFLINE_1_47_, persistent0_.USER_SESSION_ID as USER_SES2_47_, persistent0_.DATA as DATA3_47_, persistent0_.LAST_SESSION_REFRESH as LAST_SES4_47_, persistent0_.REALM_ID as REALM_ID5_47_, persistent0_.USER_ID as USER_ID6_47_ from OFFLINE_USER_SESSION persistent0_ where persistent0_.OFFLINE_FLAG=$1 order by persistent0_.USER_SESSION_ID limit $2 offset $3</code></p>
  </li>
  </ol>
  <p>I setup Infinispan WebConsole UI so I can see the progress of the cache sync. Every time it gets 15k entries in (out of the ~3 million)</p>
  <p><a href="https://i.stack.imgur.com/YqkFO.png" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/YqkFO.png" alt="enter image description here" /></a></p>
  <p>I am not positive the issue here since the syncing of offline sessions from database works fine for the embedded version, but for the remote infinispan startup it seems to have an issue either with the batching of the queries or there's another configuration I am missing either on keycloak of infinispan side.</p>
  <hr />
  <p>Update - further testing</p>
  <p>Setup a test environment with snapshot of database with 3.5 million OUS/OCS. The RDS instance was provisioned with 5500 IOPS. Upgrading to keycloak version 5.0, there were timeouts happening but running vacuum analyze on entire database resolved the issue and we were able to successfully standup remote infinispan. However, after successful runs, in our live environment we ran into the same timeouts and vacuum analyze did not fix the issue.</p>