Я проводил стресс-тест, чтобы определить, сможет ли Keycloak справиться с нагрузкой, которую мы предполагаем в какой-то момент. Используя более старую версию (v.4.8.3), мы заметили, что Keycloak зависал на несколько минут при первом доступе к экрану клиента после запуска. Это было с ~ 2500 клиентами.
После обновления этой старой версии до последней версии Keycloak он не запускался, поэтому я попытался сначала запустить без этих 2500 клиентов, а затем загрузить тестовых пользователей и клиентов через Остаточный интерфейс с использованием JMeter.
Keycloak был настроен следующим образом:
- автономная конфигурация
- Postgresql v.12 (localhost)
- развернут один дополнительный. jar, содержащий наш алгоритм шифрования паролей BCrypt (подтвержденный для работы) плюс некоторые библиотечные модули, для которых требуется
Итак, я добавил 10 тыс. пользователей и 10 тыс. клиентов. Это прошло без каких-либо проблем, и даже казалось, что проблема зависания была решена в версии 10.0.2, потому что клиенты сразу же отображались на странице, когда я щелкал по ней.
Затем я попытался добавить еще один каждого через интерфейс Keycloak. Добавление другого клиента не было проблемой, но добавление другого пользователя было . После нажатия кнопки «Сохранить» Keycloak зависает примерно на 5 минут, а затем создает следующую трассировку стека (усеченную, чтобы соответствовать максимальной длине сообщения):
2020-06-16 16:09:39,653 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000001:-6370960e:5ee8cef7:36a in state RUN
2020-06-16 16:09:39,658 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000001:-6370960e:5ee8cef7:36a invoked while multiple threads active within it.
2020-06-16 16:09:39,660 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff7f000001:-6370960e:5ee8cef7:36a completed with multiple threads - thread default task-8 was in progress with org.hibernate@5.3.15.Final//org.hibernate.tuple.entity.AbstractEntityTuplizer.getPropertyValue(AbstractEntityTuplizer.java:577)
org.hibernate@5.3.15.Final//org.hibernate.persister.entity.AbstractEntityPersister.getPropertyValue(AbstractEntityPersister.java:4997)
org.hibernate@5.3.15.Final//org.hibernate.engine.internal.Cascade.cascade(Cascade.java:180)
<snip>
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.ClientAdapter.getClientScopes(ClientAdapter.java:381)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.entities.CachedClient.<init>(CachedClient.java:117)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.cacheClient(RealmCacheSession.java:1091)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClientById(RealmCacheSession.java:1051)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:632)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:640)
org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.ClientStorageManager.getClients(ClientStorageManager.java:186)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClients(RealmCacheSession.java:546)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmAdapter.getClients(RealmAdapter.java:733)
org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.getDefaultRoles(DefaultRoles.java:38)
org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.addDefaultRoles(DefaultRoles.java:47)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:110)
org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:130)
org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.UserStorageManager.addUser(UserStorageManager.java:152)
org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.UserCacheSession.addUser(UserCacheSession.java:797)
org.keycloak.keycloak-services@10.0.2//org.keycloak.services.resources.admin.UsersResource.createUser(UsersResource.java:129)
...
...
org.wildfly.extension.undertow@19.1.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1541)
org.wildfly.extension.undertow@19.1.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$879/0x0000000800cc1440.call(Unknown Source)
...
...
io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
io.undertow.core@2.1.0.Final//io.undertow.server.Connectors.executeRootHandler(Connectors.java:370)
io.undertow.core@2.1.0.Final//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
org.jboss.threads@2.3.3.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
java.base@11.0.6/java.lang.Thread.run(Thread.java:834) ```
2020-06-16 16:09:39,674 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000001:-6370960e:5ee8cef7:36a aborting with 1 threads active!
2020-06-16 16:09:39,678 WARN [org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl] (Transaction Reaper Worker 0) HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]
2020-06-16 16:09:39,679 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000001:-6370960e:5ee8cef7:36a
2020-06-16 16:09:39,713 WARN [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (default task-8) IJ000609: Attempt to return connection twice: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1854447[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@70689a22 connection handles=0 lastReturned=1592316579713 lastValidated=1592315711533 lastCheckedOut=1592316279657 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@717d396a mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@19f9ce2e[pool=KeycloakDS] xaResource=LocalXAResourceImpl@4ee761ed[connectionListener=1854447 connectionManager=304cc4b8 warned=false currentXid=null productName=PostgreSQL productVersion=12.3 jndiName=java:jboss/datasources/KeycloakDS] txSync=null]: java.lang.Throwable: STACKTRACE
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.returnConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:725)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.returnConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:614)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.pool.AbstractPool.returnConnection(AbstractPool.java:847)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.returnManagedConnection(AbstractConnectionManager.java:725)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.managedConnectionDisconnected(AbstractConnectionManager.java:1113)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.disconnectManagedConnection(AbstractConnectionManager.java:1069)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:1046)
at org.jboss.ironjacamar.impl@1.4.20.Final//org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:792)
at org.jboss.ironjacamar.jdbcadapters@1.4.20.Final//org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:151)
at org.jboss.as.connector@19.1.0.Final//org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:64)
at org.hibernate@5.3.15.Final//org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at org.hibernate@5.3.15.Final//org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
at org.hibernate@5.3.15.Final//org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:106)
at org.hibernate@5.3.15.Final//org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:136)
...
...
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.ClientAdapter.getClientScopes(ClientAdapter.java:381)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.entities.CachedClient.<init>(CachedClient.java:117)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.cacheClient(RealmCacheSession.java:1091)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClientById(RealmCacheSession.java:1051)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:632)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:640)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.ClientStorageManager.getClients(ClientStorageManager.java:186)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClients(RealmCacheSession.java:546)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmAdapter.getClients(RealmAdapter.java:733)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.getDefaultRoles(DefaultRoles.java:38)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.addDefaultRoles(DefaultRoles.java:47)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:110)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:130)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.UserStorageManager.addUser(UserStorageManager.java:152)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.UserCacheSession.addUser(UserCacheSession.java:797)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.services.resources.admin.UsersResource.createUser(UsersResource.java:129)
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.resteasy-jaxrs@3.11.2.Final//org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:138)
at org.jboss.resteasy.resteasy-jaxrs@3.11.2.Final//org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:535)
at org.jboss.resteasy.resteasy-jaxrs@3.11.2.Final//org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:424)
...
...
at javax.servlet.api@2.0.0.Final//javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet@2.1.0.Final//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:91)
at io.undertow.servlet@2.1.0.Final//io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
...
...
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at java.base/java.lang.Thread.run(Thread.java:834)
2020-06-16 16:09:39,728 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-8) SQL Error: 0, SQLState: null
2020-06-16 16:09:39,728 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-8) javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1854447[state=DESTROYED managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@70689a22 connection handles=0 lastReturned=1592316579713 lastValidated=1592315711533 lastCheckedOut=1592316279657 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@717d396a mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@19f9ce2e[pool=KeycloakDS] xaResource=LocalXAResourceImpl@4ee761ed[connectionListener=1854447 connectionManager=304cc4b8 warned=false currentXid=null productName=PostgreSQL productVersion=12.3 jndiName=java:jboss/datasources/KeycloakDS] txSync=null]
2020-06-16 16:09:39,752 ERROR [org.keycloak.services.error.KeycloakErrorHandler] (default task-8) Uncaught server error: javax.persistence.PersistenceException: org.hibernate.HibernateException: Transaction was rolled back in a different thread!
at org.hibernate@5.3.15.Final//org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
at org.hibernate@5.3.15.Final//org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1515)
at org.hibernate@5.3.15.Final//org.hibernate.query.Query.getResultList(Query.java:132)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.ClientAdapter.getClientScopes(ClientAdapter.java:381)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.entities.CachedClient.<init>(CachedClient.java:117)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.cacheClient(RealmCacheSession.java:1091)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClientById(RealmCacheSession.java:1051)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:632)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaRealmProvider.getClients(JpaRealmProvider.java:640)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.ClientStorageManager.getClients(ClientStorageManager.java:186)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmCacheSession.getClients(RealmCacheSession.java:546)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.RealmAdapter.getClients(RealmAdapter.java:733)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.getDefaultRoles(DefaultRoles.java:38)
at org.keycloak.keycloak-server-spi@10.0.2//org.keycloak.models.utils.DefaultRoles.addDefaultRoles(DefaultRoles.java:47)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:110)
at org.keycloak.keycloak-model-jpa@10.0.2//org.keycloak.models.jpa.JpaUserProvider.addUser(JpaUserProvider.java:130)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.storage.UserStorageManager.addUser(UserStorageManager.java:152)
at org.keycloak.keycloak-model-infinispan@10.0.2//org.keycloak.models.cache.infinispan.UserCacheSession.addUser(UserCacheSession.java:797)
at org.keycloak.keycloak-services@10.0.2//org.keycloak.services.resources.admin.UsersResource.createUser(UsersResource.java:129)
...
...
at org.jboss.threads@2.3.3.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
at org.jboss.threads@2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.hibernate.HibernateException: Transaction was rolled back in a different thread!
at org.hibernate@5.3.15.Final//org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl.processAnyDelayedAfterCompletion(SynchronizationCallbackCoordinatorTrackingImpl.java:90)
at org.hibernate@5.3.15.Final//org.hibernate.internal.SessionImpl.delayedAfterCompletion(SessionImpl.java:658)
at org.hibernate@5.3.15.Final//org.hibernate.internal.SessionImpl.list(SessionImpl.java:1532)
at org.hibernate@5.3.15.Final//org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1538)
at org.hibernate@5.3.15.Final//org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1506)
... 91 more
2020-06-16 16:09:39,769 WARN [com.arjuna.ats.arjuna] (default task-8) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000001:-6370960e:5ee8cef7:36a
... после чего пользователь не создано. В поисках решения я натолкнулся на ряд предложений по увеличению значения тайм-аута (простоя) и некоторых настроек конфигурации источника данных, ни один из которых не повлиял на проблему, кроме увеличения времени его замораживания перед созданием этого стека. след.
Был еще один намек, который я нашел, он должен был добавить jta = false к источнику данных, например:
<datasource jta="false" jndi-name="java:jboss/datasources/KeycloakDS" ...
С этим добавлением пользовательский интерфейс Keycloak все еще завис, но я мог видеть, что много взаимодействия происходит с Postgresql: количество транзакций в секунду выросло примерно до 700, а затем уменьшилось:
Тем не менее, пользователь действительно был создан, хотя и без введенных мной имени и фамилии. «Имя пользователя» было скопировано с адреса электронной почты, который я ввел для этого пользователя (но, возможно, это обычное поведение).
Это было то место, где я был на прошлой неделе с версией 10.0.1, а сегодня я попытался перейти на 10.0.2, но, увы, без разницы.
Я также разместил это на форуме обсуждения keycloak неделю go, но не получил там ответа, поэтому я спрашиваю здесь. Конечно, это может быть проблема JBoss, я понятия не имею.
Любые предложения были бы замечательными!