Bug 1134184 - Hot Rod client receives ArrayIndexOutOfBoundsException and InvalidResponseException when topology changes
Summary: Hot Rod client receives ArrayIndexOutOfBoundsException and InvalidResponseExc...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: JBoss Data Grid 6
Classification: JBoss
Component: Infinispan
Version: 6.3.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ER2
: 6.3.1
Assignee: Tristan Tarrant
QA Contact: Martin Gencur
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-08-27 05:05 UTC by Osamu Nagano
Modified: 2019-10-10 09:23 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Previously in JBoss Data Grid, the new segment-based topology information sent to Hot Rod clients would incorrectly compute the segments. As a result, segment entries were incorrectly added for nodes that were not present. This presented a runtime error when the distributed cache view changes were processed by the Hot Rod client. This is fixed in JBoss Data Grid 6.3.1 so that servers that are not part of the topology are filtered out from the segment information sent to Hot Rod clients. As a result, the Hot Rod clients correctly process topology views.
Clone Of:
Environment:
Last Closed: 2015-01-26 14:03:58 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)
test client (3.62 KB, application/octet-stream)
2014-08-27 05:05 UTC, Osamu Nagano 		no flags Details
Log from the test client using HotRod protocol 1.3 (6.64 KB, text/plain)
2014-08-27 12:52 UTC, Alan Field 		no flags Details
Log from the test client using HotRod protocol 2.0 (46.62 KB, text/plain)
2014-08-27 12:53 UTC, Alan Field 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker ISPN-4674 0 Critical Closed Hot Rod client receives ArrayIndexOutOfBoundsException and InvalidResponseException when topology changes 2020-02-20 05:40:04 UTC

Description Osamu Nagano 2014-08-27 05:05:21 UTC 
Created attachment 931249 [details]
test client

Description of problem:
A Hot Rod client, which is keep putting a key-value pairs, receives "java.lang.ArrayIndexOutOfBoundsException: 2" and "org.infinispan.client.hotrod.exceptions.InvalidResponseException:: Invalid magic number. Expected 0xa1 and received 0x0" when a second node joins to the cluster.  The array index should be 1, which is the same as the cluster size.  And the stream seems to keep a garbage, resulting InvalidResponseException.


How reproducible:
Always using default 2 node cluster and attached test client.


Steps to Reproduce:
0. Build the attached client as follows.
~~~
unzip keep-putting.zip
cd keep-putting
mvn clean compile dependency:copy-dependencies
~~~
1. Start the first node using the default clustered.xml configuration.
2. Run the test client as follows.  It just keeps putting a new key-value pair.
~~~
java -cp 'target/dependency/*:target/classes' \
     -Djava.util.logging.manager=org.jboss.logmanager.LogManager \
     -Dlogging.configuration=file:logging.properties \
     com.example.Main localhost:11222 default
~~~
3. Start the second node.  The client will report the stack traces.


Actual results:
Just after a new server node joined, a client reports the following stack traces.  The second one is repeated as the client trying to put.
~~~
13:34:19,394 WARNING [com.example.Main] (main) Loop 112715 failed.: java.lang.ArrayIndexOutOfBoundsException: 2
        at org.infinispan.client.hotrod.impl.protocol.Codec20.readNewTopologyAndHash(Codec20.java:191) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.protocol.Codec20.readNewTopologyIfPresent(Codec20.java:167) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.protocol.Codec20.readHeader(Codec20.java:89) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.HotRodOperation.readHeaderAndValidate(HotRodOperation.java:56) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.AbstractKeyValueOperation.sendPutOperation(AbstractKeyValueOperation.java:50) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.PutOperation.executeOperation(PutOperation.java:30) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.PutOperation.executeOperation(PutOperation.java:19) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.execute(RetryOnFailureOperation.java:49) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.RemoteCacheImpl.put(RemoteCacheImpl.java:237) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.RemoteCacheSupport.put(RemoteCacheSupport.java:79) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at com.example.Main.main(Main.java:31) [:]

13:34:24,396 ERROR [org.infinispan.client.hotrod.impl.protocol.Codec20] (main) ISPN004003: Invalid magic number. Expected 0xa1 and received 0x0
13:34:24,397 WARNING [com.example.Main] (main) Loop 112716 failed.: org.infinispan.client.hotrod.exceptions.InvalidResponseException:: Invalid magic number. Expected 0xa1 and received 0x0
        at org.infinispan.client.hotrod.impl.protocol.Codec20.readHeader(Codec20.java:68) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.HotRodOperation.readHeaderAndValidate(HotRodOperation.java:56) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.AbstractKeyValueOperation.sendPutOperation(AbstractKeyValueOperation.java:50) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.PutOperation.executeOperation(PutOperation.java:30) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.PutOperation.executeOperation(PutOperation.java:19) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.execute(RetryOnFailureOperation.java:49) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.RemoteCacheImpl.put(RemoteCacheImpl.java:237) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.client.hotrod.impl.RemoteCacheSupport.put(RemoteCacheSupport.java:79) [infinispan-client-hotrod-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at com.example.Main.main(Main.java:31) [:]
~~~


Expected results:
Hot Rod client shouldn't be affected by a topology change of the sever side.


Additional info:
The joining server may reports the following error during its start up.  I got this one just once among several test runs.
~~~
13:25:08,394 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread-1) ISPN000136: Execution error: org.infinispan.statetransfer.OutdatedTopologyException: Cache topology changed while t
he command was executing: expected 1, got 2
        at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.handleNonTxWriteCommand(BaseDistributionInterceptor.java:189) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.distribution.NonTxDistributionInterceptor.visitPutKeyValueCommand(NonTxDistributionInterceptor.java:72) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.EntryWrappingInterceptor.invokeNextAndApplyChanges(EntryWrappingInterceptor.java:326) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.EntryWrappingInterceptor.setSkipRemoteGetsAndInvokeNextForDataCommand(EntryWrappingInterceptor.java:407) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.EntryWrappingInterceptor.visitPutKeyValueCommand(EntryWrappingInterceptor.java:164) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitPutKeyValueCommand(AbstractLockingInterceptor.java:48) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.statetransfer.StateTransferInterceptor.handleNonTxWriteCommand(StateTransferInterceptor.java:172) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:101) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.CacheMgmtInterceptor.updateStoreStatistics(CacheMgmtInterceptor.java:148) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:134) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:32) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:39) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:48) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:95) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.remoting.InboundInvocationHandlerImpl.access$000(InboundInvocationHandlerImpl.java:50) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at org.infinispan.remoting.InboundInvocationHandlerImpl$2.run(InboundInvocationHandlerImpl.java:178) [infinispan-core-6.1.0.Final-redhat-4.jar:6.1.0.Final-redhat-4]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_65]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_65]
~~~
Comment 2 Osamu Nagano 2014-08-27 07:45:21 UTC 
This seems a bug of new codec 2.0.  If we use the old codec, 1.3 like blow, it works fine.

~~~
        ConfigurationBuilder builder = new ConfigurationBuilder();
        builder.addServers(serverList);
        builder.protocolVersion("1.3");
       
        Configuration cfg = builder.build();	
        manager = new RemoteCacheManager(cfg);
~~~

As a workaround, can we continue to use version 1.3 on JDG 6.3.0?
Comment 3 Alan Field 2014-08-27 12:52:28 UTC 
Created attachment 931454 [details]
Log from the test client using HotRod protocol 1.3
Comment 4 Alan Field 2014-08-27 12:53:00 UTC 
Created attachment 931455 [details]
Log from the test client using HotRod protocol 2.0
Comment 5 Alan Field 2014-08-27 12:56:34 UTC 
I was able to reproduce this issue. The attached logs show the difference between the behavior using HotRod protocol 1.3 and 2.0. In 1.3 the topology change happens immediately, and the test client keeps running without errors. In 2.0, it takes almost 2 minutes before the topology change is detected by the client. During that two minute period the exceptions described above are produced. 

Changing target release to 6.3.1 to discuss
Comment 6 Galder Zamarreño 2014-08-27 15:30:58 UTC 
Hi Osamu, thanks a lot for reporting this. I've tested this with Infinispan 7.0 Beta1 and the issue is present there too. I'll create a JIRA issue to investigate it further and then port the fix over to JDG.

Indeed, using version 1.3 with JDG 6.3.0 is fine. Some of the new bells and whistles, including more precise hash topology header, are not there, but you can run this version temporarily without any major issues.
Comment 7 Galder Zamarreño 2014-08-27 15:53:08 UTC 
I can't seem to add a link JBoss JIRA, I keep getting the error message "An invalid value 'ISPN-4674' for an External Bug Tracker Bug ID was submitted.". Anyway, the JIRA link: https://issues.jboss.org/browse/ISPN-4674
Comment 8 Osamu Nagano 2014-08-28 02:43:20 UTC 
Thanks Alan, Galder.  We'll use protocol 1.3 for a while.

ISPN-4674 can't be linked for me too.
Comment 9 Galder Zamarreño 2014-08-28 07:30:58 UTC 
Re: linking -> weird :|

I've replicated the issue in a unit test, I'm currently debugging through it.
Comment 10 Alan Field 2014-08-28 07:49:42 UTC 
I entered a Bugzilla for the linking issue:

https://bugzilla.redhat.com/show_bug.cgi?id=1134477

We'll see what happens!
Comment 11 Galder Zamarreño 2014-08-29 10:07:22 UTC 
I've sent a PR for the community fix: https://github.com/infinispan/infinispan/pull/2828
Comment 13 Alan Field 2014-09-08 12:12:44 UTC 
Verified that this issue no longer occurs using JDG 6.3.1 ER2 client and server libraries.
Note You need to log in before you can comment on or make changes to this bug.