[infinispan-issues] [JBoss JIRA] (ISPN-7099) Error executing command RollbackCommand due to timed out waiting for topology

Tue Jul 31 03:54:00 EDT 2018

    [ https://issues.jboss.org/browse/ISPN-7099?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13612449#comment-13612449 ] 

tommaso borgato edited comment on ISPN-7099 at 7/31/18 3:53 AM:
----------------------------------------------------------------

The issue is still valid for 9.3.1.

Summary: on node dev213 of a 4 nodes cluster, the server is shutting down to trigger some fail-over in the cluster; at this point, right after the log confirm the deployments used for testing (ear + jdbc driver) completed the shut down, the following is logged:

{noformat}
[JBossINF] [0m[0m08:48:36,352 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-1) WFLYJCA0019: Stopped Driver service with driver-name = h2
[JBossINF] [0m[0m08:48:36,366 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) WFLYUT0008: Undertow HTTPS listener https suspending
[JBossINF] [0m[0m08:48:36,366 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-8) WFLYUT0008: Undertow AJP listener ajp suspending
[JBossINF] [0m[0m08:48:36,367 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to 10.16.176.58:8443
[JBossINF] [0m[0m08:48:36,367 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-8) WFLYUT0007: Undertow AJP listener ajp stopped, was bound to 10.16.176.58:8009
[JBossINF] [0m[0m08:48:36,367 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-4) WFLYSRV0028: Stopped deployment mysql-connector.jar (runtime-name: mysql-connector.jar) in 11455ms
[JBossINF] [0m[0m08:48:36,367 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-1) WFLYSRV0208: Stopped subdeployment (runtime-name: clusterbench-ee7-ejb.jar) in 11465ms
[JBossINF] [0m[0m08:48:36,368 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-7) WFLYSRV0208: Stopped subdeployment (runtime-name: b.war) in 11466ms
[JBossINF] [0m[0m08:48:36,368 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-6) WFLYSRV0208: Stopped subdeployment (runtime-name: c.war) in 11466ms
[JBossINF] [0m[0m08:48:36,370 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-2) WFLYSRV0208: Stopped subdeployment (runtime-name: d.war) in 11468ms
[JBossINF] [0m[0m08:48:36,370 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0208: Stopped subdeployment (runtime-name: a.war) in 11469ms
[JBossINF] [0m[0m08:48:36,371 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment clusterbench-ee7.ear (runtime-name: clusterbench-ee7.ear) in 11466ms
[JBossINF] [0m[31m08:48:44,931 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p11-t1) ISPN000136: Error executing command RollbackCommand, writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 13 from dev215,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] 	at java.lang.Thread.run(Thread.java:748)
{noformat}

complete log here: [https://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/view/EAP7/view/EAP7-Clustering_JJB/view/clustering-db-session-tests/job/eap-7x-db-failover-db-session-shutdown-repl-sync-mysql-5-7_JJB/19/console-dev213/|https://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/view/EAP7/view/EAP7-Clustering_JJB/view/clustering-db-session-tests/job/eap-7x-db-failover-db-session-shutdown-repl-sync-mysql-5-7_JJB/19/console-dev213/].

was (Author: tommaso-borgato):
The issue is still valid for 9.3.1.

Summary: on node dev213 of a 4 nodes cluster, the server is shutting down to trigger some fail-over in the cluster; at this point, right after the log confirm the application used for testing,completed the shut down, the following is logged:

{noformat}
[JBossINF] [0m[0m08:48:36,352 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-1) WFLYJCA0019: Stopped Driver service with driver-name = h2
[JBossINF] [0m[0m08:48:36,366 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) WFLYUT0008: Undertow HTTPS listener https suspending
[JBossINF] [0m[0m08:48:36,366 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-8) WFLYUT0008: Undertow AJP listener ajp suspending
[JBossINF] [0m[0m08:48:36,367 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to 10.16.176.58:8443
[JBossINF] [0m[0m08:48:36,367 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-8) WFLYUT0007: Undertow AJP listener ajp stopped, was bound to 10.16.176.58:8009
[JBossINF] [0m[0m08:48:36,367 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-4) WFLYSRV0028: Stopped deployment mysql-connector.jar (runtime-name: mysql-connector.jar) in 11455ms
[JBossINF] [0m[0m08:48:36,367 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-1) WFLYSRV0208: Stopped subdeployment (runtime-name: clusterbench-ee7-ejb.jar) in 11465ms
[JBossINF] [0m[0m08:48:36,368 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-7) WFLYSRV0208: Stopped subdeployment (runtime-name: b.war) in 11466ms
[JBossINF] [0m[0m08:48:36,368 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-6) WFLYSRV0208: Stopped subdeployment (runtime-name: c.war) in 11466ms
[JBossINF] [0m[0m08:48:36,370 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-2) WFLYSRV0208: Stopped subdeployment (runtime-name: d.war) in 11468ms
[JBossINF] [0m[0m08:48:36,370 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0208: Stopped subdeployment (runtime-name: a.war) in 11469ms
[JBossINF] [0m[0m08:48:36,371 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment clusterbench-ee7.ear (runtime-name: clusterbench-ee7.ear) in 11466ms
[JBossINF] [0m[31m08:48:44,931 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p11-t1) ISPN000136: Error executing command RollbackCommand, writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 13 from dev215,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] 	at java.lang.Thread.run(Thread.java:748)
{noformat}

complete log here: [https://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/view/EAP7/view/EAP7-Clustering_JJB/view/clustering-db-session-tests/job/eap-7x-db-failover-db-session-shutdown-repl-sync-mysql-5-7_JJB/19/console-dev213/|https://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/view/EAP7/view/EAP7-Clustering_JJB/view/clustering-db-session-tests/job/eap-7x-db-failover-db-session-shutdown-repl-sync-mysql-5-7_JJB/19/console-dev213/].

> Error executing command RollbackCommand due to timed out waiting for topology
> -----------------------------------------------------------------------------
>
>                 Key: ISPN-7099
>                 URL: https://issues.jboss.org/browse/ISPN-7099
>             Project: Infinispan
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 8.2.4.Final, 9.3.1.Final
>            Reporter: Radoslav Husar
>              Labels: infinispan_clean_shutdown
>
> Occured on server during eap-7x-failover-http-session-shutdown-dist-sync scenario.
> Server log stacktrace:
> {code}
> 00:14:37,012 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-6) ISPN000136: Error executing command RollbackCommand, writing keys [SessionCreationMetaDataKey(896a6XPyj99XiHDouVS5eojwHiGrjYJ2N-rOrzh8), SessionAttributesKey(896a6XPyj99XiHDouVS5eojwHiGrjYJ2N-rOrzh8), SessionAccessMetaDataKey(896a6XPyj99XiHDouVS5eojwHiGrjYJ2N-rOrzh8)]: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 28
> [JBossINF] 	at org.infinispan.statetransfer.StateTransferLockImpl.reportErrorAfterWait(StateTransferLockImpl.java:159)
> [JBossINF] 	at org.infinispan.statetransfer.StateTransferLockImpl.waitForTransactionData(StateTransferLockImpl.java:98)
> [JBossINF] 	at org.infinispan.interceptors.base.BaseStateTransferInterceptor.waitForTransactionData(BaseStateTransferInterceptor.java:97)
> [JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:249)
> [JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitRollbackCommand(StateTransferInterceptor.java:97)
> [JBossINF] 	at org.infinispan.commands.tx.RollbackCommand.acceptVisitor(RollbackCommand.java:40)
> [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> [JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:114)
> [JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:83)
> [JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitRollbackCommand(AbstractVisitor.java:117)
> [JBossINF] 	at org.infinispan.commands.tx.RollbackCommand.acceptVisitor(RollbackCommand.java:40)
> [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> [JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitRollbackCommand(AbstractVisitor.java:117)
> [JBossINF] 	at org.infinispan.commands.tx.RollbackCommand.acceptVisitor(RollbackCommand.java:40)
> [JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:335)
> [JBossINF] 	at org.infinispan.transaction.impl.TransactionCoordinator.rollbackInternal(TransactionCoordinator.java:231)
> [JBossINF] 	at org.infinispan.transaction.impl.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:202)
> [JBossINF] 	at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:159)
> [JBossINF] 	at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:114)
> [JBossINF] 	at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:401)
> [JBossINF] 	at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:448)
> [JBossINF] 	at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:321)
> [JBossINF] 	at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:108)
> [JBossINF] 	at org.wildfly.clustering.ee.infinispan.InfinispanBatch.close(InfinispanBatch.java:71)
> [JBossINF] 	at org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:81)
> [JBossINF] 	at io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:814)
> [JBossINF] 	at io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:572)
> [JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:339)
> [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:1668)
> [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1668)
> [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1668)
> [JBossINF] 	at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1668)
> [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:207)
> [JBossINF] 	at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:810)
> [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
> {code}
> Followed by:
> {code}
> 00:14:37,012 WARN  [org.infinispan.transaction.impl.TransactionCoordinator] (transport-thread--p15-t24) ISPN000141: Could not rollback prepared 1PC transaction. This transaction will be rolled back by the recovery process, if enabled. Transaction: LocalXaTransaction{xid=DummyXid{id=13473}} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=26, stateTransferFlag=null} org.infinispan.transaction.xa.LocalXaTransaction at 43a2: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 28
> [JBossINF] 	at org.infinispan.statetransfer.StateTransferLockImpl.reportErrorAfterWait(StateTransferLockImpl.java:159)
> ...
> {code}
> Server log:
> http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-http-session-shutdown-dist-sync/30/console-dev214/

--
This message was sent by Atlassian JIRA
(v7.5.0#75005)