Reading entry via HotRod fails in compatibility mode for non-local entry if stored via Embedded cache ------------------------------------------------------------------------------------------------------ Key: ISPN-3406 URL: https://issues.jboss.org/browse/ISPN-3406 Project: Infinispan Issue Type: Bug Affects Versions: 6.0.0.Alpha2 Reporter: Martin Gencur Assignee: Mircea Markus In DIST mode where numOwners<numNodes, reading an entry via HotRod fails if it was previously stored into an embedded cache and the entry is not local to the HotRod server endpoint. The resulting value is a byte array instead of expected type: expected:<v1> but was:<[B@41c001f5> The following test case fails in DIST mode and numOwners=1 {code:java} public void testEmbeddedPutRestHotRodGet() throws Exception { final String key = "2"; // 1. Put with Embedded assertEquals(null, cacheFactory2.getEmbeddedCache().put(key, "v1")); // 2. Get with Hot Rod assertEquals("v1", cacheFactory1.getHotRodCache().get(key)); //^^^^fails here // 3. Get with REST HttpMethod get = new GetMethod(cacheFactory2.getRestUrl() + "/" + key); cacheFactory2.getRestClient().executeMethod(get); assertEquals(HttpServletResponse.SC_OK, get.getStatusCode()); assertEquals("v1", get.getResponseBodyAsString()); } {code} The relevant part of trace log is here: {code} 2013-08-13 10:42:35,299 INFO (testng-DistEmbeddedRestHotRodTest) [org.infinispan.test.fwk.UnitTestTestNGListener] Starting test testEmbeddedPutRestHotRodGet(org.infinispan.it.compatibility.DistEmbeddedRestHotRodTest) 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=2, value=v1, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@4677c9e2] 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command PutKeyValueCommand{key=2, value=v1, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true} 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor] Are (DistEmbeddedRestHotRodTest-NodeB-63949) we the lock owners for key '2'? true 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to lock 2 with acquisition timeout of 10000 millis 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.util.concurrent.locks.containers.ReentrantPerEntryLockContainer] Creating and acquiring new lock instance for key 2 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.util.concurrent.locks.LockManagerImpl] Successfully acquired lock 2! 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.EntryWrappingInterceptor] Wrapping entry '2'? true 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.container.EntryFactoryImpl] Exists in context? null 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.container.EntryFactoryImpl] Retrieved from container null 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.container.EntryFactoryImpl] Creating new entry. 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.container.EntryFactoryImpl] Wrap 2 for put. Entry=ReadCommittedEntry(62673892){key=2, value=null, oldValue=null, isCreated=true, isChanged=false, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}} 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.distribution.NonTxDistributionInterceptor] Not doing a remote get for key 2 since entry is not affected by rehash or is already in data container. We are DistEmbeddedRestHotRodTest-NodeB-63949, owners are [DistEmbeddedRestHotRodTest-NodeB-63949] 2013-08-13 10:42:35,301 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.CallInterceptor] Executing command: PutKeyValueCommand{key=2, value=v1, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}. 2013-08-13 10:42:35,302 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] I'm the primary owner, sending the command to all ([DistEmbeddedRestHotRodTest-NodeB-63949]) the recipients in order to be applied. 2013-08-13 10:42:35,302 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.EntryWrappingInterceptor] About to commit entry ReadCommittedEntry(62673892){key=2, value=v1, oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}} 2013-08-13 10:42:35,302 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.container.entries.ReadCommittedEntry] Updating entry (key=2 removed=false valid=true changed=true created=true loaded=false value=v1 metadata=EmbeddedMetadata{version=null}) 2013-08-13 10:42:35,302 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.interceptors.EntryWrappingInterceptor] The return value is null 2013-08-13 10:42:35,302 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to unlock 2 2013-08-13 10:42:35,302 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.util.concurrent.locks.containers.ReentrantPerEntryLockContainer] Unlocking lock instance for key 2 2013-08-13 10:42:35,302 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.statetransfer.StateTransferManagerImpl] CommandTopologyId=2, localTopologyId=2 2013-08-13 10:42:35,304 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop marshaller 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransportFactory] Using consistent hash for determining the server: /127.0.0.1:15233 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TransportObjectFactory] Fetching from pool: TcpTransport{socket=Socket[addr=localhost/127.0.0.1,port=15233,localport=36161], serverAddress=localhost/127.0.0.1:15233, id =1} 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransportFactory] For server /127.0.0.1:15233: active = 1; idle = 0 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 160 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 12 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 3 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote 0 bytes 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 3 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote byte 0 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.protocol.Codec12] Wrote header for message 5. Operation code: 0x03. Flags: 0x0 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Wrote 4 bytes 2013-08-13 10:42:35,306 TRACE (testng-DistEmbeddedRestHotRodTest) [org.infinispan.client.hotrod.impl.transport.tcp.TcpTransport] Flushed socket: Socket[addr=localhost/127.0.0.1,port=15233,localport=36161] 2013-08-13 10:42:35,306 TRACE (HotRodServerWorker-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @62a7e5af 2013-08-13 10:42:35,307 TRACE (HotRodServerWorker-2) [org.infinispan.server.hotrod.Decoder10$] Operation code: 3 has been matched to GetRequest 2013-08-13 10:42:35,307 TRACE (HotRodServerWorker-2) [org.infinispan.server.hotrod.HotRodDecoder] Decoded header HotRodHeader{op=GetRequest, version=12, messageId=5, cacheName=, flag=0, clientIntelligence=3, topologyId=0} 2013-08-13 10:42:35,307 TRACE (HotRodServerWorker-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @62a7e5af 2013-08-13 10:42:35,308 TRACE (HotRodServerWorker-2) [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command GetKeyValueCommand {key=[B0x033e0132..(4), flags=[OPERATION_HOTROD]} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@4bd56a3a] 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Start unmarshaller after retrieving marshaller from thread local 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop unmarshaller 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command GetKeyValueCommand {key=2, flags=[OPERATION_HOTROD]} 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.container.EntryFactoryImpl] Exists in context? null 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.container.EntryFactoryImpl] Retrieved from container null 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.container.EntryFactoryImpl] Wrap 2 for read. Entry=null 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.interceptors.CallInterceptor] Executing command: GetKeyValueCommand {key=2, flags=[OPERATION_HOTROD]}. 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.commands.read.GetKeyValueCommand] Entry not found 2013-08-13 10:42:35,309 TRACE (HotRodServerWorker-2) [org.infinispan.interceptors.distribution.NonTxDistributionInterceptor] Doing a remote get for key 2 2013-08-13 10:42:35,311 TRACE (HotRodServerWorker-2) [org.infinispan.remoting.rpc.RpcManagerImpl] DistEmbeddedRestHotRodTest-NodeA-65464 invoking ClusteredGetCommand{key=2, flags=[OPERATION_HOTROD]} to recipient list [DistEmbeddedRestHotRodTest-NodeB-63949] with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=org.infinispan.remoting.responses.ClusteredGetResponseValidityFilter@73d884a6, responseMode=WAIT_FOR_VALID_RESPONSE, skipReplicationQueue=false} 2013-08-13 10:42:35,311 TRACE (HotRodServerWorker-2) [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=[DistEmbeddedRestHotRodTest-NodeB-63949], command=ClusteredGetCommand{key=2, flags=[OPERATION_HOTROD]}, mode=WAIT_FOR_VALID_RESPONSE, timeout=15000 2013-08-13 10:42:35,311 TRACE (HotRodServerWorker-2) [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] Replication task sending ClusteredGetCommand{key=2, flags=[OPERATION_HOTROD]} to addresses [DistEmbeddedRestHotRodTest-NodeB-63949] with response mode GET_FIRST 2013-08-13 10:42:35,311 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.MarshallableTypeHints] Cache a buffer size predictor for 'org.infinispan.commands.remote.ClusteredGetCommand' assuming its serializability is unknown 2013-08-13 10:42:35,311 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.AdaptiveBufferSizePredictor] Next predicted buffer size for object type 'org.infinispan.commands.remote.ClusteredGetCommand' will be 512 2013-08-13 10:42:35,311 TRACE (HotRodServerWorker-2) [org.infinispan.marshall.core.VersionAwareMarshaller] Wrote version 510 2013-08-13 10:42:35,312 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.MarshallableTypeHints] Cache a buffer size predictor for 'org.infinispan.commands.remote.ClusteredGetCommand' assuming its serializability is unknown 2013-08-13 10:42:35,312 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.AdaptiveBufferSizePredictor] Next predicted buffer size for object type 'org.infinispan.commands.remote.ClusteredGetCommand' will be 512 2013-08-13 10:42:35,312 TRACE (HotRodServerWorker-2) [org.infinispan.marshall.core.VersionAwareMarshaller] Wrote version 510 2013-08-13 10:42:35,312 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop marshaller 2013-08-13 10:42:35,312 TRACE (HotRodServerWorker-2) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop marshaller 2013-08-13 10:42:35,313 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Start unmarshaller after retrieving marshaller from thread local 2013-08-13 10:42:35,313 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.marshall.core.VersionAwareMarshaller] Read version 510 2013-08-13 10:42:35,313 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Start unmarshaller after retrieving marshaller from factory 2013-08-13 10:42:35,313 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.marshall.core.VersionAwareMarshaller] Read version 510 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop unmarshaller 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop unmarshaller 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] Attempting to execute command: ClusteredGetCommand{key=2, flags=[OPERATION_HOTROD]} [sender=DistEmbeddedRestHotRodTest-NodeA-65464] 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.remoting.InboundInvocationHandlerImpl] Calling perform() on ClusteredGetCommand{key=2, flags=[OPERATION_HOTROD]} 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command GetKeyValueCommand {key=2, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP, OPERATION_HOTROD]} and InvocationContext [org.infinispan.context.impl.NonTxInvocationContext@6d24bbbe] 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command GetKeyValueCommand {key=2, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP, OPERATION_HOTROD]} 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.container.EntryFactoryImpl] Exists in context? null 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.container.EntryFactoryImpl] Retrieved from container ImmortalCacheEntry{key=2, value=v1} 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.container.EntryFactoryImpl] Wrap 2 for read. Entry=ImmortalCacheEntry{key=2, value=v1} 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.interceptors.CallInterceptor] Executing command: GetKeyValueCommand {key=2, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP, OPERATION_HOTROD]}. 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commands.read.GetKeyValueCommand] Found entry ImmortalCacheEntry{key=2, value=v1} 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.interceptors.EntryWrappingInterceptor] Entry for key 2 is not changed(ImmortalCacheEntry{key=2, value=v1}): not calling commitUpdate 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.MarshallableTypeHints] Cache a buffer size predictor for 'java.lang.String' assuming its serializability is unknown 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.AdaptiveBufferSizePredictor] Next predicted buffer size for object type 'java.lang.String' will be 512 2013-08-13 10:42:35,314 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop marshaller 2013-08-13 10:42:35,315 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.remoting.InboundInvocationHandlerImpl] About to send back response SuccessfulResponse{responseValue=ImmortalCacheValue {value=[B@714d0d01}} for command ClusteredGetCommand{key=2, flags=[OPERATION_HOTROD]} 2013-08-13 10:42:35,315 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.MarshallableTypeHints] Cache a buffer size predictor for 'org.infinispan.remoting.responses.SuccessfulResponse' assuming its serializability is unknown 2013-08-13 10:42:35,315 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.AdaptiveBufferSizePredictor] Next predicted buffer size for object type 'org.infinispan.remoting.responses.SuccessfulResponse' will be 512 2013-08-13 10:42:35,315 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.marshall.core.VersionAwareMarshaller] Wrote version 510 2013-08-13 10:42:35,315 TRACE (OOB-4,DistEmbeddedRestHotRodTest-NodeB-63949) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop marshaller 2013-08-13 10:42:35,315 TRACE (OOB-3,DistEmbeddedRestHotRodTest-NodeA-65464) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Start unmarshaller after retrieving marshaller from thread local 2013-08-13 10:42:35,315 TRACE (OOB-3,DistEmbeddedRestHotRodTest-NodeA-65464) [org.infinispan.marshall.core.VersionAwareMarshaller] Read version 510 2013-08-13 10:42:35,315 TRACE (OOB-3,DistEmbeddedRestHotRodTest-NodeA-65464) [org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller] Stop unmarshaller 2013-08-13 10:42:35,315 TRACE (HotRodServerWorker-2) [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] Received response: SuccessfulResponse{responseValue=ImmortalCacheValue {value=[B@64b7716c}} from DistEmbeddedRestHotRodTest-NodeB-63949 2013-08-13 10:42:35,316 TRACE (HotRodServerWorker-2) [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] Responses: [sender=DistEmbeddedRestHotRodTest-NodeB-63949, retval=SuccessfulResponse{responseValue=ImmortalCacheValue {value=[B@64b7716c}} , received=true, suspected=false] {code} I'll provide the test case.