[infinispan-issues] [JBoss JIRA] (ISPN-4424) ReplaceIfUnmodified is broken under concurrent execution

Mon Jun 23 04:03:25 EDT 2014

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

Galder Zamarreño edited comment on ISPN-4424 at 6/23/14 4:03 AM:
-----------------------------------------------------------------

{code}
17109 TRACE [org.infinispan.client.hotrod.impl.protocol.Codec20] (pool-7-thread-2:) Wrote header for message 6561. Operation code: 0x11. Flags: 0x0
17111 TRACE [org.infinispan.server.hotrod.HotRodDecoder] (HotRodServerWorker-5-2:) Decoded header HotRodHeader{op=GetWithVersionRequest, version=20, messageId=6561, cacheName=, flag=0, clientIntelligence=3, topologyId=2}
17113 TRACE [org.infinispan.server.hotrod.HotRodDecoder] (HotRodServerWorker-5-2:) Write response GetWithVersionResponse{version=20, messageId=6561, operation=GetWithVersionResponse, status=Success, data=[B0x034b000001cf,h=3e25a7d7], dataVersion=281479271678483}
{code}
^ A client thread requests an entry's versioned data. This returns 463 (...000001cf) and version 281479271678483.

With the version and previous value in place, client calls replaceWithVersion(key, 464, 281479271678483), with the intention to update the entry to 464 value if the version is still 281479271678483.

Server side, we see the server requesting the cached entry and finding 463 as value and 281479271678483 version:

{code}17126 TRACE [org.infinispan.interceptors.CallInterceptor] (HotRodServerWorker-3-1:___defaultcache) Executing command: GetKeyValueCommand {key=[B0x033e07484f47454b..[10], flags=[SKIP_LISTENER_NOTIFICATION]}
2014-06-20 16:16:56,815 17126 TRACE [org.infinispan.commands.read.GetKeyValueCommand] (HotRodServerWorker-3-1:___defaultcache) Found entry MetadataImmortalCacheEntry{key=[B0x033e07484f47454b..[10], value=[B0x034b000001cf, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678483}}}{code}

In parallel, an entry update happens:

{code}17126 TRACE [org.infinispan.container.DefaultDataContainer] (remote-thread-NodeA-p3-t1:___defaultcache) Creating new ICE for writing. Existing=MetadataImmortalCacheEntry{key=[B0x033e07484f47454b..[10], value=[B0x034b000001cf, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678483}}}, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678485}}, new value=[B at 7b55e60d
17126 TRACE [org.infinispan.container.DefaultDataContainer] (remote-thread-NodeA-p3-t1:___defaultcache) Store MetadataImmortalCacheEntry{key=[B0x033e07484f47454b..[10], value=[B0x034b000001d0, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678485}}} in container{code}

Entry is now updated to value 464 (...000001d0) and version 281479271678485.

However, the server ends up calling replace with the old value being 464 but it somehow passed the if condition where the version should be 281479271678483 (new version to be applied shown in the logs):

{code}17126 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (HotRodServerWorker-3-1:___defaultcache) Invoked with command ReplaceCommand{key=[B0x033e07484f47454b..[10], oldValue=[B0x034b000001d0, newValue=[B0x034b000001d0, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678486}}, flags=null, successful=true, valueMatcher=MATCH_EXPECTED} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext at 2feeb01e]{code}

One way to solve this issue would be to add synchronisation but that would hurt performance badly. The real problem though is the fact that when the server calls getCacheEntry(), this returns a mutable cache entry. This entry cannot be directly mutated by the client but can indeed mutated by the server, and in fact it does so when it calls InternalCacheEntryFactory.update() method. One way to solve this might be getCacheEntry to return a true immutable cache entry, whose call reordering cannot lead to race conditions such as this.

was (Author: galder.zamarreno):
{code}
17109 TRACE [org.infinispan.client.hotrod.impl.protocol.Codec20] (pool-7-thread-2:) Wrote header for message 6561. Operation code: 0x11. Flags: 0x0
17111 TRACE [org.infinispan.server.hotrod.HotRodDecoder] (HotRodServerWorker-5-2:) Decoded header HotRodHeader{op=GetWithVersionRequest, version=20, messageId=6561, cacheName=, flag=0, clientIntelligence=3, topologyId=2}
17113 TRACE [org.infinispan.server.hotrod.HotRodDecoder] (HotRodServerWorker-5-2:) Write response GetWithVersionResponse{version=20, messageId=6561, operation=GetWithVersionResponse, status=Success, data=[B0x034b000001cf,h=3e25a7d7], dataVersion=281479271678483}
{code}
^ A client thread requests an entry's versioned data. This returns 463 (...000001cf) and version 281479271678483.

With the version and previous value in place, client calls replaceWithVersion(key, 464, 281479271678483), with the intention to update the entry to 464 value if the version is still 281479271678483.

Server side, we see the server requesting the cached entry and finding 463 as value and 281479271678483 version:

{code}17126 TRACE [org.infinispan.interceptors.CallInterceptor] (HotRodServerWorker-3-1:___defaultcache) Executing command: GetKeyValueCommand {key=[B0x033e07484f47454b..[10], flags=[SKIP_LISTENER_NOTIFICATION]}
2014-06-20 16:16:56,815 17126 TRACE [org.infinispan.commands.read.GetKeyValueCommand] (HotRodServerWorker-3-1:___defaultcache) Found entry MetadataImmortalCacheEntry{key=[B0x033e07484f47454b..[10], value=[B0x034b000001cf, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678483}}}{code}

In parallel, an entry update happens:

{code}17126 TRACE [org.infinispan.container.DefaultDataContainer] (remote-thread-NodeA-p3-t1:___defaultcache) Creating new ICE for writing. Existing=MetadataImmortalCacheEntry{key=[B0x033e07484f47454b..[10], value=[B0x034b000001cf, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678483}}}, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678485}}, new value=[B at 7b55e60d
17126 TRACE [org.infinispan.container.DefaultDataContainer] (remote-thread-NodeA-p3-t1:___defaultcache) Store MetadataImmortalCacheEntry{key=[B0x033e07484f47454b..[10], value=[B0x034b000001d0, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678485}}} in container{code}

Entry is now updated to value 464 (...000001d0) and version 281479271678485.

However, the server ends up calling replace with the old value being 464 but it somehow passed the if condition where the version should be 281479271678483 (new version to be applied shown in the logs):

{code}2014-06-20 16:16:56,815 17126 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (HotRodServerWorker-3-1:___defaultcache) Invoked with command ReplaceCommand{key=[B0x033e07484f47454b..[10], oldValue=[B0x034b000001d0, newValue=[B0x034b000001d0, metadata=EmbeddedMetadata{version=NumericVersion{version=281479271678486}}, flags=null, successful=true, valueMatcher=MATCH_EXPECTED} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext at 2feeb01e]{code}

One way to solve this issue would be to add synchronisation but that would hurt performance badly. The real problem though is the fact that when the server calls getCacheEntry(), this returns a mutable cache entry. This entry cannot be directly mutated by the client but can indeed mutated by the server, and in fact it does so when it calls InternalCacheEntryFactory.update() method. One way to solve this might be getCacheEntry to return a true immutable cache entry, whose call reordering cannot lead to race conditions such as this.

> ReplaceIfUnmodified is broken under concurrent execution
> --------------------------------------------------------
>
>                 Key: ISPN-4424
>                 URL: https://issues.jboss.org/browse/ISPN-4424
>             Project: Infinispan
>          Issue Type: Bug
>      Security Level: Public(Everyone can see) 
>          Components: Remote Protocols
>    Affects Versions: 6.0.2.Final, 7.0.0.Alpha4
>            Reporter: Galder Zamarreño
>            Assignee: Galder Zamarreño
>             Fix For: 7.0.0.Final
>
>
> Versioned update with a multi threaded Hot Rod client results in inconsistency.  Some replaceWithVersion return true ignoring a version update executed in another thread. Here's a log excerpt of a concurrency stress test:
> ```
> 2014-06-20 16:16:56,798 INFO  [PutFromNull] (pool-7-thread-10) count=462,prev=462,new=463
> 2014-06-20 16:16:56,820 INFO  [PutFromNull] (pool-7-thread-9) count=463,prev=463,new=464
> 2014-06-20 16:16:56,831 INFO  [PutFromNull] (pool-7-thread-2) count=464,prev=463,new=464
> 2014-06-20 16:16:56,845 INFO  [PutFromNull] (pool-7-thread-9) count=465,prev=464,new=465
> ```
> Here you see two threads applying the same replacement, from 463 to 464.
> The issue appears a result of a race condition in Hot Rod server's protocol decoder. When replaceIfUmodified is received, the cache entry is retrieved to verify whether the version in the server and the version sent in the command match. However, the cache entry retrieved is mutable, and the value could change midway through this operation as a result of another thread updating the value. Please find below some log snippets showing this.

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