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.
William Burns <wburns> updated the status of jira ISPN-3633 to Coding In Progress
William Burns <wburns> 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.
William Burns <wburns> 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.
Radim Vansa <rvansa> 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?
William Burns <wburns> updated the status of jira ISPN-3633 to Open
William Burns <wburns> made a comment on jira ISPN-3633 In my test the command was forwarded to A, but I need to dig further still.
William Burns <wburns> 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.
William Burns <wburns> 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.
William Burns <wburns> 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.
Radim Vansa <rvansa> updated the status of jira ISPN-3633 to Reopened
Radim Vansa <rvansa> 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
William Burns <wburns> 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?
William Burns <wburns> updated the status of jira ISPN-3633 to Resolved
William Burns <wburns> 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.
William Burns <wburns> updated the status of jira ISPN-3780 to Coding In Progress
Radim Vansa <rvansa> 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)?
William Burns <wburns> 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.
William Burns <wburns> 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!
Radim Vansa <rvansa> 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}
William Burns <wburns> 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"
Radim Vansa <rvansa> 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
Radim Vansa <rvansa> 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.
William Burns <wburns> 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.
William Burns <wburns> 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.
William Burns <wburns> 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.