[infinispan-issues] [JBoss JIRA] (ISPN-4426) Transaction replayed but not committed

[Dan Berindei (JIRA)]

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

Dan Berindei commented on ISPN-4426:
------------------------------------

I found a little more information in the log: the CommitCommand is actually executed 3 times, because both the originator and and the old owners forward the command to the new owners in the write CH (including the old owners):

{noformat}
10:07:31,964 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-5) Calling perform() on CommitCommand {gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=41}
10:07:31,968 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-23) Calling perform() on CommitCommand {gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=41}
10:07:32,408 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-23) Calling perform() on CommitCommand {gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=41}
{noformat}

The problem seems to be caused by the ISPN-4137 fix, as the transaction is now only marked as completed in TxInterceptor. The first thread (remote-thread-5) decides to replay the PrepareCommand and updates the {{lookedUpEntriesTopology}} to the new topology. Then the second thread (remote-thread-23) sees that it doesn't need to replay the PrepareCommand and tries to execute the CommitCommand directly. The modifications list is empty, however, so nothing is committed, but the transaction is marked as completed, which then prevents remote-thread-5 (and again remote-thread-23) from doing anything else:

{noformat}
10:07:31,974 DEBUG [org.infinispan.statetransfer.StateTransferInterceptor] (remote-thread-5) Replaying the transactions received as a result of state transfer PrepareCommand {modifications=[PutKeyValueCommand{key=key_0000000000001531, value=[21 #21: 246, 320, 846, 1083, 1256, 1398, 1526, 1667, 1816, 2533, 2557, 2724, 2804, 2840, 2921, 3492, 3613, 3659, 4413, 4677, 5760, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}, ... onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=-1}
10:07:31,974 TRACE [org.infinispan.commands.tx.PrepareCommand] (remote-thread-5) Invoking remotely originated prepare: PrepareCommand {modifications=[PutKeyValueCommand{key=key_0000000000001531, value=[21 #21: 246, 320, 846, 1083, 1256, 1398, 1526, 1667, 1816, 2533, 2557, 2724, 2804, 2840, 2921, 3492, 3613, 3659, 4413, 4677, 5760, ], flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedMetadata{version=null}, successful=true}, ... ], onePhaseCommit=false, gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=-1} with invocation context: org.infinispan.context.impl.RemoteTxInvocationContext at 7a5688e0
10:07:31,976 DEBUG [org.infinispan.statetransfer.StateTransferInterceptor] (remote-thread-23) handleTopologyAffectedCommand for command CommitCommand {gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=41}, origin edg-perf03-58446
10:07:31,980 DEBUG [org.infinispan.interceptors.EntryWrappingInterceptor] (remote-thread-23) Commiting CommitCommand
10:07:31,980 DEBUG [org.infinispan.statetransfer.StateTransferInterceptor] (remote-thread-23) handled command CommitCommand {gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=41}, origin edg-perf03-58446
10:07:32,013 DEBUG [org.infinispan.statetransfer.StateTransferInterceptor] (remote-thread-5) Prepare command replayed
10:07:32,013 DEBUG [org.infinispan.statetransfer.StateTransferInterceptor] (remote-thread-5) handleTopologyAffectedCommand for command CommitCommand {gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=41}, origin edg-perf03-58446
10:07:32,014 DEBUG [org.infinispan.statetransfer.StateTransferInterceptor] (remote-thread-5) handled command CommitCommand {gtx=GlobalTransaction:<edg-perf03-58446>:23655:remote, cacheName='testCache', topologyId=41}, origin edg-perf03-58446
10:07:32,408 TRACE [org.infinispan.commands.tx.AbstractTransactionBoundaryCommand] (remote-thread-23) Did not find a RemoteTransaction for GlobalTransaction:<edg-perf03-58446>:23655:remote
{noformat}


> Transaction replayed but not committed
> --------------------------------------
>
>                 Key: ISPN-4426
>                 URL: https://issues.jboss.org/browse/ISPN-4426
>             Project: Infinispan
>          Issue Type: Bug
>      Security Level: Public(Everyone can see) 
>          Components: State Transfer
>    Affects Versions: 7.0.0.Alpha4
>            Reporter: Radim Vansa
>            Assignee: Dan Berindei
>            Priority: Critical
>              Labels: 63gablocker
>
> Dist TX cache, node C is joining. In previous topology, entry is owned by A (primary) and B (backup). In new topology, primary ownership is transferred to C, B stays backup.
> 1. TX is prepared in old topology and is being committed, when topology changes
> 2. on C (the new owner), the TX info is received and later even the old entry
> 3. C receives the CommitCommand, therefore, it correctly replays the PrepareCommand.
> 4. When the entries are about to be committed, in TxInterceptor the transaction is found to be already completed as it has lower TxID.
> Result: the transaction is not being executed and stale data stay on the node (with my algortihm it eventually led to complete entry loss).



--
This message was sent by Atlassian JIRA
(v6.2.6#6264)