[infinispan-issues] [JBoss JIRA] (ISPN-5166) During ST, previously removed entry was revived

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 Assignee: Dan Berindei 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}