ISPN000482: Cannot create remote transaction X, already completed in ASYM_ENCRYPT scenario (following "received message without encrypt header from perf21; dropping it") ------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Key: WFLY-10464 URL: https://issues.jboss.org/browse/WFLY-10464 Project: WildFly Issue Type: Bug Components: Clustering Reporter: Michal Vinkler Assignee: Paul Ferraro Priority: Critical Affected scenario: eap-7x-failover-http-session-shutdown-dist-sync-auth-asymEncrypt (scenario with "AUTH" and "ASYM_ENCRYPT" protocols enabled). In server logs, we can see lots of WARN/ERROR messages logged. With 2000 clients, none of them is bound to a specific time/event (i.e. failover). When lowering number of clients to 10, Excpetion #1 starts occurring right after each failover, #2 + #3 occur after node rejoins the cluster. {code:title=#1 ISPN000482: Cannot create remote transaction X, already completed} [JBossINF] [0m[33m04:44:50,005 WARN [org.infinispan.remoting.inboundhandler.NonTotalOrderTxPerCacheInboundInvocationHandler] (remote-thread--p5-t3) ISPN000071: Caught exception when handling command LockControlCommand{cache=clusterbench-ee7.ear.clusterbench-ee7-web-default.war, keys=[SessionCreationMetaDataKey(r6mU8aS9wDfsmP7rAJ1892KSrjgnmzoTRytiyrNt)], flags=[FORCE_WRITE_LOCK], unlock=false, gtx=GlobalTx:perf21:49128}: org.infinispan.commons.CacheException: ISPN000482: Cannot create remote transaction GlobalTx:perf21:49128, already completed [JBossINF] at org.infinispan.transaction.impl.TransactionTable.lambda$getOrCreateRemoteTransaction$1(TransactionTable.java:375) [JBossINF] at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1853) [JBossINF] at org.infinispan.transaction.impl.TransactionTable.getOrCreateRemoteTransaction(TransactionTable.java:368) [JBossINF] at org.infinispan.transaction.impl.TransactionTable.getOrCreateRemoteTransaction(TransactionTable.java:348) [JBossINF] at org.infinispan.commands.control.LockControlCommand.createContext(LockControlCommand.java:139) [JBossINF] at org.infinispan.commands.control.LockControlCommand.invokeAsync(LockControlCommand.java:122) [JBossINF] at org.infinispan.remoting.inboundhandler.BasePerCacheInboundInvocationHandler.invokeCommand(BasePerCacheInboundInvocationHandler.java:94) [JBossINF] at org.infinispan.remoting.inboundhandler.BaseBlockingRunnable.invoke(BaseBlockingRunnable.java:99) [JBossINF] at org.infinispan.remoting.inboundhandler.BaseBlockingRunnable.runAsync(BaseBlockingRunnable.java:71) [JBossINF] at org.infinispan.remoting.inboundhandler.BaseBlockingRunnable.run(BaseBlockingRunnable.java:40) [JBossINF] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [JBossINF] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [JBossINF] at org.wildfly.clustering.service.concurrent.ClassLoaderThreadFactory.lambda$newThread$0(ClassLoaderThreadFactory.java:47) [JBossINF] at java.lang.Thread.run(Thread.java:748) [JBossINF] {code} {code:title=#2 ISPN000476: Timed out waiting for responses for request 47698 from X} [JBossINF] [0m[31m04:46:24,448 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p12-t1) ISPN000136: Error executing command GetKeyValueCommand, writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 47698 from perf21 [JBossINF] at org.infinispan.remoting.transport.impl.MultiTargetRequest.onTimeout(MultiTargetRequest.java:167) [JBossINF] at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) [JBossINF] at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) [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} {code:title=#3 CIRCULAR REFERENCE -> UT005023: Exception handling request to /clusterbench/session: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 47460 from X} [JBossINF] [0m[31m04:46:24,053 ERROR [io.undertow.request] (default task-98) UT005023: Exception handling request to /clusterbench/session: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 47460 from perf21 [JBossINF] at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:259) [JBossINF] at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:485) [JBossINF] at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:528) [JBossINF] at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:348) [JBossINF] at org.infinispan.cache.impl.EncoderCache.get(EncoderCache.java:658) [JBossINF] at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:348) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.getValue(InfinispanSessionMetaDataFactory.java:78) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:68) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:39) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:59) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:37) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.findSession(InfinispanSessionManager.java:200) [JBossINF] at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:176) [JBossINF] at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:858) [JBossINF] at io.undertow.servlet.spec.HttpServletRequestImpl.getSession(HttpServletRequestImpl.java:412) [JBossINF] at org.jboss.weld.module.web.servlet.SessionHolder.requestInitialized(SessionHolder.java:47) [JBossINF] at org.jboss.weld.module.web.servlet.HttpContextLifecycle.requestInitialized(HttpContextLifecycle.java:241) [JBossINF] at org.jboss.weld.module.web.servlet.WeldInitialListener.requestInitialized(WeldInitialListener.java:152) [JBossINF] at io.undertow.servlet.core.ApplicationListeners.requestInitialized(ApplicationListeners.java:246) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:291) [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:1514) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) [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.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1985) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378) [JBossINF] at java.lang.Thread.run(Thread.java:748) [JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 47460 from perf21 [JBossINF] at org.infinispan.remoting.transport.impl.MultiTargetRequest.onTimeout(MultiTargetRequest.java:167) [JBossINF] at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87) [JBossINF] at org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22) [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 [JBossINF] Suppressed: java.util.concurrent.ExecutionException: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 47460 from perf21 [JBossINF] at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) [JBossINF] at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915) [JBossINF] at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:82) [JBossINF] at org.infinispan.interceptors.impl.SimpleAsyncInvocationStage.get(SimpleAsyncInvocationStage.java:37) [JBossINF] at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:250) [JBossINF] at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:485) [JBossINF] at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:528) [JBossINF] at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:348) [JBossINF] at org.infinispan.cache.impl.EncoderCache.get(EncoderCache.java:658) [JBossINF] at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:348) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.getValue(InfinispanSessionMetaDataFactory.java:78) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:68) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:39) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:59) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:37) [JBossINF] at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.findSession(InfinispanSessionManager.java:200) [JBossINF] at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:176) [JBossINF] at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:858) [JBossINF] at io.undertow.servlet.spec.HttpServletRequestImpl.getSession(HttpServletRequestImpl.java:412) [JBossINF] at org.jboss.weld.module.web.servlet.SessionHolder.requestInitialized(SessionHolder.java:47) [JBossINF] at org.jboss.weld.module.web.servlet.HttpContextLifecycle.requestInitialized(HttpContextLifecycle.java:241) [JBossINF] at org.jboss.weld.module.web.servlet.WeldInitialListener.requestInitialized(WeldInitialListener.java:152) [JBossINF] at io.undertow.servlet.core.ApplicationListeners.requestInitialized(ApplicationListeners.java:246) [JBossINF] at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:291) [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:1514) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) [JBossINF] at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) [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.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1985) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487) [JBossINF] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378) [JBossINF] ... 1 more [JBossINF] [CIRCULAR REFERENCE:org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 47460 from perf21] {code} {code:title=#4 received message without encrypt header} [JBossINF] [0m[31m04:45:10,048 ERROR [org.jgroups.protocols.ASYM_ENCRYPT] (thread-9,ejb,perf18) perf18: received message without encrypt header from perf21; dropping it {code} Client gets valid responses till approx. 30 seconds after first failover, then Read timeouts start occuring. As far as I can tell, no valid response is received from this point. Link to server log - 2000 clients: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa... Link to client log - 2000 clients: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa... Link to server log - 10 clients: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa... Link to client log - 10 clients: http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-fa...