Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-10464

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

    XMLWordPrintable

Details

    Description

      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/

      Attachments

        Issue Links

          blocks

          Bug - A problem that impairs or prevents the functions of the product. CLOUD-2417 [EAP CD] Clustering with openshift.KUBE_PING doesn't work correctly

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed
          causes

          Bug - A problem that impairs or prevents the functions of the product. CLOUD-2789 Problems with cluster scale-down when SYM_ENCRYPT configured

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • New
          clones

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-14784 ISPN000482: Cannot create remote transaction X, already completed in ASYM_ENCRYPT scenario (following "received message without encrypt header from perf21; dropping it")

          • Blocker - To be worked above all other priorities. This term is chosen when the severity of the issue is very high, has no workaround, or the effort for the change is comparatively low. Issues that may be very publicly visible and could generate significant media attention may also drive a higher priority.
          • Verified

          Activity

            People

              rhn-engineering-rhusar Radoslav Husar
              mvinkler1@redhat.com Michal Vinkler
              Tommaso Borgato Tommaso Borgato
              Votes:
              1 Vote for this issue
              Watchers:
              11 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: