I'm seeing random exceptions like this when running HotRodReplicationTest.testReplicatedPut

2010-04-12 11:08:20,472 4773 ERROR [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-2,Infinispan-Cluster,eq-12496 Caught while requesting or applying state
org.infinispan.statetransfer.StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
at org.infinispan.statetransfer.StateTransferManagerImpl.assertDelimited(StateTransferManagerImpl.java:389)
at org.infinispan.statetransfer.StateTransferManagerImpl.assertDelimited(StateTransferManagerImpl.java:384)
at org.infinispan.statetransfer.StateTransferManagerImpl.applyState(StateTransferManagerImpl.java:307)
at org.infinispan.remoting.InboundInvocationHandlerImpl.applyState(InboundInvocationHandlerImpl.java:73)
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.setState(JGroupsTransport.java:564)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.handleUpEvent(MessageDispatcher.java:665)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:725)
at org.jgroups.JChannel.up(JChannel.java:1420)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:855)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.connectToStateProvider(STREAMING_STATE_TRANSFER.java:523)
at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.handleStateRsp(STREAMING_STATE_TRANSFER.java:462)
at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.up(STREAMING_STATE_TRANSFER.java:224)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:474)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:890)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:614)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:294)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:707)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:131)
at org.jgroups.protocols.FD.up(FD.java:261)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:269)
at org.jgroups.stack.Protocol.up(Protocol.java:353)
at org.jgroups.protocols.Discovery.up(Discovery.java:277)
at org.jgroups.protocols.TP.passMessageUp(TP.java:982)
at org.jgroups.protocols.TP.access$100(TP.java:55)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1522)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1504)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)

In Hot Rod, keys and values are stored as byte arrays and I have defined two wrapper classes called CacheKey and CacheValue to wrap them around.

Somehow which I still haven't figured out, JBMAR thinks that out of a byte array key of 19 bytes like the following, 45 refers to a new object, to be precise a Long:
array=[107, 45, 116, 101, 115, 116, 82, 101, 112, 108

The end result is that it then tries to read a new object of type 116 which is java.util.concurrent.CopyOnWriteArraySet class object.

Instead, when things work fine, it reads the 19 byte length byte array and discovers the CacheValue class in the value part.

Taken from the logs:

When things work fine, at reading time you see:
2010-04-12 16:44:34,227 4797 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (Incoming-2,Infinispan-Cluster,eq-56246 Attempting to unlock CacheKey{data=ByteArray{size=19, hashCode=119db9e, array=[107, 45, 116, 101, 115, 116, 82, 101, 112, 108, ..]}}
2010-04-12 16:44:34,227 4797 INFO [org.jboss.marshalling.river.RiverUnmarshaller] (Incoming-2,Infinispan-Cluster,eq-56246 doReadObject
2010-04-12 16:44:34,227 4797 TRACE [org.infinispan.marshall.jboss.JBossMarshaller] (Incoming-2,Infinispan-Cluster,eq-56246 Read obj 123, of class class java.lang.Byte

However, when they go wrong, you see:
2010-04-12 16:47:43,204 4693 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (Incoming-2,Infinispan-Cluster,eq-56524 Attempting to unlock CacheKey{data=ByteArray{size=19, hashCode=15c2843, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0, ..]}}
2010-04-12 16:47:43,204 4693 INFO [org.jboss.marshalling.river.RiverUnmarshaller] (Incoming-2,Infinispan-Cluster,eq-56524 doReadObject
2010-04-12 16:47:43,204 4693 INFO [org.jboss.marshalling.river.RiverUnmarshaller] (Incoming-2,Infinispan-Cluster,eq-56524 Read 116, so returning CopyOnWriteArraySet.class

See the different in the cache keys! I suspect that JBMAR is getting confused with the contents of what's being sent around.

If you look further up, you see the difference in the value parts as well:

good-infinispan.log: 2010-04-12 16:44:34,227 4797 TRACE [org.infinispan.interceptors.CallInterceptor] (Incoming-2,Infinispan-Cluster,eq-56246 Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=19, hashCode=119db9e, array=[107, 45, 116, 101, 115, 116, 82, 101, 112, 108, ..]}}, value=CacheValue{data=ByteArray

{size=19, array=[118, 45, 116, 101, 115, 116, 82, 101, 112, 108, ..]}

, version=4294967297}, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}.

bad-infinispan.log: 2010-04-12 16:47:43,203 4692 TRACE [org.infinispan.interceptors.CallInterceptor] (Incoming-2,Infinispan-Cluster,eq-56524 Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=19, hashCode=15c2843, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0, ..]}}, value=class java.lang.Long, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}.

In the good one, it correctly spots the CacheValue whereas in the bad part, it thinks that the value part is a Long.