Bug 1019348 - InvalidateL1Command during State Transfer should not cancel writing the entry by State Transfer
InvalidateL1Command during State Transfer should not cancel writing the entry...
Status: VERIFIED
Product: JBoss Data Grid 6
Classification: JBoss
Component: Infinispan (Show other bugs)
6.2.0
Unspecified Unspecified
unspecified Severity urgent
: ER6
: 6.2.0
Assigned To: Tristan Tarrant
Martin Gencur
:
Depends On:
Blocks: 1017190
  Show dependency treegraph
 
Reported: 2013-10-15 10:20 EDT by Radim Vansa
Modified: 2014-03-24 21:37 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Known Issue
Doc Text:
In a cluster with L1 enabled, during rebalancing after a node joins or leaves the cluster, an entry may be lost on a node.
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
JBoss Issue Tracker ISPN-3633 Critical Resolved InvalidateL1Command during ST should not cancel writing the entry by ST 2016-11-13 03:22 EST
JBoss Issue Tracker ISPN-3780 Critical Resolved CLONE - InvalidateL1Command during ST should not cancel writing the entry by ST in nontx 2016-11-13 03:22 EST

  None (edit)
Description Radim Vansa 2013-10-15 10:20:32 EDT
When a node which is about to receive the entries for some segment receives InvalidateL1Command, this puts the key into StateConsumer.updatedKeys. After the entries for ST are received, the entry which was invalidated is not updated -> this result in losing the entry.
Comment 2 JBoss JIRA Server 2013-10-15 11:52:38 EDT
William Burns <wburns@redhat.com> updated the status of jira ISPN-3633 to Coding In Progress
Comment 3 JBoss JIRA Server 2013-10-18 17:30:22 EDT
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

Radim,

Do you have a trace of when this happens?  I have tried various scenarios of interleaving L1 invalidations with state transfer and I can't reproduce the issue yet.
Comment 4 JBoss JIRA Server 2013-10-20 22:11:24 EDT
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

If not, can you provide the configuration you used for the cache when you saw the problem?  I am particularly interested in if it was transactional and isolation level.
Comment 5 JBoss JIRA Server 2013-10-21 09:54:27 EDT
Radim Vansa <rvansa@redhat.com> made a comment on jira ISPN-3633

This was a transactional cache, with default (read committed) isolation.

Here is an excerpt from the logs, the full ones are on https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/jdg-radargun-resilience-dist-tx-l1/1/artifact/report/stdout.zip
08:38:28,313 TRACE [org.infinispan.statetransfer.StateConsumerImpl] (remote-thread-21) Key key_000000000000491A modified by a regular tx, state transfer will ignore it
08:38:28,313 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (remote-thread-21) Entry for key key_000000000000491A is null : not calling commitUpdate

Then later on, when executing StateResponseCommand:

08:38:45,514 TRACE [org.infinispan.transaction.LocalTransaction] (remote-thread-20) Adding modification PutKeyValueCommand{key=key_000000000000491A, value=[37 #1: 173, ], 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, metadata=EmbeddedMetadata{version=null}, successful=true, ignorePreviousValue=true}. Mod list is null
08:38:45,526 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (remote-thread-20) State transfer will not write key/value key_000000000000491A/[37 #1: 173, ] because it was already updated by somebody else

Therefore, for reproduction of this bug you need to get to this situation
1. A gets entry from B, caches that
2. state transfer from B to A begins (B is previous owner, A is new one) - some delay or many entries would be required here
3. entry is overwritten on B, invalidating A's record
4. when A get's the StateResponseCommand, the entry is not set
5. you may check the entry on A to be still null

Is there anything that should prohibit this behaviour? Am I oversimplifying something?
Comment 6 JBoss JIRA Server 2013-10-22 13:01:39 EDT
William Burns <wburns@redhat.com> updated the status of jira ISPN-3633 to Open
Comment 7 JBoss JIRA Server 2013-10-22 16:08:11 EDT
William Burns <wburns@redhat.com> updated the status of jira ISPN-3633 to Coding In Progress
Comment 8 JBoss JIRA Server 2013-10-22 19:34:30 EDT
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

In my test the command was forwarded to A, but I need to dig further still.
Comment 9 JBoss JIRA Server 2013-10-22 19:39:01 EDT
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

In my test the command was forwarded to the new owner, but I need to dig further still.
Comment 10 JBoss JIRA Server 2013-10-24 20:32:16 EDT
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

I was finally able to reproduce the problem.

It has to be done as so.

A - primary owner
C - non owner

# C gets value for k from A the current value and caches it in L1
# A is updating k with a new value in an explicit tx along with another entry that maps to C
# A sends and completes prepare to C where it believes it is only updating the other entry (note commit is not yet sent)
# State transfer starts and now C is the owner of k (note data has not been transferred yet)
# A now commits the tx which causes an invalidation to be sent to C and the value to be marked as modified
# State transfer finally is sent to C for data and is ignored.

Actually thinking about this it may have a worse issue even when L1 is not enabled that the data cached is the old value as it wouldn't retrieve the value from the put command.  I would need to test that still though.
Comment 11 JBoss JIRA Server 2013-10-25 11:30:26 EDT
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

Yeah a small tweak to my test by disabling L1 and I can confirm that it misses the updated value after the state transfer.
Comment 12 JBoss JIRA Server 2013-11-20 11:54:01 EST
Radim Vansa <rvansa@redhat.com> updated the status of jira ISPN-3633 to Reopened
Comment 13 JBoss JIRA Server 2013-11-20 11:54:01 EST
Radim Vansa <rvansa@redhat.com> made a comment on jira ISPN-3633

This issue still is not fixed for non-transactional cache: When topology changes so that owners [A, B] -> [A, C], C has the entry in L1 cache:

1. D executes PUT -> sends command to A
2. A executes the PUT, sends invalidation to C
3. ST from A to C begins
4. C receives InvalidateL1 and puts this key into updateKeys
5. C receives state but ignores the updated key
Comment 14 JBoss JIRA Server 2013-12-02 09:51:19 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

I was never able to reproduce this except when the issue was related to when the ST occurred in the middle of a prepare commit step, but I will revisit and see if I can find anything else.

Do you happen to have a trace of when this occurs with non tx caches?
Comment 15 JBoss JIRA Server 2013-12-02 09:51:23 EST
William Burns <wburns@redhat.com> updated the status of jira ISPN-3633 to Coding In Progress
Comment 16 JBoss JIRA Server 2013-12-02 11:22:09 EST
William Burns <wburns@redhat.com> updated the status of jira ISPN-3633 to Resolved
Comment 17 JBoss JIRA Server 2013-12-02 11:22:09 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

Radim I created ISPN-3780 as a clone of this to handle the non tx part.  I just wanted to make sure we have the proper fix version here since the tx version made it into 6.0.
Comment 18 JBoss JIRA Server 2013-12-02 11:22:12 EST
William Burns <wburns@redhat.com> updated the status of jira ISPN-3780 to Coding In Progress
Comment 19 JBoss JIRA Server 2013-12-03 02:33:30 EST
Radim Vansa <rvansa@redhat.com> made a comment on jira ISPN-3633

I don't store the traces for longer period, I could try to re-run the job and reproduce it again, if it is worth. I understand that you may have problems reproducing this (as for any race), but do you have any doubts about order of interleaving operations (and therefore you need the logs)?
Comment 20 JBoss JIRA Server 2013-12-03 07:13:04 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3633

I will try the interleavings again,  I wasn't able to reproduce that one before.  It must be more specific positioning, I will try to see what I can get.
Comment 21 JBoss JIRA Server 2013-12-04 10:25:42 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3780

Radim, I have converted over the existing tx tests we had for this issue and created a couple new ones, but I still haven't been able to reproduce this yet for non tx.  Is there any way you could get logs for when this happens?  I can keep adding some more to see if I can find it, but I think the logs here would help the most.

Thanks!
Comment 22 JBoss JIRA Server 2013-12-04 11:57:49 EST
Radim Vansa <rvansa@redhat.com> made a comment on jira ISPN-3780

{code}
edg-perf03:07:00:02,044 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (SharedLogChecker-6) Replication task sending ClusteredGetCommand{key=key_0000000000003154, flags=null} to addresses [edg-perf02-17030, edg-perf01-24254] with response mode GET_FIRST
edg-perf03:07:00:02,045 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (SharedLogChecker-6) Response(s) to ClusteredGetCommand{key=key_0000000000003154, flags=null} is {edg-perf02-17030=SuccessfulResponse{responseValue=null} }
...
edg-perf02: 07:00:02,445 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-36,edg-perf02-17030) Attempting to execute command: SingleRpcCommand{cacheName='testCache', command=PutKeyValueCommand{key=key_0000000000003154, value=[ #1: 39~552, ], flags=null, putIfAbsent=true, metadata=EmbeddedMetadata{version=null}, successful=true, ignorePreviousValue=false}} [sender=edg-perf04-38684]
...
edg-perf02:07:00:04,011 TRACE [org.infinispan.commands.remote.BaseRpcInvokingCommand] (remote-thread-22) Invoking command PutKeyValueCommand{key=key_0000000000003154, value=[ #1: 39~552, ], flags=null, putIfAbsent=true, metadata=EmbeddedMetadata{version=null}, successful=true, ignorePreviousValue=false}, with originLocal flag set to false
...
edg-perf02:07:00:04,013 TRACE [org.infinispan.distribution.L1ManagerImpl] (remote-thread-22) Invalidating keys [key_0000000000003154] on nodes [edg-perf03-38968]. Use multicast? true
...
edg-perf03:07:00:04,014 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-79,edg-perf03-38968) Attempting to execute command: SingleRpcCommand{cacheName='testCache', command=InvalidateL1Command{num keys=1, forRehash=false, origin=edg-perf04-38684}} [sender=edg-perf02-17030]
...
edg-perf03:07:00:04,014 TRACE [org.infinispan.commands.remote.BaseRpcInvokingCommand] (remote-thread-27) Invoking command InvalidateL1Command{num keys=1, forRehash=false, origin=edg-perf04-38684}, with originLocal flag set to false
...
edg-perf03:07:00:04,015 TRACE [org.infinispan.container.EntryFactoryImpl] (remote-thread-27) Retrieved from container null (isL1Enabled=true, isLocal=true)
...
edg-perf03:07:00:04,015 TRACE [org.infinispan.commands.write.InvalidateL1Command] (remote-thread-27) Preparing to invalidate keys [key_0000000000003154]
edg-perf03:07:00:04,015 TRACE [org.infinispan.statetransfer.StateConsumerImpl] (remote-thread-27) Key key_0000000000003154 modified by a regular tx, state transfer will ignore it
edg-perf03:07:00:04,015 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (remote-thread-27) Entry for key key_0000000000003154 is null : not calling commitUpdate
...
edg-perf02:07:00:04,046 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (transport-thread-15) edg-perf02-17030 invoking StateResponseCommand{cache=testCache, origin=edg-perf02-17030, topologyId=12} to recipient list [edg-perf03-38968] with options RpcOptions{timeout=600000, unit=MILLISECONDS, fifoOrder=true, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS, skipReplicationQueue=false}
...
edg-perf03:07:00:04,082 TRACE [org.infinispan.remoting.InboundInvocationHandlerImpl] (remote-thread-33) Calling perform() on StateResponseCommand{cache=testCache, origin=edg-perf02-17030, topologyId=12}
...
edg-perf03:07:00:04,817 TRACE [org.infinispan.interceptors.CallInterceptor] (remote-thread-33) Executing command: PutKeyValueCommand{key=key_0000000000003154, value=[ #1: 39~552, ], 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, metadata=EmbeddedMetadata{version=null}, successful=true, ignorePreviousValue=false}.
edg-perf03:07:00:04,817 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (remote-thread-33) State transfer will not write key/value key_0000000000003154/[ #1: 39~552, ] because it was already updated by somebody else
{code}
Comment 23 JBoss JIRA Server 2013-12-04 15:00:05 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3780

Radim, do you happen to have a link to the entire trace?

In the cases I am finding the put is retried properly with the new topology and everything is fine.  I  have tried a few slight variations of the following case you originally stated.

{quote}
1. D executes PUT -> sends command to A
2. A executes the PUT, sends invalidation to C
3. ST from A to C begins
4. C receives InvalidateL1 and puts this key into updateKeys
5. C receives state but ignores the updated key
{quote}

In this case the put on A should end up throwing a OutdatedTopologyException after it tries to commit which would cause a retry to occur from node D with the updated topology which would put the correct value into C.

I wonder though if the L1 invalidation came from the L1LastChanceInterceptor though as that would not cause a retry.  It could be that the commit completes, then the topology is updated and then last chance fires, which is why it would have the correct topology id on the command.  I will try to get that test up and running.  The complete log would help show me if that matches your case or not.

Either way I wouldn't expect the value to be in L1 still.  I would expect the value to be removed from the invalidation, can you confirm if that is true?  Looking at the log it looks like it was already null "Entry for key key_0000000000003154 is null"
Comment 24 JBoss JIRA Server 2013-12-05 03:47:39 EST
Radim Vansa <rvansa@redhat.com> made a comment on jira ISPN-3780

Seems that this time the logs are not that big (191 MB) https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/jdg-radargun-resilience-dist-no-tx-l1/5/artifact/report/stdout.zip
Comment 25 JBoss JIRA Server 2013-12-05 04:02:32 EST
Radim Vansa <rvansa@redhat.com> made a comment on jira ISPN-3780

The topology change is started on A only after the invalidation has been sent to C.

By the time the entry was requested from C on A, no value was yet present on A, but C was registered as requestor. Registering registor when the value is null is probably redundant, but the case we are inspecting would happen if the entry already contained some old value.
Comment 26 JBoss JIRA Server 2013-12-05 16:05:21 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3780

{quote}The topology change is started on A only after the invalidation has been sent to C.{quote}

Yeah it appears that the new topology was only installed on C before the invalidation arrived and A doesn't get the new topology until after the put command is completed.

Now normally I would think the topology check in the entryCommit in EntryWrappingInterceptor would then throw an error.  However the topologyId is always a -1 for InvalidateL1Commands.  It is never set in StateTransferInterceptor and the setting of the topology doesn't work in RpcMangerImpl because the command is wrapped in a CacheRpcCommand which doesn't implement TopologyAffectedCommand.  I think the easiest fix is to move the if check higher up in RpcManagerImpl, but I will get a test going first to confirm this.  Also I will try to fix the issue I found with the LastChanceInterceptor which this may also fix.
Comment 27 JBoss JIRA Server 2013-12-05 16:06:03 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3780

{quote}The topology change is started on A only after the invalidation has been sent to C.{quote}

Yeah it appears that the new topology was only installed on C before the invalidation arrived and A doesn't get the new topology until after the put command is completed which is why it wasn't retried.

Now normally I would think the topology check in the entryCommit in EntryWrappingInterceptor would then throw an error since A topolyg is 1 behind, however the topologyId is always -1 for InvalidateL1Commands.  It is never set in StateTransferInterceptor and the setting of the topology doesn't work in RpcMangerImpl because the command is wrapped in a CacheRpcCommand which doesn't implement TopologyAffectedCommand.  I think the easiest fix is to move the if check higher up in RpcManagerImpl, but I will get a test going first to confirm this.  Also I will try to fix the issue I found with the LastChanceInterceptor which this may also fix.
Comment 28 JBoss JIRA Server 2013-12-06 11:55:41 EST
William Burns <wburns@redhat.com> made a comment on jira ISPN-3780

Trying to write a test for this wasn't quite what I thought at first.  I found this issue is only reproducible when an owner sends a L1 invalidation but the node doesn't actually have the L1 value present (as you mentioned).  In this case the EntryWrappingInterceptor is guaranteed to add to the updatedKeys as long as a ST is in progress.

Note You need to log in before you can comment on or make changes to this bug.