[jboss-jira] [JBoss JIRA] (WFLY-4697) EJBCLient access to SFSBs does not play well with clean shutdown

[ https://issues.jboss.org/browse/WFLY-4697?page=com.atlassian.jira.plugin.... ] Richard Achmatowicz edited comment on WFLY-4697 at 6/23/15 2:48 PM: -------------------------------------------------------------------- I have been experimenting with this fix which uses preSuspend() and resume() to send out moduleUnavailable and moduleAvailable messages to all connected EJBClient connections. It works well in communicating to clients that they need to start redirecting invocations to another node. Consequently, invocations are no longer getting directed to a node shutting down and the exceptions above are greatly reduced in number, in most cases down to zero. This works quite well in the case of RemoteFailoverTestCase (which was failing for similar reasons) where the invocations are not part of a managed transaction context. The only other change required to fix RemoteFailoverTestCase was to adjust the default value of the cache stop timeout (see cache transaction configuration). The cache stop timeout is used by Infinispan to allow a server which is shutting down to delay shutdown by stop-timeout ms in order to wait for any remote transactions it is involved in to complete (the default is 30 seconds). This delays the generation of the new cache topology. If a transaction on another node in the cluster (for example, the node we have just redirected the invocation to) is trying to commit, it will wait for the cache topology to arrive (the default wait time is 17.5 seconds). YThis was resulting in the following exceptions: {noformat} 14:05:14,181 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (EJB default - 5) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 7 at org.infinispan.statetransfer.StateTransferLockImpl.waitForTransactionData(StateTransferLockImpl.java:92) at org.infinispan.interceptors.base.BaseStateTransferInterceptor.waitForTransactionData(BaseStateTransferInterceptor.java:96) at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:227) at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:95) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:123) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:123) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:123) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:71) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:123) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:123) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336) at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157) at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:112) at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:367) at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:413) at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:303) at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:104) at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73) at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48) at org.jboss.as.ejb3.cache.distributable.DistributableCache.release(DistributableCache.java:139) at org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor.releaseInstance(StatefulSessionSynchronizationInterceptor.java:173) at org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization.afterCompletion(StatefulSessionSynchronizationInterceptor.java:257) at org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList.afterCompletion(JCAOrderedLastSynchronizationList.java:147) at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:545) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:101) at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1200) at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:91) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:279) at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:327) at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:79) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:53) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356) at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:635) at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356) at org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:195) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:331) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:69) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:202) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) at org.jboss.threads.JBossThread.run(JBossThread.java:320) {noformat} Reducing the stop-timeout from 30 seconds to 10 seconds prevented these exceptions from occurring. was (Author: rachmato): I have been experimenting with this fix which uses preSuspend() and resume() to send out moduleUnavailable and moduleAvailable messages to all connected EJBClient connections. It works well in communicating to clients that they need to start redirecting invocations to another node. Consequently, invocations are no longer getting directed to a node shutting down and the exceptions above are greatly reduced in number. This works quite well in the case of RemoteFailoverTestCase (which was failing for similar reasons) where the invocations are not part of a managed transaction context. The only other change required to fix RemoteFailoverTestCase was to adjust the default value of the cache stop timeout (see cache transaction configuration). The cache stop timeout is used by Infinispan to allow a server which is shutting down to delay shutdown by stop-timeout ms in order to wait for any remote transactions it is involved in to complete (the default is 30 seconds). This delays the generation of the new cache topology. If a transaction on another node in the cluster (for example, the node we have just redirected the invocation to) is trying to commit, it will wait for the cache topology to arrive (the default wait time is 17.5 seconds). YThis was resulting in the following exceptions: {noformat} 14:05:14,181 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (EJB default - 5) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Timed out waiting for topology 7 at org.infinispan.statetransfer.StateTransferLockImpl.waitForTransactionData(StateTransferLockImpl.java:92) at org.infinispan.interceptors.base.BaseStateTransferInterceptor.waitForTransactionData(BaseStateTransferInterceptor.java:96) at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:227) at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:95) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:123) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:123) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:123) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:71) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:123) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:123) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336) at org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:157) at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:112) at org.infinispan.transaction.tm.DummyTransaction.finishResource(DummyTransaction.java:367) at org.infinispan.transaction.tm.DummyTransaction.commitResources(DummyTransaction.java:413) at org.infinispan.transaction.tm.DummyTransaction.runCommit(DummyTransaction.java:303) at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:104) at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:73) at org.wildfly.clustering.ee.infinispan.ActiveTransactionBatch.close(ActiveTransactionBatch.java:48) at org.jboss.as.ejb3.cache.distributable.DistributableCache.release(DistributableCache.java:139) at org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor.releaseInstance(StatefulSessionSynchronizationInterceptor.java:173) at org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization.afterCompletion(StatefulSessionSynchronizationInterceptor.java:257) at org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList.afterCompletion(JCAOrderedLastSynchronizationList.java:147) at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:545) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:101) at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1200) at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89) at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:91) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:279) at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:327) at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:79) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:53) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356) at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:635) at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356) at org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:195) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:331) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:69) at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:202) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) at org.jboss.threads.JBossThread.run(JBossThread.java:320) {noformat} Reducing the stop-timeout from 30 seconds to 10 seconds prevented these exceptions from occurring. -- This message was sent by Atlassian JIRA (v6.3.15#6346)