[infinispan-issues] [JBoss JIRA] (ISPN-5158) Transaction rolled back but returns successful response

[Radim Vansa (JIRA)]

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

Radim Vansa commented on ISPN-5158:
-----------------------------------

It seems that the fix is not complete. This is what I found when running with the fixes: It seems that transaction was rolled back but still did not throw an exception:

{code}
11:55:40,011 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-1,edg-perf02-35237) ISPN000093: Received new, MERGED cluster view: MergeView::[edg-perf03-14221|17] (3) [edg-perf03-14221, edg-perf01-13291, edg-perf02-35237], 8 subgroups: [edg-perf03-14221|8] (2) [edg-perf03-14221, edg-perf02-56279], [edg-perf03-14221|9] (3) [edg-perf03-14221, edg-perf01-13291, edg-perf02-56279], [edg-perf01-13291|4] (2) [edg-perf01-13291, edg-perf02-56279], [edg-perf01-13291|16] (1) [edg-perf01-13291], [edg-perf03-14221|5] (2) [edg-perf03-14221, edg-perf04-62504], [edg-perf03-14221|16] (3) [edg-perf03-14221, edg-perf04-62504, edg-perf02-35237], [edg-perf01-13291|8] (1) [edg-perf01-13291], [edg-perf03-14221|13] (2) [edg-perf03-14221, edg-perf04-62504]
11:55:40,012 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-15) Received new cluster view: 17, isCoordinator = false, becameCoordinator = false
11:57:31,680 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-1,edg-perf02-35237) ISPN000093: Received new, MERGED cluster view: MergeView::[edg-perf02-35237|18] (3) [edg-perf02-35237, edg-perf01-13291, edg-perf04-62504], 1 subgroups: [edg-perf04-62504|17] (1) [edg-perf04-62504]
11:57:31,683 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-18) Received new cluster view: 18, isCoordinator = true, becameCoordinator = true

11:57:31,979 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread-23) Attempting to execute command on self: CacheTopologyControlCommand{cache=testCache, type=REBALANCE_START, sender=edg-perf02-35237, joinInfo=null, topologyId=53, rebalanceId=14, currentCH=DefaultConsistentHash{ns = 512, owners = (2)[edg-perf02-35237: 257+85, edg-perf01-13291: 255+86]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf02-35237: 171+171, edg-perf01-13291: 171+170, edg-perf04-62504: 170+171]}, availabilityMode=null, actualMembers=[edg-perf02-35237, edg-perf01-13291, edg-perf04-62504], throwable=null, viewId=18}
11:57:32,004 TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (transport-thread-23) Waiting on view 18 being accepted
11:57:32,069 DEBUG [org.infinispan.topology.LocalTopologyManagerImpl] (transport-thread-23) Starting local rebalance for cache testCache, topology = CacheTopology{id=53, rebalanceId=14, currentCH=DefaultConsistentHash{ns = 512, owners = (2)[edg-perf02-35237: 257+85, edg-perf01-13291: 255+86]}, pendingCH=DefaultConsistentHash{ns = 512, owners = (3)[edg-perf02-35237: 171+171, edg-perf01-13291: 171+170, edg-perf04-62504: 170+171]}, unionCH=null, actualMembers=[edg-perf02-35237, edg-perf01-13291, edg-perf04-62504]}


11:57:32,113 TRACE [org.infinispan.commands.tx.PrepareCommand] (remote-thread-83) Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=key_0000000000001D43, value=[29 #19: 
54, 54, 85, 318, 786, 905, 985, 1276, 1313, 1464, 1551, 1585, 1621, 1972, 2014, 2319, 2319, 2415, 2471, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=Embe
ddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf03-14221>:47986:remote, cacheName='testCache', topologyId=50} with invocation context: org.infinispan.context.i
mpl.RemoteTxInvocationContext at b4026157
11:57:32,113 TRACE [org.infinispan.transaction.TransactionTable] (remote-thread-83) Created and registered remote transaction RemoteTransaction{modifications=[PutKeyValueCommand{key=key_0000000000001D43, value=[29 #19: 54, 54, 85, 318, 786, 905, 985, 1276, 1313, 1464, 1551, 1585, 1621, 1972, 2014, 2319, 2319, 2415, 2471, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, lookedUpEntriesTopology=2147483647, isMarkedForRollback=false, tx=GlobalTransaction:<edg-perf03-14221>:47986:remote, state=null}


11:57:32,116 TRACE [org.infinispan.statetransfer.StateTransferLockImpl] (transport-thread-23) Signalling transaction data received for topology 53
11:57:32,142 DEBUG [org.infinispan.transaction.TransactionTable] (transport-thread-23) Rolling back transaction GlobalTransaction:<edg-perf03-14221>:47986:remote because originator edg-perf03-14221 left the cluster
11:57:32,143 TRACE [org.infinispan.transaction.TransactionTable] (transport-thread-23) Marking transaction GlobalTransaction:<edg-perf03-14221>:47986:remote as completed


11:57:32,183 TRACE [org.infinispan.interceptors.TxInterceptor] (remote-thread-83) Rolling back remote transaction GlobalTransaction:<edg-perf03-14221>:47986:remote because either already completed (true) or originator no longer in the cluster (true).
11:57:32,214 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-83) About to send back response null for command PrepareCommand {modifications=[PutKeyValueCommand{key=key_0000000000001D4
3, value=[29 #19: 54, 54, 85, 318, 786, 905, 985, 1276, 1313, 1464, 1551, 1585, 1621, 1972, 2014, 2319, 2319, 2415, 2471, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALW
AYS, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf03-14221>:47986:remote, cacheName='testCache', topologyId=50}
{code}

The above can be found in /qa/hudson_jobs/jdg-resilience-split-dist-tx/builds/6/edg-perf02.log

> 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)