[jboss-jira] [JBoss JIRA] (WFLY-6224) IllegalStateException "not in a valid state to be invoking cache operations on" in two cluster test

[Richard Achmatowicz (JIRA)]

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

Richard Achmatowicz commented on WFLY-6224:
-------------------------------------------

(text copied from WFLY-10607)
I'm looking at this issue at the moment. The issue centers around the operation of the StatefulComponentInstanceInterceptor and the StatefulSessionSynchronizationInterceptor which work together to manage the following: when a method invocation is processed at the server, lookup bean instances from the cache and attach them to the invocation, release those bean instances back to the cache when the invocation has finished, and manage registration of transaction synchronizations if the method is in the scope of a container-managed transaction. Actually, a lot more goes on, but its not worth going into in detail. For example, over and above the managed transaction, we have an Infinispan transaction associated with operations get()/put() on the cache which involve the InfinispanBatcher.

The "not in valid state" issue arises when the forwarding node tries to make an invocation on a remote bean and the bean is not found (i.e. NoSuchEJBException is returned as a result of the invocation). What happens here is this: the synchronization interceptor unconditionally calls release() in its finally clause to decrement the usage count of the bean instance which was looked up by the instance interceptor. Under the right conditions, this will case a commit of the Infinispan transaction. Later on, the instance interceptor handles the NoSuchEJBException on the method return by attempting to call discard() on the same bean instance within the same Infinispan transaction ; this fails because the Infinispan transaction has already been committed by the synchronization interceptor. 

The fix here is to modify the code in the synchronization interceptor to check if the method invocation return is an exception and if so, do not call release() in that case - we don't want to commit work that is associated with (bad) exceptions. When this is done, the instance interceptor can now successfully call discard() and the problem is resolved. 

> IllegalStateException "not in a valid state to be invoking cache operations on" in two cluster test
> ---------------------------------------------------------------------------------------------------
>
>                 Key: WFLY-6224
>                 URL: https://issues.jboss.org/browse/WFLY-6224
>             Project: WildFly
>          Issue Type: Bug
>          Components: Clustering, EJB
>    Affects Versions: 10.0.0.Final, 11.0.0.CR1, 13.0.0.Final
>            Reporter: Ladislav Thon
>            Assignee: Paul Ferraro
>
> During a 2clusters test eap-7x-failover-ejb-2clusters-ejbremote-shutdown-repl-async (where 2clusters test = standalone EJB client -> 2-node "forwarder" cluster -> 2-node "target" cluster -> back to "forwarder" -> back to standalone client), I'm seeing {{IllegalStateException: Transaction is not in a valid state to be invoking cache operations on}}:
> {code}
> 05:12:09,813 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-40) ISPN000136: Error executing command GetKeyValueCommand, writing keys []: java.lang.IllegalStateException: Transaction DummyTransaction{xid=DummyXid{id=352}, status=3} is not in a valid state to be invoking cache operations on.
> 	at org.infinispan.interceptors.TxInterceptor.enlist(TxInterceptor.java:394)
> 	at org.infinispan.interceptors.TxInterceptor.enlistIfNeeded(TxInterceptor.java:350)
> 	at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:344)
> 	at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:330)
> 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
> 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
> 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> 	at org.infinispan.statetransfer.StateTransferInterceptor.visitReadCommand(StateTransferInterceptor.java:176)
> 	at org.infinispan.statetransfer.StateTransferInterceptor.visitGetKeyValueCommand(StateTransferInterceptor.java:153)
> 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
> 	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
> 	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
> 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
> 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
> 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
> 	at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:411)
> 	at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:443)
> 	at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:286)
> 	at org.wildfly.clustering.ejb.infinispan.bean.InfinispanBeanFactory.findValue(InfinispanBeanFactory.java:85)
> 	at org.wildfly.clustering.ejb.infinispan.bean.InfinispanBeanFactory.findValue(InfinispanBeanFactory.java:49)
> 	at org.wildfly.clustering.ejb.infinispan.InfinispanBeanManager.findBean(InfinispanBeanManager.java:238)
> 	at org.jboss.as.ejb3.cache.distributable.DistributableCache.release(DistributableCache.java:137)
> 	at org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor.releaseInstance(StatefulSessionSynchronizationInterceptor.java:168)
> 	at org.jboss.as.ejb3.component.stateful.StatefulSessionSynchronizationInterceptor$StatefulSessionSynchronization.afterCompletion(StatefulSessionSynchronizationInterceptor.java:250)
> 	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.afterCompletion(TwoPhaseCoordinator.java:476)
> 	at com.arjuna.ats.internal.jta.transaction.arjunacore.subordinate.SubordinateAtomicAction.doOnePhaseCommit(SubordinateAtomicAction.java:247)
> 	at com.arjuna.ats.internal.jta.transaction.arjunacore.subordinate.TransactionImple.doOnePhaseCommit(TransactionImple.java:283)
> 	at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionCommitTask.manageTransaction(XidTransactionCommitTask.java:85)
> 	at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionManagementTask.run(XidTransactionManagementTask.java:68)
> 	at org.jboss.as.ejb3.remote.protocol.versionone.TransactionRequestHandler.processMessage(TransactionRequestHandler.java:139)
> 	at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.processMessage(VersionOneProtocolChannelReceiver.java:213)
> 	at org.jboss.as.ejb3.remote.protocol.versiontwo.VersionTwoProtocolChannelReceiver.processMessage(VersionTwoProtocolChannelReceiver.java:76)
> 	at org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver.handleMessage(VersionOneProtocolChannelReceiver.java:159)
> 	at org.jboss.remoting3.remote.RemoteConnectionChannel$5.run(RemoteConnectionChannel.java:456)
> 	at org.jboss.remoting3.EndpointImpl$TrackingExecutor$1.run(EndpointImpl.java:717)
> 	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)
> {code}
> The difference from WFLY-4678 is the circumstances.
> In the following text, I'm refering to the nodes by their real names: {{perf17}} is the standalone EJB client, the "forwarder" cluster is {{perf20}} and {{perf21}}, and the "target" cluster is {{perf18}} and {{perf19}}.
> The stack trace above is the first occurence of the exception, it appears on perf19 (https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-failover-ejb-2clusters-ejbremote-shutdown-repl-async/21/console-perf19/). At that time, perf18 is just shutting down gracefully, but the perf19 log clearly shows that both Infinispan and JGroups have already figured out that perf18 went away. Still, the absence of graceful shutdown for transactions might be an explanation... except that there's no reason why the cache on perf19 would be in an invalid state if it's perf18 who is going down. So maybe perf19 had to reach out to perf18 for some reason and the exception actually comes from perf18... but the cache is REPL, so perf19 should have all data locally already and it shouldn't really have to reach out to perf18.
> So, not really sure why it happens.



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