[jboss-jira] [JBoss JIRA] (WFLY-10464) ISPN000482: Cannot create remote transaction X, already completed in ASYM_ENCRYPT scenario (following "received message without encrypt header from perf21; dropping it")
Radoslav Husar (JIRA)
issues at jboss.org
Fri Sep 14 13:19:03 EDT 2018
[ https://issues.jboss.org/browse/WFLY-10464?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Radoslav Husar updated WFLY-10464:
----------------------------------
Affects Version/s: 14.0.0.Final
> 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
> Affects Versions: 14.0.0.Final
> Reporter: Michal Vinkler
> Assignee: Radoslav Husar
> 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-failover-http-session-shutdown-dist-sync-auth-asymEncrypt/28/console-perf18/
> Link to client log - 2000 clients:
> http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-failover-http-session-shutdown-dist-sync-auth-asymEncrypt/28/console-perf17/
> Link to server log - 10 clients:
> http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-failover-http-session-shutdown-dist-sync-auth-asymEncrypt/29/console-perf20/
> Link to client log - 10 clients:
> http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-failover-http-session-shutdown-dist-sync-auth-asymEncrypt/29/console-perf17/
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the jboss-jira
mailing list