Re: [keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed.

Hi Joy, Yes, we have seen similar errors, although we are yet to determine whether these errors are the cause or just a symptom ________________________________________ From: Joy Kent [joy(a)autonomic.ai] Sent: Thursday, August 9, 2018 7:01 PM To: Nalyvayko, Peter Cc: keycloak-user(a)lists.jboss.org Subject: Re: [keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed. Hi Peter, While debugging more on this issue, we noticed that there are other exceptions like this in the logs: [keycloak-test-6df85dc969-nr6pt] 20:13:20,661 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state RUN [keycloak-test-6df85dc969-nr6pt] 20:13:20,662 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 1) ARJUNA012095: Abort of action id 0:ffff646009a0:375a4efd:5b6b81d4:123b0 invoked while multiple threads active within it. [keycloak-test-6df85dc969-nr6pt] 20:13:20,663 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 1) ARJUNA012381: Action id 0:ffff646009a0:375a4efd:5b6b81d4:123b0 completed with multiple threads - thread default task-34 was in progress with java.net.SocketInputStream.socketRead0(Native Method) [keycloak-test-6df85dc969-nr6pt] java.net.SocketInputStream.socketRead(SocketInputStream.java:116) [keycloak-test-6df85dc969-nr6pt] java.net.SocketInputStream.read(SocketInputStream.java:171) [keycloak-test-6df85dc969-nr6pt] java.net.SocketInputStream.read(SocketInputStream.java:141) [keycloak-test-6df85dc969-nr6pt] org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140) [keycloak-test-6df85dc969-nr6pt] org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109) [keycloak-test-6df85dc969-nr6pt] org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:67) [keycloak-test-6df85dc969-nr6pt] org.postgresql.core.PGStream.receiveChar(PGStream.java:288) [keycloak-test-6df85dc969-nr6pt] org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1963) [keycloak-test-6df85dc969-nr6pt] org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300) [keycloak-test-6df85dc969-nr6pt] org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428) [keycloak-test-6df85dc969-nr6pt] org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354) [keycloak-test-6df85dc969-nr6pt] org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:169) [keycloak-test-6df85dc969-nr6pt] org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:117) [keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [keycloak-test-6df85dc969-nr6pt] sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [keycloak-test-6df85dc969-nr6pt] java.lang.reflect.Method.invoke(Method.java:498) [keycloak-test-6df85dc969-nr6pt] org.postgresql.ds.PGPooledConnection$StatementHandler.invoke(PGPooledConnection.java:424) [keycloak-test-6df85dc969-nr6pt] com.sun.proxy.$Proxy115.executeQuery(Unknown Source) [keycloak-test-6df85dc969-nr6pt] org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:504) [keycloak-test-6df85dc969-nr6pt] org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.getResultSet(Loader.java:2122) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1905) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1881) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.doQuery(Loader.java:925) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.doList(Loader.java:2622) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.doList(Loader.java:2605) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2434) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.Loader.list(Loader.java:2429) [keycloak-test-6df85dc969-nr6pt] org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:501) [keycloak-test-6df85dc969-nr6pt] org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:371) [keycloak-test-6df85dc969-nr6pt] org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216) [keycloak-test-6df85dc969-nr6pt] org.hibernate.internal.SessionImpl.list(SessionImpl.java:1339) [keycloak-test-6df85dc969-nr6pt] org.hibernate.internal.QueryImpl.list(QueryImpl.java:87) [keycloak-test-6df85dc969-nr6pt] org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:606) [keycloak-test-6df85dc969-nr6pt] org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:483) [keycloak-test-6df85dc969-nr6pt] com.autonomic.keycloak.federation.AuUserStorageProvider.getUsers(AuUserStorageProvider.java:196) [keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [keycloak-test-6df85dc969-nr6pt] sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [keycloak-test-6df85dc969-nr6pt] java.lang.reflect.Method.invoke(Method.java:498) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.jpa.interceptor.SFSBInvocationInterceptor.processInvocation(SFSBInvocationInterceptor.java:57) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor.processInvocation(StatefulSessionSynchronizationInterceptor.java:135) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor.processInvocation(StatefulComponentInstanceInterceptor.java:59) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:255) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:334) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:240) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438) [keycloak-test-6df85dc969-nr6pt] org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:609) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) [keycloak-test-6df85dc969-nr6pt] org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185) [keycloak-test-6df85dc969-nr6pt] org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81) [keycloak-test-6df85dc969-nr6pt] com.autonomic.keycloak.federation.AuUserStorageProvider$$$view1.getUsers(Unknown Source) [keycloak-test-6df85dc969-nr6pt] org.keycloak.storage.UserStorageManager.lambda$getUsers$0(UserStorageManager.java:517) [keycloak-test-6df85dc969-nr6pt] org.keycloak.storage.UserStorageManager$$Lambda$1180/1899642151.query(Unknown Source) [keycloak-test-6df85dc969-nr6pt] org.keycloak.storage.UserStorageManager.query(UserStorageManager.java:503) [keycloak-test-6df85dc969-nr6pt] org.keycloak.storage.UserStorageManager.getUsers(UserStorageManager.java:513) [keycloak-test-6df85dc969-nr6pt] org.keycloak.models.cache.infinispan.UserCacheSession.getUsers(UserCacheSession.java:632) [keycloak-test-6df85dc969-nr6pt] org.keycloak.services.resources.admin.UsersResource.getUsers(UsersResource.java:209) [keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [keycloak-test-6df85dc969-nr6pt] sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [keycloak-test-6df85dc969-nr6pt] sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [keycloak-test-6df85dc969-nr6pt] java.lang.reflect.Method.invoke(Method.java:498) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:138) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:107) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:133) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:101) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [keycloak-test-6df85dc969-nr6pt] org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [keycloak-test-6df85dc969-nr6pt] javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129) [keycloak-test-6df85dc969-nr6pt] org.keycloak.services.filters.KeycloakSessionServletFilter.doFilter(KeycloakSessionServletFilter.java:90) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78) [keycloak-test-6df85dc969-nr6pt] io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) [keycloak-test-6df85dc969-nr6pt] io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [keycloak-test-6df85dc969-nr6pt] io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) [keycloak-test-6df85dc969-nr6pt] io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77) [keycloak-test-6df85dc969-nr6pt] io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50) [keycloak-test-6df85dc969-nr6pt] io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) [keycloak-test-6df85dc969-nr6pt] io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61) [keycloak-test-6df85dc969-nr6pt] io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68) [keycloak-test-6df85dc969-nr6pt] io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction$$Lambda$1015/1489808400.call(Unknown Source) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown Source) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown Source) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown Source) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1508) [keycloak-test-6df85dc969-nr6pt] org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$1016/1612860281.call(Unknown Source) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) [keycloak-test-6df85dc969-nr6pt] io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) [keycloak-test-6df85dc969-nr6pt] io.undertow.server.Connectors.executeRootHandler(Connectors.java:326) [keycloak-test-6df85dc969-nr6pt] io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [keycloak-test-6df85dc969-nr6pt] java.lang.Thread.run(Thread.java:748) [keycloak-test-6df85dc969-nr6pt] [keycloak-test-6df85dc969-nr6pt] 20:13:20,664 WARN [com.arjuna.ats.arjuna] (Transaction Reaper Worker 1) ARJUNA012108: CheckedAction::check - atomic action 0:ffff646009a0:375a4efd:5b6b81d4:123b0 aborting with 1 threads active! [keycloak-test-6df85dc969-nr6pt] 20:13:21,162 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state CANCEL [keycloak-test-6df85dc969-nr6pt] 20:13:21,163 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged: sun.misc.Unsafe.park(Native Method) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224) [keycloak-test-6df85dc969-nr6pt] java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) [keycloak-test-6df85dc969-nr6pt] org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.lock(BaseWrapperManagedConnection.java:374) [keycloak-test-6df85dc969-nr6pt] org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:290) [keycloak-test-6df85dc969-nr6pt] org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.end(XAResourceWrapperImpl.java:118) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1089) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1060) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1287) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:313) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381) [keycloak-test-6df85dc969-nr6pt] com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78) [keycloak-test-6df85dc969-nr6pt] [keycloak-test-6df85dc969-nr6pt] 20:13:21,663 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff646009a0:375a4efd:5b6b81d4:123b0 in state CANCEL_INTERRUPTED [keycloak-test-6df85dc969-nr6pt] 20:13:21,663 WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker 1,5,main] not responding to interrupt when cancelling TX 0:ffff646009a0:375a4efd:5b6b81d4:123b0 -- worker marked as zombie and TX scheduled for mark-as-rollback Have you seen this before? What might be causing this exception? Thanks, Joy On Sat, Aug 4, 2018 at 6:08 AM, Joy Kent <joy@autonomic.ai<mailto:joy@autonomic.ai>> wrote: Thanks Peter. I would like to hear more if you have more findings. I will do more testing locally as well, and report back if I find anything. On Fri, Aug 3, 2018 at 7:13 PM, Nalyvayko, Peter <pnalyvayko@agi.com<mailto:pnalyvayko@agi.com>> wrote: Lately I've been looking into performance and JVM memory consumption in effort to identify a culprit of system slowdown due to memory starvation. Preliminary results seem to indicate that simple grants such as owner password and client credential grants, can be safely marked off the list of possible causes. More complex use cases, such as identity brokering are another story, as they involve external systems downstream that could cause the entire system to misbehave, but I do not have an empirical evidence yet ________________________________________ From: Joy Kent [joy@autonomic.ai<mailto:joy@autonomic.ai>] Sent: Friday, August 3, 2018 5:41 PM To: Nalyvayko, Peter Cc: keycloak-user@lists.jboss.org<mailto:keycloak-user@lists.jboss.org> Subject: Re: [keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed. Interesting. Looking over the history, I did see a huge memory jump around the time when the exception occurred. Is there a memory leak somewhere? On Fri, Aug 3, 2018 at 1:58 PM, Joy Kent <joy@autonomic.ai<mailto:joy@autonomic.ai><mailto:joy@autonomic.ai<mailto:joy@autonomic.ai>>> wrote: Hi Peter, Thanks for your suggestions. I haven't checked the memory usage around that time. I will check that and report back. Thanks, Joy On Fri, Aug 3, 2018 at 12:56 PM, Nalyvayko, Peter <pnalyvayko@agi.com<mailto:pnalyvayko@agi.com><mailto:pnalyvayko@agi.com<mailto:pnalyvayko@agi.com>>> wrote: tl;dr :) You may want to check if JVM is running out of memory, we've seen it happen before and the effects were similar. My 0.02 cents Regards, Peter ________________________________________ From: keycloak-user-bounces@lists.jboss.org<mailto:keycloak-user-bounces@lists.jboss.org><mailto:keycloak-user-bounces@lists.jboss.org<mailto:keycloak-user-bounces@lists.jboss.org>> [keycloak-user-bounces@lists.jboss.org<mailto:keycloak-user-bounces@lists.jboss.org><mailto:keycloak-user-bounces@lists.jboss.org<mailto:keycloak-user-bounces@lists.jboss.org>>] on behalf of Joy Kent [joy@autonomic.ai<mailto:joy@autonomic.ai><mailto:joy@autonomic.ai<mailto:joy@autonomic.ai>>] Sent: Friday, August 3, 2018 2:30 PM To: keycloak-user@lists.jboss.org<mailto:keycloak-user@lists.jboss.org><mailto:keycloak-user@lists.jboss.org<mailto:keycloak-user@lists.jboss.org>> Subject: [keycloak-user] ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed. We have a keycloak 3.4.3.Final cluster with two PostgreSQL databases, one for keycloak, and the other for user federation storage. Both keycloak and user federation PostgreSQL databases are running with AWS RDS instances. Recently, we noticed that keycloak continuously threw exceptions when the user federation PostgreSQL database did a MultiAZ region failover, and became not usable. The exception snippet will be attached below. I have searched around, but didn't find the answer. This is our keycloak Database configuration: <datasource jndi-name="java:jboss/datasources/KeycloakDS" pool-name="KeycloakDS" enabled="true" use-java-context="true" use-ccm="true"> <connection-url>jdbc:postgresql://${env.POSTGRES_PORT_5432_TCP_ADDR}:${env.POSTGRES_PORT_5432_TCP_PORT:5432}/${env.POSTGRES_DATABASE:keycloak}</connection-url> <driver>postgresql</driver> <pool> <flush-strategy>IdleConnections</flush-strategy> </pool> <security> <user-name>${env.POSTGRES_USER:keycloak}</user-name> <password>${env.POSTGRES_PASSWORD:password}</password> </security> <validation> <check-valid-connection-sql>SELECT 1</check-valid-connection-sql> <background-validation>true</background-validation> <background-validation-millis>60000</background-validation-millis> </validation> </datasource> The user federation Database configuration looks like this: <xa-datasource jndi-name="java:jboss/datasources/IamDS" pool-name="IamDS" enabled="true" use-java-context="true" use-ccm="false"> <xa-datasource-property name="ServerName"> ${env.IAM_DB_HOST} </xa-datasource-property> <xa-datasource-property name="PortNumber"> ${env.IAM_DB_TCP_PORT:5432} </xa-datasource-property> <xa-datasource-property name="DatabaseName"> ${env.IAM_DB_DATABASE:iam} </xa-datasource-property> <driver>postgresql</driver> <xa-pool> <min-pool-size>${env.IAM_XA_POOL_MIN_SIZE:5}</min-pool-size> <max-pool-size>${env.IAM_XA_POOL_MAX_SIZE:100}</max-pool-size> <prefill>false</prefill> </xa-pool> <security> <user-name>${env.IAM_POSTGRES_USER:user}</user-name> <password>${env.IAM_POSTGRES_PASSWORD:password}</password> </security> <validation> <check-valid-connection-sql>SELECT 1</check-valid-connection-sql> <background-validation>true</background-validation> <background-validation-millis>60000</background-validation-millis> </validation> </xa-datasource> The driver is: <drivers> <driver name="postgresql" module="org.postgresql.jdbc"> <xa-datasource-class>org.postgresql.xa.PGXADataSource</xa-datasource-class> </driver> </drivers> I found a page https://access.redhat.com/documentation/en-us/red_hat_jboss_enterprise_ap..., which seems to indicate that exception-sorter is important: To configure database connection validation, you specify the validation Is the exception-sorter the missing configuration? I have tried this change, which seems to "fix" the problem. But by looking at the code, I can't tell how this can solve the problem. Does anyone know where might be wrong? Thanks a lot for your help! ===================== The exception snippet is as follows: ESC[0mESC[0m04:44:55,502 INFO [org.keycloak.events] (default task-21) type=CLIENT_LOGIN, realmId=xxxxxxxxxxx, clientId=xxxxxxxxxx, userId=xxxxxxxxxxxx, ipAddress=100.96.4.0, token_id =xxxxxxxxxxxx, grant_type=client_credentials, refresh_token_type=Refresh, refresh_token_id=xxxxxxxxxx, client_auth_method=client-secret, username=xxxxxxxxxxx ESC[0mESC[33m04:44:55,503 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) SQL Error: 0, SQLState: 08003 ESC[0mESC[31m04:44:55,503 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-21) This connection has been closed. ESC[0mESC[33m04:44:55,503 WARN [com.arjuna.ats.arjuna] (default task-21) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffff646043f0:2ee9e692:5b425ae8:2c012df, org.wildfly.transaction.client.AbstractTran saction$AssociatingSynchronization@76b2b731 >: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: could not prepare statement at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1692) at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1602) at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1608) at org.hibernate.jpa.internal.EntityManagerImpl$CallbackExceptionMapperImpl.mapManagedFlushFailure(EntityManagerImpl.java:235) at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3163) at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2352) at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:491) at org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoordinatorImpl.java:316) at org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:47) at org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:37) at org.wildfly.transaction.client.AbstractTransaction.performConsumer(AbstractTransaction.java:209) at org.wildfly.transaction.client.AbstractTransaction.performConsumer(AbstractTransaction.java:220) at org.wildfly.transaction.client.AbstractTransaction$AssociatingSynchronization.beforeCompletion(AbstractTransaction.java:265) at com.arjuna.ats.internal.jta.re<http://com.arjuna.ats.internal.jta.re><http://com.arjuna.ats.internal.jta.re>sources.arjunacore.Sy<http://sources.arjunacore.Sy>nchronizationImple.beforeCompletion(SynchronizationImple.java:76) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:368) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91) at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) at com.arjuna.ats.internal.jta.tr<http://com.arjuna.ats.internal.jta.tr><http://com.arjuna.ats.internal.jta.tr>ansaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1289) at com.arjuna.ats.internal.jta.tr<http://com.arjuna.ats.internal.jta.tr><http://com.arjuna.ats.internal.jta.tr>ansaction.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) at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:136) at org.keycloak.services.filters.KeycloakTransactionCommitter.filter(KeycloakTransactionCommitter.java:43) at org.jboss.resteasy.core.ServerResponseWriter.executeFilters(ServerResponseWriter.java:165) at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) at com.arjuna.ats.internal.jta.tr<http://com.arjuna.ats.internal.jta.tr><http://com.arjuna.ats.internal.jta.tr>ansaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1289) at com.arjuna.ats.internal.jta.tr<http://com.arjuna.ats.internal.jta.tr><http://com.arjuna.ats.internal.jta.tr>ansaction.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) at org.keycloak.services.DefaultKeycloakTransactionManager.commit(DefaultKeycloakTransactionManager.java:136) at org.keycloak.services.filters.KeycloakTransactionCommitter.filter(KeycloakTransactionCommitter.java:43) at org.jboss.resteasy.core.ServerResponseWriter.executeFilters(ServerResponseWriter.java:165) ..... Caused by: org.hibernate.exception.JDBCConnectionException: could not prepare statement at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:115) at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:182) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareStatement(StatementPreparerImpl.java:78) at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.buildBatchStatement(AbstractBatchImpl.java:136) at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.getBatchStatement(AbstractBatchImpl.java:125) at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2980) at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3499) at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:89) at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:589) at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337) at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39) at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1295) at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:468) at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3159) ... 72 more Caused by: org.postgresql.util.PSQLException: This connection has been closed. at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766) at org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582) at org.jboss.jca.adapters.jdbc.Ba<http://org.jboss.jca.adapters.jdbc.Ba><http://org.jboss.jca.adapters.jdbc.Ba>seWrapperManagedConnection.doPrepareStatement(BaseWrapperManagedConnection.java:757) at org.jboss.jca.adapters.jdbc.Ba<http://org.jboss.jca.adapters.jdbc.Ba><http://org.jboss.jca.adapters.jdbc.Ba>seWrapperManagedConnection.prepareStatement(BaseWrapperManagedConnection.java:743) at org.jboss.jca.adapters.jdbc.WrappedConnection.prepareStatement(WrappedConnection.java:454) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$1.doPrepare(StatementPreparerImpl.java:87) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172) ... 85 more _______________________________________________ keycloak-user mailing list keycloak-user@lists.jboss.org<mailto:keycloak-user@lists.jboss.org><mailto:keycloak-user@lists.jboss.org<mailto:keycloak-user@lists.jboss.org>> https://lists.jboss.org/mailman/listinfo/keycloak-user