Server and client get out of sync after multimap get with metadata operation ---------------------------------------------------------------------------- Key: ISPN-11630 URL: https://issues.redhat.com/browse/ISPN-11630 Project: Infinispan Issue Type: Bug Components: Hot Rod, Multimap Affects Versions: 11.0.0.Dev04, 10.1.6.Final Reporter: Dan Berindei Assignee: Dan Berindei Priority: Major Labels: testsuite_stability Fix For: 11.0.0.CR1 The Hot Rod server includes metadata information with the {{GET_MULTIMAP_WITH_METADATA_REQUEST}} response even if the status is {{KEY_DOES_NOT_EXIST_STATUS}}, but the client does not expect any other information after the header, so it tries to read the metadata information as the start of a new response and fails: {noformat} 08:50:15,468 TRACE (testng-Test:[]) [Codec] [] Wrote header for messageId=47333 to PooledUnsafeDirectByteBuf(ridx: 0, widx: 14, cap: 19). Operation code: 0x69(GET_MULTIMAP_WITH_METADATA_REQUEST). Flags: 0x1. Topology id: -1 08:50:15,468 TRACE (HotRod-Test-ServerIO-2061-1:[]) [Encoder2x] Write topology response header with no change 08:50:15,468 TRACE (Test-Client-Async-454-1:[]) [Codec] Received response for messageId=47333 08:50:15,468 TRACE (Test-Client-Async-454-1:[]) [HeaderDecoder] Decoding header for GetKeyWithMetadataMultimapOperation{(default), key=[B0x4A016B, flags=1, connection=127.0.0.1/127.0.0.1:38741} on [id: 0x36567c12, L:/127.0.0.1:36216 - R:127.0.0.1/127.0.0.1:38741] 08:50:15,468 TRACE (Test-Client-Async-454-1:[]) [HeaderDecoder] Decoding payload for GetKeyWithMetadataMultimapOperation{(default), key=[B0x4A016B, flags=1, connection=127.0.0.1/127.0.0.1:38741} on [id: 0x36567c12, L:/127.0.0.1:36216 - R:127.0.0.1/127.0.0.1:38741] 08:50:15,468 TRACE (Test-Client-Async-454-1:[]) [Codec] Socket dump: A1E5F102\j020003FFFFFFFFFFFFFFFF00 08:50:15,468 TRACE (Test-Client-Async-454-1:[]) [RetryOnFailureOperation] (1) GetKeyWithMetadataMultimapOperation{(default), key=[B0x4A016B, flags=1, connection=127.0.0.1/127.0.0.1:38741} Requesting [id: 0x36567c12, L:/127.0.0.1:36216 - R:127.0.0.1/127.0.0.1:38741] close due to exception org.infinispan.client.hotrod.exceptions.InvalidResponseException: ISPN004003: Invalid magic number. Expected 0xa1 and received 0x3 at org.infinispan.client.hotrod.impl.protocol.Codec20.readMessageId(Codec20.java:147) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.HeaderDecoder.decode(HeaderDecoder.java:86) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.HintedReplayingDecoder.callDecode(HintedReplayingDecoder.java:94) ~[classes/:?] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[netty-codec-4.1.45.Final.jar:4.1.45.Final] {noformat} Because the client can't parse the remaining buffer as a response, it tries to close the connection, but sometimes even closing throws an {{AssertionError}}, causing random failures in test {{RemoteMultimapCacheAPITest.testGetWithMetadataNotExist}}: {noformat} 08:50:15,469 TRACE (Test-Client-Async-454-1:[]) [ChannelRecord] Closing channel [id: 0x36567c12, L:/127.0.0.1:36216 ! R:127.0.0.1/127.0.0.1:38741] 08:50:15,469 TRACE (testng-Test:[]) [ChannelFactory] Releasing channel [id: 0x36567c12, L:/127.0.0.1:36216 ! R:127.0.0.1/127.0.0.1:38741] 08:50:15,469 TRACE (testng-Test:[]) [ChannelPool] Requesting [id: 0x36567c12, L:/127.0.0.1:36216 ! R:127.0.0.1/127.0.0.1:38741] close due to exception java.lang.AssertionError: Error releasing [id: 0x36567c12, L:/127.0.0.1:36216 ! R:127.0.0.1/127.0.0.1:38741] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.release(ChannelPool.java:168) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelRecord.release(ChannelRecord.java:77) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.releaseChannel(ChannelFactory.java:312) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.HotRodOperation.releaseChannel(HotRodOperation.java:103) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.invoke(RetryOnFailureOperation.java:80) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.activateChannel(ChannelPool.java:215) [classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.acquire(ChannelPool.java:84) [classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:262) [classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:300) [classes/:?] at org.infinispan.client.hotrod.impl.operations.AbstractKeyOperation.fetchChannelAndInvoke(AbstractKeyOperation.java:41) [classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.execute(RetryOnFailureOperation.java:62) [classes/:?] at org.infinispan.client.hotrod.impl.multimap.RemoteMultimapCacheImpl.getWithMetadata(RemoteMultimapCacheImpl.java:106) [classes/:?] at org.infinispan.client.hotrod.RemoteMultimapCacheAPITest.testGetWithMetadataNotExist(RemoteMultimapCacheAPITest.java:59) [test-classes/:?] 08:50:15,479 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.client.hotrod.RemoteMultimapCacheAPITest.testGetWithMetadataNotExist java.lang.AssertionError: Error releasing [id: 0x36567c12, L:/127.0.0.1:36216 ! R:127.0.0.1/127.0.0.1:38741] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.release(ChannelPool.java:168) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelRecord.release(ChannelRecord.java:77) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.releaseChannel(ChannelFactory.java:312) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.HotRodOperation.releaseChannel(HotRodOperation.java:103) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.invoke(RetryOnFailureOperation.java:80) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.activateChannel(ChannelPool.java:215) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.acquire(ChannelPool.java:84) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:262) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:300) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.AbstractKeyOperation.fetchChannelAndInvoke(AbstractKeyOperation.java:41) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.execute(RetryOnFailureOperation.java:62) ~[classes/:?] at org.infinispan.client.hotrod.impl.multimap.RemoteMultimapCacheImpl.getWithMetadata(RemoteMultimapCacheImpl.java:106) ~[classes/:?] at org.infinispan.client.hotrod.RemoteMultimapCacheAPITest.testGetWithMetadataNotExist(RemoteMultimapCacheAPITest.java:59) ~[test-classes/:?] {noformat}