]
Radoslav Husar updated WFLY-10464:
----------------------------------
Summary: ISPN000482: Cannot create remote transaction X, already completed in
ASYM_ENCRYPT scenario (was: ISPN000482: Cannot create remote transaction X, already
completed in Asym Encrypt scenario)
ISPN000482: Cannot create remote transaction X, already completed in
ASYM_ENCRYPT scenario
------------------------------------------------------------------------------------------
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...