Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-15906

(7.2.z) WARN HeuristicMixedException due to replication timeout

    XMLWordPrintable

Details

    • Bug
    • Resolution: Won't Do
    • Major
    • None
    • 7.2.0.GA.CR1
    • Clustering, Transactions
    • None

    Description

      Found during regression tests for JBEAP-15815.
      Does not cause errors on the client side so priority can remain "Major".
      Seems to be related to the use of an invalidation-cache backed by a relational database.
      Infinispan version is 9.3.3.Final.

      Was observed in Failover scenario perflab_eap-7x-failover-db-session-shutdown-repl-sync-postgresql-10.1 where cache is backed by relational database:

      <datasource jndi-name="java:jboss/datasources/testDS" pool-name="testDS" enabled="true" jta="true" use-java-context="true">
<connection-url>jdbc:postgresql://postgres-101.rhev-ci-vms.eng.rdu2.redhat.com:5432/dballo15</connection-url>
<driver>postgresql-connector.jar</driver>
<security>
<user-name>dballo15</user-name>
<password>dballo15</password>
</security>
<transaction-isolation>TRANSACTION_READ_COMMITTED</transaction-isolation>
<pool>
<min-pool-size>1</min-pool-size>
<max-pool-size>5</max-pool-size>
<prefill>true</prefill>
</pool>
<statement>
<prepared-statement-cache-size>32</prepared-statement-cache-size>
<share-prepared-statements>true</share-prepared-statements>
</statement>
</datasource>

...

<invalidation-cache name="offload">
<locking isolation="REPEATABLE_READ"/>
<transaction mode="BATCH"/>
<jdbc-store data-source="testDS" fetch-state="false" passivation="false" purge="false" shared="true" dialect="POSTGRES">
<table prefix="s">
<id-column name="id" type="VARCHAR(255)"/>
<data-column name="datum" type="BYTEA"/>
<timestamp-column name="version" type="BIGINT"/>
</table>
</jdbc-store>
</invalidation-cache>

      There are 4 nodes and after nodes are started we observe the timeouts;
      Here is the sequence of events:

      • node-2 start 10:48:15
      • node-3 start 10:48:24
      • node-4 start 10:48:31
      • node-1 start 10:48:38
      • node-1 error 10:49:41 : Timed out waiting for responses for request 243 from node-3
      • node-3 error 10:49:42 : Timed out waiting for responses for request 272 from node-1
      • node-1 error 10:50:21 : Timed out waiting for responses for request 1334 from node-4
      • node-1 stop 10:51:32

      As first node is failed after the first errors come out, it does not seem to be related to fail-over.

      Here is the snippet of log with javax.transaction.HeuristicMixedException:

      [JBossINF] �[0m�[33m10:49:41,334 WARN  [org.wildfly.clustering.web.undertow] (default task-48) javax.transaction.HeuristicMixedException: org.infinispan.commons.CacheException: javax.transaction.HeuristicMixedException
[JBossINF] 	at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:102)
[JBossINF] 	at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:87)
[JBossINF] 	at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:945)
[JBossINF] 	at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:579)
[JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:346)
[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:1502)
[JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
[JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
[JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
[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:1349)
[JBossINF] 	at java.lang.Thread.run(Thread.java:748)
[JBossINF] Caused by: javax.transaction.HeuristicMixedException
[JBossINF] 	at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:457)
[JBossINF] 	at org.infinispan.commons.tx.TransactionImpl.commitResources(TransactionImpl.java:466)
[JBossINF] 	at org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:335)
[JBossINF] 	at org.infinispan.commons.tx.TransactionImpl.commit(TransactionImpl.java:110)
[JBossINF] 	at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:97)
[JBossINF] 	... 24 more
[JBossINF] Caused by: javax.transaction.xa.XAException
[JBossINF] 	at org.infinispan.transaction.impl.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:211)
[JBossINF] 	at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157)
[JBossINF] 	at org.infinispan.transaction.xa.XaTransactionTable.commit(XaTransactionTable.java:127)
[JBossINF] 	at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:68)
[JBossINF] 	at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:419)
[JBossINF] 	... 28 more
[JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 243 from dev214
[JBossINF] 	at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:259)
[JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:137)
[JBossINF] 	at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:155)
[JBossINF] 	... 31 more
[JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 243 from dev214
[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: org.infinispan.util.logging.TraceException
[JBossINF] 		at org.infinispan.interceptors.impl.SimpleAsyncInvocationStage.get(SimpleAsyncInvocationStage.java:41)
[JBossINF] 		at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:250)
[JBossINF] 		at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:137)
[JBossINF] 		at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:155)
[JBossINF] 		at org.infinispan.transaction.xa.XaTransactionTable.commit(XaTransactionTable.java:127)
[JBossINF] 		at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:68)
[JBossINF] 		at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:419)
[JBossINF] 		at org.infinispan.commons.tx.TransactionImpl.commitResources(TransactionImpl.java:466)
[JBossINF] 		at org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:335)
[JBossINF] 		at org.infinispan.commons.tx.TransactionImpl.commit(TransactionImpl.java:110)
[JBossINF] 		at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:97)
[JBossINF] 		at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:87)
[JBossINF] 		at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:945)
[JBossINF] 		at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:579)
[JBossINF] 		at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:346)
[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:1502)
[JBossINF] 		at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
[JBossINF] 		at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
[JBossINF] 		at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
[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:1349)
[JBossINF] 		... 1 more

      We observed the issue also in scenario perflab_eap-7x-failover-ejb-2clusters-ejbremote-shutdown-repl-async.

      Attachments

        Issue Links

          is caused by

          Bug - A problem that impairs or prevents the functions of the product. ISPN-9701 TransactionTable does not shutdown gracefully

          • Critical - To be worked on immediately following BLOCKER issues.
          • Closed

          Activity

            People

              pferraro@redhat.com Paul Ferraro
              tborgato@redhat.com Tommaso Borgato
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: