8 Replies Latest reply on Sep 15, 2010 4:35 AM by thom28

    SuspectException handling.

    thom28

      Hello,

      i'm working on a two nodes synchronous replication cluster.

      I make a failure happen (with System.exit()) on a node when performing an operation on memory with the other node in order to check failover capacities.

      All my operations are in transactions with dummyTransactionManager.

      Then when node crash, the other node throws the SuspectException. ==> This implies that when a node crash, all in progress write operations from other nodes will fail?

       

      See StackTrace:

      interceptors.InvocationContextInterceptor     - Execution error:
      org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member: ProcessUnit_AgentManager_2-31542
              at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:418)
              at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:100)
              at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:124)
              at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:229)
              at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:216)
              at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:199)
              at org.infinispan.interceptors.base.BaseRpcInterceptor.visitLockControlCommand(BaseRpcInterceptor.java:59)
              at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
              at org.infinispan.interceptors.LockingInterceptor.visitLockControlCommand(LockingInterceptor.java:149)
              at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
              at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
              at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:147)
              at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:82)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
              at org.infinispan.interceptors.ImplicitEagerLockingInterceptor.lockEagerly(ImplicitEagerLockingInterceptor.java:96)
              at org.infinispan.interceptors.ImplicitEagerLockingInterceptor.visitRemoveCommand(ImplicitEagerLockingInterceptor.java:51)
              at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
              at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:183)
              at org.infinispan.interceptors.TxInterceptor.visitRemoveCommand(TxInterceptor.java:137)
              at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
              at org.infinispan.interceptors.CacheMgmtInterceptor.visitRemoveCommand(CacheMgmtInterceptor.java:122)
              at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:48)
              at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:34)
              at org.infinispan.commands.AbstractVisitor.visitRemoveCommand(AbstractVisitor.java:61)
              at org.infinispan.commands.write.RemoveCommand.acceptVisitor(RemoveCommand.java:70)
              at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:269)
              at org.infinispan.CacheDelegate.remove(CacheDelegate.java:212)
                ...

       

      My question is can we handle this exception to retry the failed operation?

      Is the cluster still coherent if we do so?

      Is this problem handled in next versions of infiniSpan?

       

      Have a nice day,

      Thomas.

        • 1. Re: SuspectException handling.
          manik

          Well it depends on how quickly the suspect is removed from the cluster and a new view is installed.  This is controlled by your failure detection settings in JGroups: FDVersusFD_SOCK

          • 2. Re: SuspectException handling.
            cbo_

            Manik, I can not open the link that was put into the prior post you did.

            • 3. Re: SuspectException handling.
              manik
              • 4. Re: SuspectException handling.
                thom28

                Ok, thanks for yours replies.

                I saw the document for failure detection but i don't see a way to speed up the view replacing.

                I give you a more detailled log view to analyse the problem

                (See StackTrace at the bottom)

                (You can see the config file too at bottom.)

                 

                On this stackTrace, we can notice that the Exception happen 125 ms (14:25:51,847 - 14:25:51,722) after trying to put() and remove() variable in cache. ==> It makes me suppose that it is not a timeout problem..

                The problem appear to be in the short period between:

                1. FD_SOCK     - VIEW_CHANGE  received:  [ProcessUnit_AgentManager_1-2202]
                2. AbstractLogImpl     - Received  new cluster view:  [ProcessUnit_AgentManager_1-2202|6]  [ProcessUnit_AgentManager_1-2202]

                I suspect there is short period of time where the cluster state is not coherent and it should be managed to prevent request to fail by waiting that the new view will be replaced.

                Can you confirm or invalidate this hypothesis?

                 

                Have a nice day,

                Thomas.

                 

                14:25:51,488 [FD_SOCK pinger,ProcessUnit_AgentManager_1-2202] FD_SOCK     - peer ProcessUnit_AgentManager_2-31542 closed socket (java.net.SocketException)
                14:25:51,488 [FD_SOCK pinger,ProcessUnit_AgentManager_1-2202] FD_SOCK     - suspecting ProcessUnit_AgentManager_2-31542 (own address is ProcessUnit_AgentManager_1-2202)
                14:25:51,488 [FD_SOCK pinger,ProcessUnit_AgentManager_1-2202] FD_SOCK     - ping_dest is null, pingable_mbrs=[ProcessUnit_AgentManager_1-2202]

                 

                14:25:51,519 [OOB-2,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: suspect is ProcessUnit_AgentManager_2-31542, completed false, flushOkSet {}, flushMembers []
                14:25:51,519 [OOB-2,ProcessUnit_AgentManager_1-2202] RequestCorrelator     - suspect=ProcessUnit_AgentManager_2-31542
                14:25:51,644 [ViewHandler,ProcessUnit_AgentManager_1-2202] ParticipantGmsImpl     - suspected members=[ProcessUnit_AgentManager_2-31542], suspected_mbrs=[ProcessUnit_AgentManager_2-31542]
                14:25:51,644 [ViewHandler,ProcessUnit_AgentManager_1-2202] ParticipantGmsImpl     - members are [ProcessUnit_AgentManager_2-31542, ProcessUnit_AgentManager_1-2202], coord=ProcessUnit_AgentManager_1-2202: I'm the new coord !

                 

                14:25:51,644 [ViewHandler,ProcessUnit_AgentManager_1-2202] GMS     - ProcessUnit_AgentManager_1-2202:
                14:25:51,722 [Session Task] UnitedMemoryManager     - Deleting answers and message state for id=test7 (Here i launch a put() and remove() operation)
                2010 14:25:51,769 [ViewHandler,ProcessUnit_AgentManager_1-2202] CoordGmsImpl     - new=[], suspected=[ProcessUnit_AgentManager_2-31542], leaving=[], new view: [ProcessUnit_AgentManager_1-2202|6] [ProcessUnit_AgentManager_1-2202]
                juin 2010 14:25:51,769 [ViewHandler,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: flush coordinator  is starting FLUSH with participants [ProcessUnit_AgentManager_1-2202]
                14:25:51,800 [Incoming-1,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: FLUSH_COMPLETED from ProcessUnit_AgentManager_1-2202, completed true, flushMembers [ProcessUnit_AgentManager_1-2202], flushCompleted [ProcessUnit_AgentManager_1-2202]
                14:25:51,800 [Incoming-1,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: all FLUSH_COMPLETED received
                14:25:51,800 [Incoming-2,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: received START_FLUSH, responded with FLUSH_COMPLETED to ProcessUnit_AgentManager_1-2202
                14:25:51,847 [Incoming-2,ProcessUnit_AgentManager_1-2202] GMS     - ProcessUnit_AgentManager_1-2202: view is [ProcessUnit_AgentManager_1-2202|6] [ProcessUnit_AgentManager_1-2202]
                14:25:51,847 [Incoming-2,ProcessUnit_AgentManager_1-2202] NAKACK     - removed ProcessUnit_AgentManager_2-31542 from xmit_table (not member anymore)
                14:25:51,847 [Incoming-2,ProcessUnit_AgentManager_1-2202] FD_SOCK     - VIEW_CHANGE received: [ProcessUnit_AgentManager_1-2202]
                14:25:51,847 [Session Task] InvocationContextInterceptor     - Execution error:
                org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member: ProcessUnit_AgentManager_2-31542

                 

                (...  This SuspectException is not Handled.  see original billet stackTrace to have all the details.)

                 

                14:25:51,863 [Session Task] TreatmentMsgManager     - treatment time=360

                14:25:51,863 [Incoming-2,ProcessUnit_AgentManager_1-2202] AbstractLogImpl     - Received new cluster view: [ProcessUnit_AgentManager_1-2202|6] [ProcessUnit_AgentManager_1-2202]
                14:25:51,863 [Incoming-2,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: installing view [ProcessUnit_AgentManager_1-2202|6] [ProcessUnit_AgentManager_1-2202]
                14:25:51,863 [Incoming-2,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
                14:25:51,863 [ViewHandler,ProcessUnit_AgentManager_1-2202] GMS     - ProcessUnit_AgentManager_1-2202: sending RESUME event
                14:25:51,863 [ViewHandler,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: received RESUME, sending STOP_FLUSH to all
                14:25:51,863 [Incoming-2,ProcessUnit_AgentManager_1-2202] FLUSH     - ProcessUnit_AgentManager_1-2202: received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up

                 

                 

                 

                For information, here is my infiniSpan configuration:

                <global>
                      <globalJmxStatistics enabled="true" jmxDomain="infinispan"/>
                      <transport clusterName="AgentManager-cluster" distributedSyncTimeout="50000" nodeName="ProcessUnit_AgentManager_1"/>
                      <serialization marshallerClass="org.infinispan.marshall.VersionAwareMarshaller" version="1.0"/>

                     <shutdown hookBehavior="DEFAULT"/>
                   </global>

                 

                <default>
                      <jmxStatistics enabled="true"/>
                      <lazyDeserialization enabled="false"/>
                      <invocationBatching enabled="false"/>
                      <clustering mode="replication">
                         <stateRetrieval timeout="20000" fetchInMemoryState="true"/>
                         <sync replTimeout="5000"/>
                      </clustering>

                      <locking
                            isolationLevel="READ_COMMITTED"
                            lockAcquisitionTimeout="7000"
                            writeSkewCheck="false"
                            concurrencyLevel="500"
                            useLockStriping="false"
                            />

                 

                      <transaction
                            transactionManagerLookupClass="org.infinispan.transaction.lookup.GenericTransactionManagerLookup"
                            syncRollbackPhase="true"
                            syncCommitPhase="true"
                            useEagerLocking="true"
                      />
                </default>

                • 5. Re: SuspectException handling.
                  belaban

                  If you invoke an RPC on {A,B,C,D} and C fails, then the RPC will be received by A, B and D, but because C failed there's a suspect exception.

                   

                  If you want atomicity, ie. A, B and D should *not* apply the change, then you need to make the call in a transaction.

                  • 6. Re: SuspectException handling.
                    galder.zamarreno

                    Call in a transaction and configure a JBoss Transactions based transaction manager lookup instead of the dummy transaction manager. The former is a fully fledged transaction manager whereas the second is purely for dummy testing.

                    • 7. Re: SuspectException handling.
                      galder.zamarreno

                      I've updated Infinispan transactions with information about  JBossStandaloneJTAManagerLookup

                      • 8. Re: SuspectException handling.
                        thom28

                        Hello everybody, thanks for your replies that help me in managing suspectException.

                         

                        I resolved the problem by using the jbossjta transactionManager, then  catching the suspect exception, waiting for view to change, then rollbacking the transaction and retrying the operation.

                         

                        But i come back with a new problem on SuspectException Handling.

                        I recently upgrade ISPN to version 4.1.

                        I did notice that SuspectException was catched at ISPN level which was throwing a RollBackException which trace is :

                        javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted][com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Could not commit transaction.

                         

                        Well, i adapt my code to simply retry operation. But it seems that locks are not released.

                        Let's see the trace:

                        Manager 51908 ERROR 14 sept. 2010 17:09:56,874 [Session Task] interceptors.InvocationContextInterceptor     - Execution error:org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [20 seconds] on key [test2.msgState] for requestor [GlobalTransaction:<node01-26609>:5]! Lock held by [GlobalTransaction:<node01-26609>:4]

                         

                        All futur attempts to acquire lock will fail in the same way until process is restarted.

                         

                        Is anyone experimented the same problem?

                        Have a nice day,

                        Thomas.

                         

                        PS: I put the full stack trace commented to help understanding:

                         

                        org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member: node02-29005     (note : here is the suspectException).
                            at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:418)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:100)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:124)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:229)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:216)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:199)
                            at org.infinispan.interceptors.ReplicationInterceptor.visitPrepareCommand(ReplicationInterceptor.java:63)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.LockingInterceptor.visitPrepareCommand(LockingInterceptor.java:111)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:48)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:91)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
                            at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:57)
                            at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:38)
                            at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
                            at org.infinispan.transaction.xa.TransactionXaAdapter.prepare(TransactionXaAdapter.java:86)
                            at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:96)
                            at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:812)
                            at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2674)
                            at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1788)
                            at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:99)
                            at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:176)
                            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1363)
                            at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:132)
                        (...)
                            at java.lang.Thread.run(Thread.java:619)
                        Manager 33326 ERROR 15 sept. 2010 09:57:37,683 [Session Task] TransactionXaAdapter     - Error while processing PrepareCommand
                        org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member: node02-29005
                            at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:418)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:100)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:124)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:229)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:216)
                            at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:199)
                            at org.infinispan.interceptors.ReplicationInterceptor.visitPrepareCommand(ReplicationInterceptor.java:63)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.LockingInterceptor.visitPrepareCommand(LockingInterceptor.java:111)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:48)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:91)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
                            at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:57)
                            at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:38)
                            at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:105)
                            at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:120)
                            at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
                            at org.infinispan.transaction.xa.TransactionXaAdapter.prepare(TransactionXaAdapter.java:86)
                            at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:96)
                            at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:812)
                            at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2674)
                            at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1788)
                            at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:99)
                            at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:176)
                            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1363)
                            at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:132)
                        (...)
                            at java.lang.Thread.run(Thread.java:619)
                        Manager 33357 WARN  15 sept. 2010 09:57:37,714 [Session Task] XAResourceRecord     - [com.arjuna.ats.internal.jta.resources.arjunacore.opcerror] [com.arjuna.ats.internal.jta.resources.arjunacore.opcerror] onePhaseCommit on < formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a18f30c:de2:4c907c6e:e, node_name=1, branch_uid=0:ffff0a18f30c:de2:4c907c6e:f, eis_name=unknown eis name > (TransactionXaAdapter{modifications=[PutKeyValueCommand{key=test2.msgState, value=Assigned, putIfAbsent=true, lifespanMillis=-1, maxIdleTimeMillis=-1}, PutKeyValueCommand{key=test2.processUnit, value=node01, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}], lookedUpEntries=org.infinispan.util.BidirectionalLinkedHashMap@39474b, globalTx=GlobalTransaction:<node01-15208>:4, transaction=TransactionImple < ac, BasicAction: 0:ffff0a18f30c:de2:4c907c6e:e status: ActionStatus.COMMITTING >, txTimeout=60}) failed with exception XAException.XAER_RMERR
                        javax.transaction.xa.XAException  (Note: here is the Exception launched by ISPN)
                            at org.infinispan.transaction.xa.TransactionXaAdapter.prepare(TransactionXaAdapter.java:90)
                            at org.infinispan.transaction.xa.TransactionXaAdapter.commit(TransactionXaAdapter.java:96)
                            at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:812)
                            at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2674)
                            at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1788)
                            at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:99)
                            at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:176)
                            at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1363)
                            at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:132)
                        (...)
                            at java.lang.Thread.run(Thread.java:619)
                        Manager 33404 WARN  15 sept. 2010 09:57:37,761 [Session Task] Manager     - In Manager RollbackException

                        javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.trans
                        action.arjunacore.commitwhenaborted] Could not commit transaction.
                        (Note: here is the rollback exception sent by jbossJTA))
                                at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1375)
                                at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:132)
                                (...)
                                at java.lang.Thread.run(Thread.java:619)

                        Manager 33404 WARN  15 sept. 2010 09:57:37,761 [Session Task] Manager     - aTM=Transaction: unknown status=6
                        Manager 33404 ERROR 15 sept. 2010 09:57:37,761 [Session Task] Manager     - ============================================ msg=test2 has rollbacked.
                        Manager 33404 WARN  15 sept. 2010 09:57:37,761 [Session Task] Manager     - Waiting view to change for 4000 ms.
                        Manager 33404 INFO  15 sept. 2010 09:57:37,761 [Incoming-1,node01-15208] AbstractLogImpl     - Received new cluster view: [node01-15208|2] [node01-15208]
                        Manager 33404 INFO  15 sept. 2010 09:57:37,761 [Incoming-1,node01-15208] ViewChangeInterceptor     - *****************************************************************
                        Manager 33420 INFO  15 sept. 2010 09:57:37,777 [Incoming-1,node01-15208] ViewChangeInterceptor     - *******///// VIEW CHANGED EVENT !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
                        Manager 33420 INFO  15 sept. 2010 09:57:37,777 [Incoming-1,node01-15208] ViewChangeInterceptor     - localAdress=node01-15208
                        Manager 33420 INFO  15 sept. 2010 09:57:37,777 [Incoming-1,node01-15208] ViewChangeInterceptor     - NewMember=[node01-15208]
                        Manager 33420 INFO  15 sept. 2010 09:57:37,777 [Incoming-1,node01-15208] ViewChangeInterceptor     - OldMember=[node01-15208, node02-29005]
                        Manager 33420 INFO  15 sept. 2010 09:57:37,777 [Incoming-1,node01-15208] ViewChangeInterceptor     - ViewId=2
                        Manager 33420 INFO  15 sept. 2010 09:57:37,777 [Incoming-1,node01-15208] ViewChangeInterceptor     - ViewId=VIEW_CHANGED
                        Manager 33451 INFO  15 sept. 2010 09:57:37,808 [Incoming-1,node01-15208] ViewChangeInterceptor     - *****************************************************************
                        Manager 37406 WARN  15 sept. 2010 09:57:41,763 [Session Task] Manager     - View Changing wait achieved.
                        Manager 57414 ERROR 15 sept. 2010 09:58:01,771 [Session Task] InvocationContextInterceptor     - Execution error: (Note: Here is the new try to make the operation.)
                        org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [20 seconds] on key [test2.msgState] for requestor [GlobalTransaction:<node01-15208>:5]! Lock held by [GlobalTransaction:<node01-15208>:4]
                            at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:218)
                            at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:153)
                            at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
                            at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:197)
                            at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
                            at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
                            at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:183)
                            at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:132)
                            at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:113)
                            at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
                            at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
                            at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:57)
                            at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:38)
                            at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
                            at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
                            at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
                            at org.infinispan.CacheDelegate.putIfAbsent(CacheDelegate.java:438)
                            at org.infinispan.CacheSupport.putIfAbsent(CacheSupport.java:40)
                            (...)
                            at java.lang.Thread.run(Thread.java:619)

                        (Note: All further try to acquire this lock will fall in timeout in the same way until the process is restarted.)