[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 commented on ISPN-5166:
-----------------------------------
Dan, I've already seen several 'pretty much zero'-probability situations happen repeatedly. Please, don't consider this fixed unless you're confident that it's fixed in any sequence of view/command arrivals.
> 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}
--
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 Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-5166?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-5166:
-------------------------------
Status: Open (was: New)
> 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 Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-5166?page=com.atlassian.jira.plugin.... ]
Dan Berindei reassigned ISPN-5166:
----------------------------------
Assignee: Dan Berindei
> 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}
--
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 Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-5166?page=com.atlassian.jira.plugin.... ]
Dan Berindei commented on ISPN-5166:
------------------------------------
Ok, I think I found the root cause. edg-perf03 receives the {{REBALANCE_START}} command from edg-perf02 with topology 90, but it doesn't immediately execute it because it has an older JGroups view. The rebalance is only started after edg-perf04 becomes coordinator, and after edg-perf03 replies to the {{GET_STATUS}} command with the older topology 88. This means edg-perf04's topology update has id 89 and is ignored by edg-perf03.
{{LocalTopologyManagerImpl}} should verify that the sender is still the coordinator after waiting for the proper view. In theory there will still be a small possibility for the old coordinator's last view and the new coordinator's view to arrive so close together that the {{GET_STATUS}} command will execute while the old coordinator {{REBALANCE_START}} is executing, but the chances for that to happen are pretty much zero. Still, I'll investigate adding some synchronization that doesn't rely on the coordinator waiting for the other members to execute old {{GET_TRANSACTIONS}} commands (which happens synchronously during {{REBALANCE_START}}).
> 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-4726) Compatibility mode: modules
by Ion Savin (JIRA)
[ https://issues.jboss.org/browse/ISPN-4726?page=com.atlassian.jira.plugin.... ]
Ion Savin updated ISPN-4726:
----------------------------
Fix Version/s: 7.1.0.CR1
(was: 7.2.0.CR1)
> Compatibility mode: modules
> ---------------------------
>
> Key: ISPN-4726
> URL: https://issues.jboss.org/browse/ISPN-4726
> Project: Infinispan
> Issue Type: Bug
> Components: Documentation-Servers
> Affects Versions: 7.0.0.Beta1
> Reporter: Radim Vansa
> Assignee: Ion Savin
> Fix For: 7.1.0.CR1
>
>
> I've tried to run the server in compatibility mode, but haven't included the JAR with class uploaded by HotRod client - and boom, I got ClassNotFoundExceptions.
> To resolve this, I've modified modules.xml for infinispan-commons and added the JAR with my classes there, but I don't think this is a correct solution - nor creating a new module and adding this as dependency to infinispan-commons. IMO I am using Infinispan as service, therefore, I should not put application classes as dependencies into modules.
> The recommended approach is not described neither in User Guide nor Server Guide - these specify just the configuration option.
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 2 months
[JBoss JIRA] (ISPN-2886) Using multiple DefaultCacheManager w/o jmx leads to JmxDomainConflictException
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-2886?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec reassigned ISPN-2886:
-----------------------------------------
Assignee: Sebastian Łaskawiec (was: Galder Zamarreño)
> Using multiple DefaultCacheManager w/o jmx leads to JmxDomainConflictException
> ------------------------------------------------------------------------------
>
> Key: ISPN-2886
> URL: https://issues.jboss.org/browse/ISPN-2886
> Project: Infinispan
> Issue Type: Bug
> Components: JMX, reporting and management
> Affects Versions: 5.2.1.Final
> Reporter: Thomas Fromm
> Assignee: Sebastian Łaskawiec
> Priority: Minor
>
> Creating multiple instances of DefaultCacheManager leads to CacheManagerJmxRegistrationTest, even when JMX is disabled in configuration.
> org.infinispan.jmx.JmxDomainConflictException: Domain already registered org.infinispan when trying to register: type=CacheManager,name="DefaultCacheManager"
> at org.infinispan.jmx.JmxUtil.buildJmxDomain(JmxUtil.java:75)
> at org.infinispan.jmx.CacheManagerJmxRegistration.updateDomain(CacheManagerJmxRegistration.java:101)
> at org.infinispan.jmx.CacheManagerJmxRegistration.buildRegistrar(CacheManagerJmxRegistration.java:95)
> at org.infinispan.jmx.AbstractJmxRegistration.registerMBeans(AbstractJmxRegistration.java:59)
> at org.infinispan.jmx.CacheManagerJmxRegistration.start(CacheManagerJmxRegistration.java:63)
> at org.infinispan.manager.DefaultCacheManager.start(DefaultCacheManager.java:705)
> at org.infinispan.manager.DefaultCacheManager.<init>(DefaultCacheManager.java:300)
> at org.infinispan.manager.DefaultCacheManager.<init>(DefaultCacheManager.java:171)
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 2 months
[JBoss JIRA] (ISPN-4726) Compatibility mode: modules
by Radim Vansa (JIRA)
[ https://issues.jboss.org/browse/ISPN-4726?page=com.atlassian.jira.plugin.... ]
Radim Vansa commented on ISPN-4726:
-----------------------------------
I guess the fix version should be 7.1.0.CR1, shouldn't it?
And there should be also follow-up JIRA linked that will handle the problem - is there anything like that? I thought there are already some plans about adding custom classes to the server.
> Compatibility mode: modules
> ---------------------------
>
> Key: ISPN-4726
> URL: https://issues.jboss.org/browse/ISPN-4726
> Project: Infinispan
> Issue Type: Bug
> Components: Documentation-Servers
> Affects Versions: 7.0.0.Beta1
> Reporter: Radim Vansa
> Assignee: Ion Savin
> Fix For: 7.2.0.CR1
>
>
> I've tried to run the server in compatibility mode, but haven't included the JAR with class uploaded by HotRod client - and boom, I got ClassNotFoundExceptions.
> To resolve this, I've modified modules.xml for infinispan-commons and added the JAR with my classes there, but I don't think this is a correct solution - nor creating a new module and adding this as dependency to infinispan-commons. IMO I am using Infinispan as service, therefore, I should not put application classes as dependencies into modules.
> The recommended approach is not described neither in User Guide nor Server Guide - these specify just the configuration option.
--
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 RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/ISPN-5166?page=com.atlassian.jira.plugin.... ]
RH Bugzilla Integration updated ISPN-5166:
------------------------------------------
Bugzilla Update: Perform
Bugzilla References: https://bugzilla.redhat.com/show_bug.cgi?id=1184373
> 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