[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno commented on ISPN-397:
---------------------------------------
This smells like a problem at reading time rather than at writing since both when it works
and fails, the same byte array is flushed:
good-infinispan.log: 2010-04-12 16:44:34,219 4789 INFO
[org.jboss.marshalling.AbstractMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-51725:) Buffer at position 70
before flushing:
[2, 1, -102, 80, 73, 123, 3, 3, 0, 1, 3, 10, 3, 57, 19, 107, 45, 116, 101, 115, 116, 82,
101, 112, 108, 105, 99, 97, 116, 101, 100, 80, 117, 116, 3, 55, 19, 118, 45, 116, 101,
115, 116, 82, 101, 112, 108, 105, 99, 97, 116, 101, 100, 80, 117, 116, 0, 0, 0, 1, 0, 0,
0, 1, 73, 123, 73, 123, 73, 123, ...]
bad-infinispan.log: 2010-04-12 16:47:43,200 4689 INFO
[org.jboss.marshalling.AbstractMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-25507:) Buffer at position 70
before flushing:
[2, 1, -102, 80, 73, 123, 3, 3, 0, 1, 3, 10, 3, 57, 19, 107, 45, 116, 101, 115, 116, 82,
101, 112, 108, 105, 99, 97, 116, 101, 100, 80, 117, 116, 3, 55, 19, 118, 45, 116, 101,
115, 116, 82, 101, 112, 108, 105, 99, 97, 116, 101, 100, 80, 117, 116, 0, 0, 0, 1, 0, 0,
0, 1, 73, 123, 73, 123, 73, 123, ...]
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!
StateTransferException: Expected a delimiter, recieved class
java.util.concurrent.CopyOnWriteArraySet
-----------------------------------------------------------------------------------------------------
Key: ISPN-397
URL:
https://jira.jboss.org/jira/browse/ISPN-397
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.ALPHA2
Reporter: Galder Zamarreno
Assignee: Galder Zamarreno
Attachments: HotRodReplicationTest-infinispan.log,
HotRodReplicationTest.testReplicatedPut-infinispan.log,
HotRodReplicationTest.testReplicatedPut-morelogging-infinispan.log
Something does not look right here. When I run HotRodReplicationTest, the test works fine
and you see state transfer happening fine when the 2nd instance is started. However, when
I run only HotRodReplicationTest.tesReplicatedPut method, I see this:
2010-04-12 11:08:20,401 4702 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Data container
is 29247075
2010-04-12 11:08:20,401 4702 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Initiating
state transfer process
2010-04-12 11:08:20,401 4702 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Trying to fetch state from eq-59589
2010-04-12 11:08:20,413 4714 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-12496:) Received state for cache named
'hotRodReplSync'. Attempting to apply state.
2010-04-12 11:08:20,420 4721 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-12496:) Applying state
2010-04-12 11:08:20,421 4722 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-59589:) Received request to
generate state for cache named 'hotRodReplSync'. Attempting to generate state.
2010-04-12 11:08:20,421 4722 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-59589:) Generating state. Can
provide? true
2010-04-12 11:08:20,460 4761 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-59589:) Wrote version 410
2010-04-12 11:08:20,462 4763 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-59589:) Writing 1 StoredEntries
to stream
2010-04-12 11:08:20,463 4764 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-59589:) Transaction log size is
0
2010-04-12 11:08:20,464 4765 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-12496:) Read version 410
2010-04-12 11:08:20,465 4766 TRACE
[org.infinispan.interceptors.InvocationContextInterceptor]
(Incoming-2,Infinispan-Cluster,eq-12496:) Invoked with command
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=30d83d, array=[107, 0, 0,
0, 0, 0, 0, 0, 0, 0, ..]}}, value=class java.lang.Long, putIfAbsent=false,
lifespanMillis=-1, maxIdleTimeMillis=-1} and InvocationContext
[NonTxInvocationContext{flags=[CACHE_MODE_LOCAL]}]
2010-04-12 11:08:20,465 4766 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-12496:) Attempting to lock
CacheKey{data=ByteArray{size=18, hashCode=30d83d, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0,
..]}} with acquisition timeout of 10000 millis
2010-04-12 11:08:20,466 4767 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-12496:) Successfully acquired lock!
2010-04-12 11:08:20,466 4767 TRACE [org.infinispan.container.EntryFactoryImpl]
(Incoming-2,Infinispan-Cluster,eq-12496:) Creating new entry.
2010-04-12 11:08:20,466 4767 TRACE [org.infinispan.interceptors.CallInterceptor]
(Incoming-2,Infinispan-Cluster,eq-12496:) Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=30d83d, array=[107, 0, 0,
0, 0, 0, 0, 0, 0, 0, ..]}}, value=class java.lang.Long, putIfAbsent=false,
lifespanMillis=-1, maxIdleTimeMillis=-1}.
2010-04-12 11:08:20,466 4767 TRACE [org.infinispan.interceptors.ReplicationInterceptor]
(Incoming-2,Infinispan-Cluster,eq-12496:) LOCAL mode forced on invocation. Suppressing
clustered events.
2010-04-12 11:08:20,466 4767 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-12496:) Number of entries in context: 1
2010-04-12 11:08:20,466 4767 TRACE [org.infinispan.container.entries.ReadCommittedEntry]
(Incoming-2,Infinispan-Cluster,eq-12496:) Updating entry
(key=CacheKey{data=ByteArray{size=18, hashCode=30d83d, array=[107, 0, 0, 0, 0, 0, 0, 0, 0,
0, ..]}} removed=false valid=true changed=true created=true value=class java.lang.Long]
2010-04-12 11:08:20,469 4770 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-12496:) Releasing lock on
[CacheKey{data=ByteArray{size=18, hashCode=30d83d, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0,
..]}}] for owner Thread[Incoming-2,Infinispan-Cluster,eq-12496,5,Thread Pools]
2010-04-12 11:08:20,470 4771 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-12496:) Attempting to unlock
CacheKey{data=ByteArray{size=18, hashCode=30d83d, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0,
..]}}
2010-04-12 11:08:20,470 4771 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-59589:) Waiting for a distributed
sync block
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)
2010-04-12 11:08:20,473 4774 WARN [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Could not find available peer for state, backing off and retrying
2010-04-12 11:08:21,473 5774 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Trying to fetch state from eq-59589
2010-04-12 11:08:21,478 5779 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-12496:) Received state for cache named
'hotRodReplSync'. Attempting to apply state.
Attaching logs
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
https://jira.jboss.org/jira/secure/Administrators.jspa
-
For more information on JIRA, see:
http://www.atlassian.com/software/jira