[JBoss JIRA] (ISPN-5166) During ST, previously removed entry was revived
by Radim Vansa (JIRA)
[ https://issues.jboss.org/browse/ISPN-5166?page=com.atlassian.jira.plugin.... ]
Radim Vansa updated ISPN-5166:
------------------------------
Attachment: cluster.txt
Adding requested logs as cluster.txt. Beware that this also contains logs for cache __protobuf_metadata (I haven't found a way to disable this cache and I didn't want to filter out the logs).
> During ST, previously removed entry was revived
> -----------------------------------------------
>
> Key: ISPN-5166
> URL: https://issues.jboss.org/browse/ISPN-5166
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 7.1.0.Beta1
> Reporter: Radim Vansa
> Priority: Critical
> Attachments: cluster.txt, topo.txt
>
>
> In transactional mode, entry was removed (transaction succeeded and the entry was removed from data container), but later, when StateResponseCommand arrives, the entry is revived with the old value.
> Here is how the remove is executed on edg-perf01:
> {code}
> 07:50:08,276 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Replication task sending PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=89} to single recipient edg-perf03-24234 with response mode GET_ALL
> 07:50:08,368 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) Response(s) to PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=89} is {edg-perf03-24234=null}
> 07:50:08,369 TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] (DefaultStressor-5) Forwarding command PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=90} to new targets [edg-perf03-24234]
> 07:50:08,369 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) edg-perf01-21525 invoking PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=90} to recipient list [edg-perf03-24234] with options RpcOptions{timeout=60000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS, skipReplicationQueue=false}
> 07:50:08,527 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) Response(s) to PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=90} is {edg-perf03-24234=null}
> 07:50:08,529 TRACE [org.infinispan.transaction.LocalTransaction] (DefaultStressor-5) getCommitNodes recipients=[edg-perf01-21525, edg-perf03-24234], currentTopologyId=90, members=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], txTopologyId=88
> 07:50:08,531 TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (DefaultStressor-5) dests=[edg-perf01-21525, edg-perf03-24234], command=CommitCommand {gtx=GlobalTransaction:<edg-perf01-21525>:957
> 26:local, cacheName='testCache', topologyId=90}, mode=SYNCHRONOUS_IGNORE_LEAVERS, timeout=60000
> 07:50:08,531 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Replication task sending CommitCommand {gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheNam
> e='testCache', topologyId=90} to addresses [edg-perf03-24234] with response mode GET_ALL
> 07:50:08,555 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Responses: [sender=edg-perf03-24234, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
> 07:50:08,555 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (DefaultStressor-5) About to commit entry ReadCommittedEntry(49e1fe5d){key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], oldValue=null, isCreated=false, isChanged=true, isRemoved=true, isValid=false, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
> 07:50:08,561 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (DefaultStressor-5) Updating entry (key=key_000000000000050E removed=true valid=false changed=true created=false loaded=false value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ] metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 07:50:08,561 TRACE [org.infinispan.statetransfer.CommitManager] (DefaultStressor-5) Committed key=key_000000000000050E. Old discard policy=null. New discard policy=DiscardPolicy{discardStateTransfer=true, discardXSiteStateTransfer=false}
> {code}
> The commit command on edg-perf03 is executed only after the StateResponseCommand is sent (and received on edg-perf01):
> {code}
> 07:50:10,736 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-254) Invoked with command PutKeyValueCommand{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP, PUT_FOR_STATE_TRANSFER, SKIP_SHARED_CACHE_STORE, SKIP_OWNERSHIP_CHECK, IGNORE_RETURN_VALUES, SKIP_XSITE_BACKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@3e54512]
> 07:50:10,747 TRACE [org.infinispan.transaction.xa.TransactionXaAdapter] (remote-thread-254) start called on tx GlobalTransaction:<edg-perf01-21525>:95972:local
> 07:50:10,758 TRACE [org.infinispan.transaction.LocalTransaction] (remote-thread-254) Adding modification PutKeyValueCommand{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP, PUT_FOR_STATE_TRANSFER, SKIP_SHARED_CACHE_STORE, SKIP_OWNERSHIP_CHECK, IGNORE_RETURN_VALUES, SKIP_XSITE_BACKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}. Mod list is null
> 07:50:10,763 TRACE [org.infinispan.transaction.xa.TransactionXaAdapter] (remote-thread-254) end called on tx GlobalTransaction:<edg-perf01-21525>:95972:local(testCache)
> 07:50:10,763 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-254) Invoked with command PrepareCommand {modifications=null, onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95972:local, cacheName='testCache', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@3df73149]
> 07:50:10,779 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (remote-thread-254) About to commit entry ReadCommittedEntry(206acaec){key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
> 07:50:10,779 TRACE [org.infinispan.statetransfer.CommitManager] (remote-thread-254) Trying to commit. Key=key_000000000000050E. Operation Flag=PUT_FOR_STATE_TRANSFER, L1 invalidation=false
> 07:50:10,782 TRACE [org.infinispan.container.DefaultDataContainer] (remote-thread-254) Store ImmortalCacheEntry{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ]} in container
> {code}
> Later, I can see that the value was really writen to the container (further read retrieves it):
> {code}
> 07:53:26,778 TRACE [org.infinispan.container.EntryFactoryImpl] (DefaultStressor-5) Retrieved from container ImmortalCacheEntry{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ]} (forceFetch=false, isLocal=true)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 2 months
[JBoss JIRA] (ISPN-5166) During ST, previously removed entry was revived
by Radim Vansa (JIRA)
[ https://issues.jboss.org/browse/ISPN-5166?page=com.atlassian.jira.plugin.... ]
Radim Vansa edited comment on ISPN-5166 at 1/21/15 3:30 AM:
------------------------------------------------------------
Seems like edg-perf02 started a rebalance before shutting down, but edg-perf04 somehow missed those topologies and the first topology it tries to install:
{noformat}
07:47:48,186 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf02-45949, joinInfo=null, topologyId=87, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf03-24234: 128+128, edg-perf01-21525: 128+128, edg-perf02-45949: 128+128, edg-perf04-55497: 128+128]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf02-45949, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,162 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf02-45949, joinInfo=null, topologyId=89, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,158 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf02-45949, joinInfo=null, topologyId=88, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf03-24234: 128+128, edg-perf01-21525: 128+128, edg-perf02-45949: 128+128, edg-perf04-55497: 128+128]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,175 CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-perf02-45949, joinInfo=null, topologyId=90, rebalanceId=24, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 171+170, edg-perf01-21525: 171+171, edg-perf04-55497: 170+171]}, availabilityMode=null, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,263 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-55497, joinInfo=null, topologyId=89, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf03-24234: 128+128, edg-perf01-21525: 128+128, edg-perf02-45949: 128+128, edg-perf04-55497: 128+128]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=27} [sender=edg-perf04-55497]
07:50:08,268 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-55497, joinInfo=null, topologyId=90, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=27} [sender=edg-perf04-55497]
07:50:08,306 CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-perf04-55497, joinInfo=null, topologyId=91, rebalanceId=24, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 171+170, edg-perf01-21525: 171+171, edg-perf04-55497: 170+171]}, availabilityMode=null, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=27} [sender=edg-perf04-55497]
{noformat}
I think the problem is that perf01 receives the REBALANCE_START command while it already has a rebalance in progress. Normally this can only happen if the previous CH_UPDATE was delayed, and this is fixed by executing a fake CH_UPDATE. But in this case the topology id of the REBALANCE_START is just 1 higher than the current topology id, and the fake CH_UPDATE is not executed, so the old state transfer is not cleaned up properly.
In particular, {{StateConsumerImpl.stateTransferTopologyId}} stays 90, and {{StateResponseCommands}} sent for topology 90 are not ignored as they should be.
Radim, could you also attach the ClusterTopologyManagerImpl|ClusterCacheStatus|PreferConsistencyStrategy logs from perf04 around 07:50:08?
was (Author: dan.berindei):
Seems like perf04 started a rebalance before shutting down, but perf04 somehow missed those topologies and the first topology it tries to install:
{noformat}
07:47:48,186 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf02-45949, joinInfo=null, topologyId=87, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf03-24234: 128+128, edg-perf01-21525: 128+128, edg-perf02-45949: 128+128, edg-perf04-55497: 128+128]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf02-45949, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,162 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf02-45949, joinInfo=null, topologyId=89, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,158 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf02-45949, joinInfo=null, topologyId=88, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf03-24234: 128+128, edg-perf01-21525: 128+128, edg-perf02-45949: 128+128, edg-perf04-55497: 128+128]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,175 CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-perf02-45949, joinInfo=null, topologyId=90, rebalanceId=24, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 171+170, edg-perf01-21525: 171+171, edg-perf04-55497: 170+171]}, availabilityMode=null, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=26} [sender=edg-perf02-45949]
07:50:08,263 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-55497, joinInfo=null, topologyId=89, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf03-24234: 128+128, edg-perf01-21525: 128+128, edg-perf02-45949: 128+128, edg-perf04-55497: 128+128]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=27} [sender=edg-perf04-55497]
07:50:08,268 CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-55497, joinInfo=null, topologyId=90, rebalanceId=23, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=27} [sender=edg-perf04-55497]
07:50:08,306 CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-perf04-55497, joinInfo=null, topologyId=91, rebalanceId=24, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 200+56, edg-perf01-21525: 153+103, edg-perf04-55497: 159+97]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-24234: 171+170, edg-perf01-21525: 171+171, edg-perf04-55497: 170+171]}, availabilityMode=null, actualMembers=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], throwable=null, viewId=27} [sender=edg-perf04-55497]
{noformat}
I think the problem is that perf01 receives the REBALANCE_START command while it already has a rebalance in progress. Normally this can only happen if the previous CH_UPDATE was delayed, and this is fixed by executing a fake CH_UPDATE. But in this case the topology id of the REBALANCE_START is just 1 higher than the current topology id, and the fake CH_UPDATE is not executed, so the old state transfer is not cleaned up properly.
In particular, {{StateConsumerImpl.stateTransferTopologyId}} stays 90, and {{StateResponseCommands}} sent for topology 90 are not ignored as they should be.
Radim, could you also attach the ClusterTopologyManagerImpl|ClusterCacheStatus|PreferConsistencyStrategy logs from perf04 around 07:50:08?
> During ST, previously removed entry was revived
> -----------------------------------------------
>
> Key: ISPN-5166
> URL: https://issues.jboss.org/browse/ISPN-5166
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 7.1.0.Beta1
> Reporter: Radim Vansa
> Priority: Critical
> Attachments: topo.txt
>
>
> In transactional mode, entry was removed (transaction succeeded and the entry was removed from data container), but later, when StateResponseCommand arrives, the entry is revived with the old value.
> Here is how the remove is executed on edg-perf01:
> {code}
> 07:50:08,276 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Replication task sending PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=89} to single recipient edg-perf03-24234 with response mode GET_ALL
> 07:50:08,368 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) Response(s) to PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=89} is {edg-perf03-24234=null}
> 07:50:08,369 TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] (DefaultStressor-5) Forwarding command PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=90} to new targets [edg-perf03-24234]
> 07:50:08,369 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) edg-perf01-21525 invoking PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=90} to recipient list [edg-perf03-24234] with options RpcOptions{timeout=60000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS, skipReplicationQueue=false}
> 07:50:08,527 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) Response(s) to PrepareCommand {modifications=[RemoveCommand{key=key_000000000000050E, value=null, flags=null, valueMatcher=MATCH_ALWAYS}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheName='testCache', topologyId=90} is {edg-perf03-24234=null}
> 07:50:08,529 TRACE [org.infinispan.transaction.LocalTransaction] (DefaultStressor-5) getCommitNodes recipients=[edg-perf01-21525, edg-perf03-24234], currentTopologyId=90, members=[edg-perf03-24234, edg-perf01-21525, edg-perf04-55497], txTopologyId=88
> 07:50:08,531 TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (DefaultStressor-5) dests=[edg-perf01-21525, edg-perf03-24234], command=CommitCommand {gtx=GlobalTransaction:<edg-perf01-21525>:957
> 26:local, cacheName='testCache', topologyId=90}, mode=SYNCHRONOUS_IGNORE_LEAVERS, timeout=60000
> 07:50:08,531 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Replication task sending CommitCommand {gtx=GlobalTransaction:<edg-perf01-21525>:95726:local, cacheNam
> e='testCache', topologyId=90} to addresses [edg-perf03-24234] with response mode GET_ALL
> 07:50:08,555 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Responses: [sender=edg-perf03-24234, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
> 07:50:08,555 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (DefaultStressor-5) About to commit entry ReadCommittedEntry(49e1fe5d){key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], oldValue=null, isCreated=false, isChanged=true, isRemoved=true, isValid=false, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
> 07:50:08,561 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (DefaultStressor-5) Updating entry (key=key_000000000000050E removed=true valid=false changed=true created=false loaded=false value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ] metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 07:50:08,561 TRACE [org.infinispan.statetransfer.CommitManager] (DefaultStressor-5) Committed key=key_000000000000050E. Old discard policy=null. New discard policy=DiscardPolicy{discardStateTransfer=true, discardXSiteStateTransfer=false}
> {code}
> The commit command on edg-perf03 is executed only after the StateResponseCommand is sent (and received on edg-perf01):
> {code}
> 07:50:10,736 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-254) Invoked with command PutKeyValueCommand{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP, PUT_FOR_STATE_TRANSFER, SKIP_SHARED_CACHE_STORE, SKIP_OWNERSHIP_CHECK, IGNORE_RETURN_VALUES, SKIP_XSITE_BACKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@3e54512]
> 07:50:10,747 TRACE [org.infinispan.transaction.xa.TransactionXaAdapter] (remote-thread-254) start called on tx GlobalTransaction:<edg-perf01-21525>:95972:local
> 07:50:10,758 TRACE [org.infinispan.transaction.LocalTransaction] (remote-thread-254) Adding modification PutKeyValueCommand{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP, PUT_FOR_STATE_TRANSFER, SKIP_SHARED_CACHE_STORE, SKIP_OWNERSHIP_CHECK, IGNORE_RETURN_VALUES, SKIP_XSITE_BACKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}. Mod list is null
> 07:50:10,763 TRACE [org.infinispan.transaction.xa.TransactionXaAdapter] (remote-thread-254) end called on tx GlobalTransaction:<edg-perf01-21525>:95972:local(testCache)
> 07:50:10,763 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-254) Invoked with command PrepareCommand {modifications=null, onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf01-21525>:95972:local, cacheName='testCache', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@3df73149]
> 07:50:10,779 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (remote-thread-254) About to commit entry ReadCommittedEntry(206acaec){key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ], oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
> 07:50:10,779 TRACE [org.infinispan.statetransfer.CommitManager] (remote-thread-254) Trying to commit. Key=key_000000000000050E. Operation Flag=PUT_FOR_STATE_TRANSFER, L1 invalidation=false
> 07:50:10,782 TRACE [org.infinispan.container.DefaultDataContainer] (remote-thread-254) Store ImmortalCacheEntry{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ]} in container
> {code}
> Later, I can see that the value was really writen to the container (further read retrieves it):
> {code}
> 07:53:26,778 TRACE [org.infinispan.container.EntryFactoryImpl] (DefaultStressor-5) Retrieved from container ImmortalCacheEntry{key=key_000000000000050E, value=[5 #19: 380, 431, 453, 459, 467, 650, 851, 1209, 1405, 1893, 2080, 2353, 2353, 2685, 2950, 3702, 3936, 4188, 4973, ]} (forceFetch=false, isLocal=true)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 2 months
[JBoss JIRA] (ISPN-5158) Transaction rolled back but returns successful response
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/ISPN-5158?page=com.atlassian.jira.plugin.... ]
RH Bugzilla Integration commented on ISPN-5158:
-----------------------------------------------
Misha H. Ali <mhusnain(a)redhat.com> changed the Status of [bug 1184285|https://bugzilla.redhat.com/show_bug.cgi?id=1184285] from NEW to ASSIGNED
> Transaction rolled back but returns successful response
> -------------------------------------------------------
>
> Key: ISPN-5158
> URL: https://issues.jboss.org/browse/ISPN-5158
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 7.1.0.Beta1
> Reporter: Radim Vansa
> Assignee: Dan Berindei
> Priority: Critical
> Attachments: tx.txt, views.txt
>
>
> When the cluster is merging, it is possible that a node is removed from the view although it is still responsive. Eventually the cluster is merged correctly, but since the node is reported as missing from the view, transaction originating from this node is rolled back.
> {code}
> 10:01:36,116 TRACE [org.infinispan.interceptors.TxInterceptor] (remote-thread-151) Rolling back remote transaction GlobalTransaction:<edg-perf02-39415>:28106:remote because either already completed(false) or originator no longer in the cluster(true).
> {code}
> However, even after this a successful response is sent to the originator:
> {code}
> 10:01:36,119 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-151) About to send back response null for command PrepareCommand {modifications=[PutKeyValueCommand{key=key_0000000000001318, value=[19 #1: 1195, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf02-39415>:28106:remote, cacheName='testCache', topologyId=47}
> {code}
> Originator then expects that the transaction was successfully prepared:
> {code}
> 10:01:36,124 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-9) Responses: [sender=edg-perf01-36235, received=true, suspected=false]
> [sender=edg-perf03-24110, received=true, suspected=false]
> 10:01:36,135 TRACE [org.infinispan.transaction.TransactionCoordinator] (DefaultStressor-9) Committing transaction GlobalTransaction:<edg-perf02-39415>:28106:local
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 2 months
[JBoss JIRA] (ISPN-5137) Transaction from new topology rolled back (but succeeds on originator)
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/ISPN-5137?page=com.atlassian.jira.plugin.... ]
RH Bugzilla Integration commented on ISPN-5137:
-----------------------------------------------
Misha H. Ali <mhusnain(a)redhat.com> changed the Status of [bug 1184285|https://bugzilla.redhat.com/show_bug.cgi?id=1184285] from NEW to ASSIGNED
> Transaction from new topology rolled back (but succeeds on originator)
> ----------------------------------------------------------------------
>
> Key: ISPN-5137
> URL: https://issues.jboss.org/browse/ISPN-5137
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 7.1.0.Alpha1, 7.0.3.Final
> Reporter: Radim Vansa
> Assignee: Dan Berindei
> Priority: Critical
> Fix For: 7.1.0.CR1
>
>
> During a merge of (edg-perf01, edg-perf02, edg-perf03) + (edg-perf04), transaction executed on edg-perf04 in latest topology is silently rolled back and commit command is ignored since the topology has not arrived yet.
> Topologies on edg-perf04
> {code}
> 09:06:38,233 DEBUG [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-23) Updating cluster-wide current topology for cache testCache, topology = CacheTopology{id=51, rebalanceId=12, currentCH
> =DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, unionCH=null, actualMembers=[edg-perf03-18534, edg-perf02-60481, e
> dg-perf01-19198]}, availability mode = AVAILABLE
> 09:06:38,248 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-21) Attempting to execute command on self: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04
> -59142, joinInfo=null, topologyId=51, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, ava
> ilabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19}
> 09:06:38,413 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (transport-thread-23) Replication task sending CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-per
> f04-59142, joinInfo=null, topologyId=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null,
> availabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} to addresses null with response mode GET_NONE
> 09:06:38,415 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-10) Attempting to execute command on self: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04
> -59142, joinInfo=null, topologyId=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, ava
> ilabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19}
> 09:06:38,451 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-8) Attempting to execute command on self: CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-p
> erf04-59142, joinInfo=null, topologyId=53, rebalanceId=13, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=Defa
> ultConsistentHash{ns = 512, owners = (4)[edg-perf04-59142: 128+128, edg-perf03-18534: 128+128, edg-perf02-60481: 128+128, edg-perf01-19198: 128+128]}, availabilityMode=null, actualMembers=[edg-perf04-59142, edg-
> perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19}
> {code}
> Transaction on edg-perf04 can be executed, since all owners are in current topology, though this node itself is degraded yet:
> {code}
> 09:06:38,545 TRACE [org.infinispan.partionhandling.impl.PartitionHandlingManagerImpl] (DefaultStressor-5) Checking availability for key=key_00000000000022CF, status=DEGRADED_MODE
> 09:06:38,545 TRACE [org.infinispan.partionhandling.impl.PartitionHandlingManagerImpl] (DefaultStressor-5) Key key_00000000000022CF is available.
> 09:06:38,549 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) edg-perf04-59142 invoking PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:local, cacheName='testCache', topologyId=51} to recipient list [edg-perf01-19198, edg-perf02-60481] with options RpcOptions{timeout=60000, unit=MILLISECONDS, fifoOrder=true, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS, skipReplicationQueue=false}
> 09:06:38,780 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Responses: [sender=edg-perf01-19198, received=true, suspected=false]
> [sender=edg-perf02-60481, received=true, suspected=false]
> 09:06:38,788 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) edg-perf04-59142 invoking CommitCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:local, cacheName='testCache', topologyId=51} to recipient list [edg-perf01-19198, edg-perf02-60481] with options RpcOptions{timeout=60000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS_IGNORE_LEAVERS, skipReplicationQueue=false}
> 09:06:39,080 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Responses: [sender=edg-perf01-19198, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
> [sender=edg-perf02-60481, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
> {code}
> These are topologies on edg-perf02:
> {code}
> 09:06:38,417 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-55) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-59142, joinInfo=null, topologyId=51, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> 09:06:38,467 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-56) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-59142, joinInfo=null, topologyId=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> 09:06:38,577 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-52) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-perf04-59142, joinInfo=null, topologyId=53, rebalanceId=13, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf04-59142: 128+128, edg-perf03-18534: 128+128, edg-perf02-60481: 128+128, edg-perf01-19198: 128+128]}, availabilityMode=null, actualMembers=[edg-perf04-59142, edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> {code}
> The transaction is successfully prepared on edg-perf02 (even twice as the prepare command is resent from edg-perf01)
> {code}
> 09:06:38,613 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) Calling perform() on PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> 09:06:38,620 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (remote-thread-64) Successfully acquired lock key_00000000000022CF!
> 09:06:38,626 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) About to send back response null for command PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> 09:06:38,670 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) Calling perform() on PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false,
> gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=52} // resent from edg-perf01
> 09:06:38,672 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (remote-thread-64) Already own lock for entry
> 09:06:38,675 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) About to send back response null for command PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=52}
> {code}
> However, as topology 53 is installed, this transaction is rolled back:
> {code}
> 09:06:38,577 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-52) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=RE
> BALANCE_START, sender=edg-perf04-59142, joinInfo=null, topologyId=53, rebalanceId=13, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198
> : 170+171]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf04-59142: 128+128, edg-perf03-18534: 128+128, edg-perf02-60481: 128+128, edg-perf01-19198: 128+128]}, availabilityMode=null, actualMemb
> ers=[edg-perf04-59142, edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> 09:06:38,658 DEBUG [org.infinispan.topology.LocalTopologyManagerImpl] (remote-thread-52) Installing fake cache topology CacheTopology{id=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, unionCH=null, actualMembers=null} for cache testCache
> 09:06:38,670 DEBUG [org.infinispan.transaction.TransactionTable] (remote-thread-52) The originating node left the cluster for 6 remote transactions
> 09:06:38,675 DEBUG [org.infinispan.transaction.TransactionTable] (remote-thread-52) Rolling back transaction GlobalTransaction:<edg-perf04-59142>:23898:remote because originator edg-perf04-59142 left the cluster
> 09:06:38,675 TRACE [org.infinispan.commands.tx.AbstractTransactionBoundaryCommand] (remote-thread-52) About to execute tx command RollbackCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName
> ='testCache', topologyId=-1}
> {code}
> But even after that, the CommitCommand still suceeds:
> {code}
> 09:06:38,811 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-56) Calling perform() on CommitCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> 09:06:38,812 TRACE [org.infinispan.commands.tx.AbstractTransactionBoundaryCommand] (remote-thread-56) Did not find a RemoteTransaction for GlobalTransaction:<edg-perf04-59142>:23898:remote
> 09:06:38,812 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-56) About to send back response SuccessfulResponse{responseValue=null} for command CommitCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 2 months
[JBoss JIRA] (ISPN-5137) Transaction from new topology rolled back (but succeeds on originator)
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/ISPN-5137?page=com.atlassian.jira.plugin.... ]
RH Bugzilla Integration updated ISPN-5137:
------------------------------------------
Bugzilla References: https://bugzilla.redhat.com/show_bug.cgi?id=1180680, https://bugzilla.redhat.com/show_bug.cgi?id=1184285 (was: https://bugzilla.redhat.com/show_bug.cgi?id=1180680)
> Transaction from new topology rolled back (but succeeds on originator)
> ----------------------------------------------------------------------
>
> Key: ISPN-5137
> URL: https://issues.jboss.org/browse/ISPN-5137
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 7.1.0.Alpha1, 7.0.3.Final
> Reporter: Radim Vansa
> Assignee: Dan Berindei
> Priority: Critical
> Fix For: 7.1.0.CR1
>
>
> During a merge of (edg-perf01, edg-perf02, edg-perf03) + (edg-perf04), transaction executed on edg-perf04 in latest topology is silently rolled back and commit command is ignored since the topology has not arrived yet.
> Topologies on edg-perf04
> {code}
> 09:06:38,233 DEBUG [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-23) Updating cluster-wide current topology for cache testCache, topology = CacheTopology{id=51, rebalanceId=12, currentCH
> =DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, unionCH=null, actualMembers=[edg-perf03-18534, edg-perf02-60481, e
> dg-perf01-19198]}, availability mode = AVAILABLE
> 09:06:38,248 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-21) Attempting to execute command on self: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04
> -59142, joinInfo=null, topologyId=51, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, ava
> ilabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19}
> 09:06:38,413 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (transport-thread-23) Replication task sending CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-per
> f04-59142, joinInfo=null, topologyId=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null,
> availabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} to addresses null with response mode GET_NONE
> 09:06:38,415 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-10) Attempting to execute command on self: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04
> -59142, joinInfo=null, topologyId=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, ava
> ilabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19}
> 09:06:38,451 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-8) Attempting to execute command on self: CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-p
> erf04-59142, joinInfo=null, topologyId=53, rebalanceId=13, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=Defa
> ultConsistentHash{ns = 512, owners = (4)[edg-perf04-59142: 128+128, edg-perf03-18534: 128+128, edg-perf02-60481: 128+128, edg-perf01-19198: 128+128]}, availabilityMode=null, actualMembers=[edg-perf04-59142, edg-
> perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19}
> {code}
> Transaction on edg-perf04 can be executed, since all owners are in current topology, though this node itself is degraded yet:
> {code}
> 09:06:38,545 TRACE [org.infinispan.partionhandling.impl.PartitionHandlingManagerImpl] (DefaultStressor-5) Checking availability for key=key_00000000000022CF, status=DEGRADED_MODE
> 09:06:38,545 TRACE [org.infinispan.partionhandling.impl.PartitionHandlingManagerImpl] (DefaultStressor-5) Key key_00000000000022CF is available.
> 09:06:38,549 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) edg-perf04-59142 invoking PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:local, cacheName='testCache', topologyId=51} to recipient list [edg-perf01-19198, edg-perf02-60481] with options RpcOptions{timeout=60000, unit=MILLISECONDS, fifoOrder=true, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS, skipReplicationQueue=false}
> 09:06:38,780 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Responses: [sender=edg-perf01-19198, received=true, suspected=false]
> [sender=edg-perf02-60481, received=true, suspected=false]
> 09:06:38,788 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (DefaultStressor-5) edg-perf04-59142 invoking CommitCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:local, cacheName='testCache', topologyId=51} to recipient list [edg-perf01-19198, edg-perf02-60481] with options RpcOptions{timeout=60000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS_IGNORE_LEAVERS, skipReplicationQueue=false}
> 09:06:39,080 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (DefaultStressor-5) Responses: [sender=edg-perf01-19198, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
> [sender=edg-perf02-60481, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
> {code}
> These are topologies on edg-perf02:
> {code}
> 09:06:38,417 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-55) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-59142, joinInfo=null, topologyId=51, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> 09:06:38,467 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-56) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=CH_UPDATE, sender=edg-perf04-59142, joinInfo=null, topologyId=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, availabilityMode=AVAILABLE, actualMembers=[edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> 09:06:38,577 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-52) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-perf04-59142, joinInfo=null, topologyId=53, rebalanceId=13, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf04-59142: 128+128, edg-perf03-18534: 128+128, edg-perf02-60481: 128+128, edg-perf01-19198: 128+128]}, availabilityMode=null, actualMembers=[edg-perf04-59142, edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> {code}
> The transaction is successfully prepared on edg-perf02 (even twice as the prepare command is resent from edg-perf01)
> {code}
> 09:06:38,613 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) Calling perform() on PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> 09:06:38,620 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (remote-thread-64) Successfully acquired lock key_00000000000022CF!
> 09:06:38,626 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) About to send back response null for command PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> 09:06:38,670 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) Calling perform() on PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false,
> gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=52} // resent from edg-perf01
> 09:06:38,672 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (remote-thread-64) Already own lock for entry
> 09:06:38,675 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-64) About to send back response null for command PrepareCommand {modifications=[PutKeyValueCommand{key=key_00000000000022CF, value=[35 #4: 197, 314, 331, 1101, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=52}
> {code}
> However, as topology 53 is installed, this transaction is rolled back:
> {code}
> 09:06:38,577 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (remote-thread-52) Attempting to execute non-CacheRpcCommand command: CacheTopologyControlCommand{cache=testCache, type=RE
> BALANCE_START, sender=edg-perf04-59142, joinInfo=null, topologyId=53, rebalanceId=13, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198
> : 170+171]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (4)[edg-perf04-59142: 128+128, edg-perf03-18534: 128+128, edg-perf02-60481: 128+128, edg-perf01-19198: 128+128]}, availabilityMode=null, actualMemb
> ers=[edg-perf04-59142, edg-perf03-18534, edg-perf02-60481, edg-perf01-19198], throwable=null, viewId=19} [sender=edg-perf04-59142]
> 09:06:38,658 DEBUG [org.infinispan.topology.LocalTopologyManagerImpl] (remote-thread-52) Installing fake cache topology CacheTopology{id=52, rebalanceId=12, currentCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf03-18534: 171+171, edg-perf02-60481: 171+170, edg-perf01-19198: 170+171]}, pendingCH=null, unionCH=null, actualMembers=null} for cache testCache
> 09:06:38,670 DEBUG [org.infinispan.transaction.TransactionTable] (remote-thread-52) The originating node left the cluster for 6 remote transactions
> 09:06:38,675 DEBUG [org.infinispan.transaction.TransactionTable] (remote-thread-52) Rolling back transaction GlobalTransaction:<edg-perf04-59142>:23898:remote because originator edg-perf04-59142 left the cluster
> 09:06:38,675 TRACE [org.infinispan.commands.tx.AbstractTransactionBoundaryCommand] (remote-thread-52) About to execute tx command RollbackCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName
> ='testCache', topologyId=-1}
> {code}
> But even after that, the CommitCommand still suceeds:
> {code}
> 09:06:38,811 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-56) Calling perform() on CommitCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> 09:06:38,812 TRACE [org.infinispan.commands.tx.AbstractTransactionBoundaryCommand] (remote-thread-56) Did not find a RemoteTransaction for GlobalTransaction:<edg-perf04-59142>:23898:remote
> 09:06:38,812 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-56) About to send back response SuccessfulResponse{responseValue=null} for command CommitCommand {gtx=GlobalTransaction:<edg-perf04-59142>:23898:remote, cacheName='testCache', topologyId=51}
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 2 months