Uploaded image for project: 'Keycloak'
  1. Keycloak
  2. KEYCLOAK-7745

JTA error if offline sessions can't be preloaded at startup within 5 minutes

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved (View Workflow)
    • Priority: Major
    • Resolution: Done
    • Affects Version/s: 4.0.0.Final
    • Fix Version/s: 4.1.0.Final
    • Component/s: None
    • Labels:
    • Sprint:
      Keycloak Sprint 8
    • Story Points:
      4
    • Workaround:
      Workaround Exists
    • Workaround Description:
      Hide

      Both server startup timeout and JTA transaction timeout needs to be increased to bigger value.

      • Server startup timeout can be increased by adding the system property "jboss.as.management.blocking.timeout" . For example to increase to 1 hour instead of 5 minutes, start the server through:

        ./standalone.sh -Djboss.as.management.blocking.timeout=3600
        

      • Transaction timeout can be increased by editing the transaction subsystem in standalone(-ha).xml file and adding the coordinator-environment element together with default-timeout attribute. For example something like this:

      <subsystem xmlns="urn:jboss:domain:transactions:4.0">
          ...
          <coordinator-environment default-timeout="3600"/>
      </subsystem>
      

      Show
      Both server startup timeout and JTA transaction timeout needs to be increased to bigger value. Server startup timeout can be increased by adding the system property "jboss.as.management.blocking.timeout" . For example to increase to 1 hour instead of 5 minutes, start the server through: ./standalone.sh -Djboss.as.management.blocking.timeout=3600 Transaction timeout can be increased by editing the transaction subsystem in standalone(-ha).xml file and adding the coordinator-environment element together with default-timeout attribute. For example something like this: <subsystem xmlns="urn:jboss:domain:transactions:4.0"> ... <coordinator-environment default-timeout="3600"/> </subsystem>
    • Docs QE Status:
      NEW
    • QE Status:
      NEW

      Description

      Right now, Keycloak requires to preload offline sessions from DB at startup.

      In case that Keycloak fails to do it within 5 minutes (usually happens if there is some (or more) aspects like: a) many offline sessions, b) slower connection to DB, c) Custom UserStorage provider with slower connection to DB) there is an exception in server.log and server fails to start:

      2018-06-30 00:22:29,457 DEBUG [org.keycloak.models.sessions.infinispan.initializer.InfinispanCacheInitializer] (ServerService Thread Pool -- 64) New initializer state pushed. The state is: sessionsCount: 16
      2869, finished segments count: 1629, non-finished segments count: 1629
      2018-06-30 00:22:29,467 DEBUG [org.keycloak.models.sessions.infinispan.initializer.OfflinePersistentUserSessionLoader] (ServerService Thread Pool -- 64) Persistent sessions loaded successfully!
      2018-06-30 00:22:29,477 DEBUG [org.keycloak.models.sessions.infinispan.initializer.OfflinePersistentUserSessionLoader] (ServerService Thread Pool -- 64) Persistent sessions loaded already.
      2018-06-30 00:22:29,478 WARN  [com.arjuna.ats.arjuna] (ServerService Thread Pool -- 64) ARJUNA012077: Abort called on already aborted atomic action 0:ffffac199023:-56a74a79:5b363ba2:2e
      2018-06-30 00:22:29,482 WARN  [com.arjuna.ats.arjuna] (ServerService Thread Pool -- 64) ARJUNA012077: Abort called on already aborted atomic action 0:ffffac199023:-56a74a79:5b363ba2:26
      2018-06-30 00:22:29,582 INFO  [org.jboss.as.server] (Thread-2) WFLYSRV0220: Server shutdown has been requested via an OS signal
      2018-06-30 00:22:29,587 ERROR [org.jboss.msc.service.fail] (ServerService Thread Pool -- 64) MSC000001: Failed to start service jboss.undertow.deployment.default-server.default-host./auth: org.jboss.msc.ser
      vice.StartException in service jboss.undertow.deployment.default-server.default-host./auth: java.lang.RuntimeException: RESTEASY003325: Failed to construct public org.keycloak.services.resources.KeycloakApp
      lication(javax.servlet.ServletContext,org.jboss.resteasy.core.Dispatcher)
              at org.wildfly.extension.undertow.deployment.UndertowDeploymentService$1.run(UndertowDeploymentService.java:84)
              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.lang.RuntimeException: RESTEASY003325: Failed to construct public org.keycloak.services.resources.KeycloakApplication(javax.servlet.ServletContext,org.jboss.resteasy.core.Dispatcher)
              at org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:162)
              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)
              ... 6 more
      Caused by: java.lang.RuntimeException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffffac199023:-56a74a79:5b363ba2:2e
              at org.keycloak.transaction.JtaTransactionWrapper.handleException(JtaTransactionWrapper.java:77)
              at org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTransactionWrapper.java:94)
              at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:136)
              at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:233)
              at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory.loadPersistentSessions(InfinispanUserSessionProviderFactory.java:145)
              at org.keycloak.models.sessions.infinispan.InfinispanUserSessionProviderFactory$1.onEvent(InfinispanUserSessionProviderFactory.java:116)
              at org.keycloak.services.DefaultKeycloakSessionFactory.publish(DefaultKeycloakSessionFactory.java:68)
              at org.keycloak.services.resources.KeycloakApplication$2.run(KeycloakApplication.java:167)
              at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:227)
              at org.keycloak.services.resources.KeycloakApplication.<init>(KeycloakApplication.java:160)
              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)
              ... 28 more
      Caused by: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffffac199023:-56a74a79:5b363ba2:2e
              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1279)
              at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
              at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
              at org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:73)
              at org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
              at org.keycloak.transaction.JtaTransactionWrapper.commit(JtaTransactionWrapper.java:92)
              ... 41 more
       
      2018-06-30 00:22:29,680 WARN  [org.infinispan.CLUSTER] (remote-thread--p11-t3) [Context=sessions]ISPN000312: Lost data because of graceful leaver iskssowebprd04
      2018-06-30 00:22:29,715 WARN  [org.infinispan.CLUSTER] (remote-thread--p11-t9) [Context=loginFailures]ISPN000312: Lost data because of graceful leaver iskssowebprd04
      2018-06-30 00:22:29,730 WARN  [org.infinispan.CLUSTER] (remote-thread--p11-t14) [Context=offlineClientSessions]ISPN000312: Lost data because of graceful leaver iskssowebprd04
      2018-06-30 00:22:29,744 WARN  [org.infinispan.CLUSTER] (remote-thread--p11-t13) [Context=clientSessions]ISPN000312: Lost data because of graceful leaver iskssowebprd04
      2018-06-30 00:22:29,757 WARN  [org.infinispan.CLUSTER] (remote-thread--p11-t10) [Context=authenticationSessions]ISPN000312: Lost data because of graceful leaver iskssowebprd04
      2018-06-30 00:22:29,761 WARN  [org.infinispan.CLUSTER] (remote-thread--p11-t11) [Context=offlineSessions]ISPN000312: Lost data because of graceful leaver iskssowebprd04
      2018-06-30 00:22:29,809 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 67) WFLYUT0022: Unregistered web context: '/jolokia' from server 'default-server'
      2018-06-30 00:22:29,824 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-4) ISPN000080: Disconnecting JGroups channel ejb
      

      The issue is, that always when Keycloak transaction is started, we also automatically enlist and start JTA transaction (See DefaultKeycloakTransactionManager.begin() ).

      One possibility is to have the option to skip JTA entirely.

      Another possibility is to start JTA transaction "lazily" just if there is another KeycloakTransaction enlisted. Issue is that custom UserStorage by customer may use JPA directly (not use Keycloak TransactionManager API), which may result that JPA code by customer won't use JTA transaction.

      NOTE: DefaultKeycloakTransactionManager has setJtaPolicy/getJtaPolicy methods, but it is currently not supported by the configuration.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  mposolda Marek Posolda
                  Reporter:
                  mposolda Marek Posolda
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: