Loading...

Type: Bug
Resolution: Done
Priority: Blocker
Fix Version/s: 15.0.0.Beta1, 15.0.0.Final
Affects Version/s: 14.0.0.Final
Component/s: Clustering
Labels:
None

Git Pull Request:
https://github.com/wildfly/wildfly/pull/11720

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.

#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]

#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)

#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]

#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

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/

blocks

CLOUD-2417 [EAP CD] Clustering with openshift.KUBE_PING doesn't work correctly

Closed

causes

CLOUD-2789 Problems with cluster scale-down when SYM_ENCRYPT configured

New

clones

JBEAP-14784 ISPN000482: Cannot create remote transaction X, already completed in ASYM_ENCRYPT scenario (following "received message without encrypt header from perf21; dropping it")

Closed

Details

Description

Attachments

Issue Links

Easy Agile Planning Poker

Activity

People

Dates