XAException/HeuristicRollbackException and others due to TimeoutException: Timed out waiting for topology --------------------------------------------------------------------------------------------------------- Key: WFLY-9920 URL: https://issues.jboss.org/browse/WFLY-9920 Project: WildFly Issue Type: Bug Components: Clustering Affects Versions: 12.0.0.Final, 13.0.0.Beta1 Reporter: Michal Vinkler Assignee: Paul Ferraro Priority: Critical Fix For: 13.0.0.Beta1 Seen in many failover tests: failover-http-session-jvmkill-repl-sync failover-http-session-shutdown-dist-sync failover-http-session-shutdown-repl-sync failover-http-granular-jvmkill-dist-sync failover-http-granular-shutdown-repl-sync failover-ejb-ejbservlet-jvmkill-dist-sync failover-ejb-ejbservlet-undeploy-dist-sync During our failover testing, we have seen many occurrences of "TimeoutException: Timed out waiting for topology X". Here are the variants we have identified: {code:title=ISPN000136: Error executing command PrepareCommand} [JBossINF] [0m[31m06:14:11,769 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p9-t1) ISPN000136: Error executing command PrepareCommand, writing keys [SessionAttributesKey(u8mzm-09YKM6zLEb7aaTZapiXz3-y4i8OOMegJRL), SessionCreationMetaDataKey(u8mzm-09YKM6zLEb7aaTZapiXz3-y4i8OOMegJRL), SessionAccessMetaDataKey(u8mzm-09YKM6zLEb7aaTZapiXz3-y4i8OOMegJRL)]: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 29 [JBossINF] at org.infinispan.interceptors.impl.BaseStateTransferInterceptor$CancellableRetry.run(BaseStateTransferInterceptor.java:337) [JBossINF] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [JBossINF] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [JBossINF] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [JBossINF] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [JBossINF] at java.lang.Thread.run(Thread.java:748) {code} link: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa... {code:title=ISPN000097: Error while processing a prepare in a single-phase transaction} [JBossINF] [0m[31m06:14:11,773 ERROR [org.infinispan.transaction.impl.TransactionCoordinator] (default task-65) ISPN000097: Error while processing a prepare in a single-phase transaction: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 29 [JBossINF] at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:259) [JBossINF] at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:137) [JBossINF] at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:166) [JBossINF] at org.infinispan.transaction.xa.XaTransactionTable.commit(XaTransactionTable.java:126) [JBossINF] at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:68) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:446) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.commitResources(TransactionImpl.java:493) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:335) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.commit(TransactionImpl.java:110) [JBossINF] at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:97) [JBossINF] at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:91) [JBossINF] at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:945) [JBossINF] at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:577) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:339) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) [JBossINF] at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) [JBossINF] at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) [JBossINF] at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) [JBossINF] at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360) [JBossINF] at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1979) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1481) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1360) [JBossINF] at java.lang.Thread.run(Thread.java:748) [JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 29 [JBossINF] at org.infinispan.interceptors.impl.BaseStateTransferInterceptor$CancellableRetry.run(BaseStateTransferInterceptor.java:337) [JBossINF] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [JBossINF] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [JBossINF] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [JBossINF] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [JBossINF] ... 1 more {code} link: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa... {code:title=ISPN000927: exception while committing: javax.transaction.xa.XAException} [JBossINF] [0m[33m06:14:11,780 WARN [org.infinispan.commons.tx.TransactionImpl] (default task-65) ISPN000927: exception while committing: javax.transaction.xa.XAException [JBossINF] at org.infinispan.transaction.impl.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:222) [JBossINF] at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:168) [JBossINF] at org.infinispan.transaction.xa.XaTransactionTable.commit(XaTransactionTable.java:126) [JBossINF] at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:68) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:446) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.commitResources(TransactionImpl.java:493) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:335) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.commit(TransactionImpl.java:110) [JBossINF] at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:97) [JBossINF] at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:91) [JBossINF] at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:945) [JBossINF] at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:577) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:339) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) [JBossINF] at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) [JBossINF] at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) [JBossINF] at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) [JBossINF] at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360) [JBossINF] at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1979) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1481) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1360) [JBossINF] at java.lang.Thread.run(Thread.java:748) [JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 29 [JBossINF] at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:259) [JBossINF] at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:137) [JBossINF] at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:166) [JBossINF] ... 30 more [JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 29 [JBossINF] at org.infinispan.interceptors.impl.BaseStateTransferInterceptor$CancellableRetry.run(BaseStateTransferInterceptor.java:337) [JBossINF] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [JBossINF] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [JBossINF] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [JBossINF] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [JBossINF] ... 1 more {code} link: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa... {code:title=UT005023: ... HeuristicRollbackException} [JBossINF] [0m[31m08:57:51,979 ERROR [io.undertow.request] (default task-56) UT005023: Exception handling request to /clusterbench-granular/granular: org.infinispan.commons.CacheException: javax.transaction.HeuristicRollbackException [JBossINF] at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:102) [JBossINF] at org.wildfly.clustering.server.registry.CacheRegistry.getEntry(CacheRegistry.java:174) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanRouteLocator.locate(InfinispanRouteLocator.java:57) [JBossINF] at org.wildfly.clustering.web.undertow.session.DistributableSessionIdentifierCodec.encode(DistributableSessionIdentifierCodec.java:48) [JBossINF] at org.wildfly.extension.undertow.session.CodecSessionConfig.findSessionId(CodecSessionConfig.java:60) [JBossINF] at io.undertow.servlet.spec.ServletContextImpl$ServletContextSessionConfig.findSessionId(ServletContextImpl.java:1215) [JBossINF] at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:158) [JBossINF] at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:858) [JBossINF] at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:933) [JBossINF] at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:69) [JBossINF] at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50) [JBossINF] at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) [JBossINF] at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [JBossINF] at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61) [JBossINF] at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [JBossINF] at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68) [JBossINF] at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) [JBossINF] at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) [JBossINF] at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) [JBossINF] at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1526) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) [JBossINF] at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360) [JBossINF] at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1979) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1481) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1360) [JBossINF] at java.lang.Thread.run(Thread.java:748) [JBossINF] Caused by: javax.transaction.HeuristicRollbackException [JBossINF] at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:478) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.commitResources(TransactionImpl.java:493) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:335) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.commit(TransactionImpl.java:110) [JBossINF] at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:97) [JBossINF] ... 36 more [JBossINF] Caused by: javax.transaction.xa.XAException [JBossINF] at org.infinispan.transaction.impl.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:222) [JBossINF] at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:168) [JBossINF] at org.infinispan.transaction.xa.XaTransactionTable.commit(XaTransactionTable.java:126) [JBossINF] at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:68) [JBossINF] at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:446) [JBossINF] ... 40 more [JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 21 [JBossINF] at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:259) [JBossINF] at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:137) [JBossINF] at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:166) [JBossINF] ... 43 more [JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 21 [JBossINF] at org.infinispan.interceptors.impl.BaseStateTransferInterceptor$CancellableRetry.run(BaseStateTransferInterceptor.java:337) [JBossINF] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [JBossINF] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [JBossINF] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [JBossINF] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [JBossINF] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [JBossINF] ... 1 more {code} link: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa... The client is affected, getting 500 as a response: {code} 2018/02/16 08:57:51:748 EST [WARN ][Runner - 1950] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data: <org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html>> org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html> at org.jboss.smartfrog.loaddriver.http.HttpRequestProcessorFactoryImpl$HttpRequestProcessor.processRequest(HttpRequestProcessorFactoryImpl.java:164) at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:52) at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:103) at java.lang.Thread.run(Thread.java:748) {code} link: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa...