[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno commented on ISPN-397:
---------------------------------------
Managed to replicate it again and got more logging:
2010-04-12 12:03:52,924 4601 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Generating state. Can
provide? true
2010-04-12 12:03:52,948 4625 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Wrote version 410
2010-04-12 12:03:52,949 4626 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Write obj true, of class
class java.lang.Boolean to object output
org.jboss.marshalling.river.RiverMarshaller@b52a28
2010-04-12 12:03:52,949 4626 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Write obj 123, of class
class java.lang.Byte to object output org.jboss.marshalling.river.RiverMarshaller@b52a28
2010-04-12 12:03:52,951 4628 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Writing 1 StoredEntries
to stream
2010-04-12 12:03:52,951 4628 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Write obj
[ImmortalCacheEntry{cacheValue=ImmortalCacheValue{value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297}}}
ImmortalCacheEntry{key=CacheKey{data=ByteArray{size=18, hashCode=191e4c, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}}], of class class java.util.HashSet to object
output org.jboss.marshalling.river.RiverMarshaller@b52a28
2010-04-12 12:03:52,952 4629 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Write obj 123, of class
class java.lang.Byte to object output org.jboss.marshalling.river.RiverMarshaller@b52a28
2010-04-12 12:03:52,952 4629 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Write obj 123, of class
class java.lang.Byte to object output org.jboss.marshalling.river.RiverMarshaller@b52a28
2010-04-12 12:03:52,953 4630 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Transaction log size is
0
2010-04-12 12:03:52,953 4630 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Write obj 123, of class
class java.lang.Byte to object output org.jboss.marshalling.river.RiverMarshaller@b52a28
2010-04-12 12:03:52,953 4630 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-49171:) Read version 410
2010-04-12 12:03:52,954 4631 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(Incoming-2,Infinispan-Cluster,eq-49171:) Read obj true, of class class java.lang.Boolean
2010-04-12 12:03:52,954 4631 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(Incoming-2,Infinispan-Cluster,eq-49171:) Read obj 123, of class class java.lang.Byte
2010-04-12 12:03:52,955 4632 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(Incoming-2,Infinispan-Cluster,eq-49171:) Read obj
[ImmortalCacheEntry{cacheValue=ImmortalCacheValue{value=class java.lang.Long}}
ImmortalCacheEntry{key=CacheKey{data=ByteArray{size=18, hashCode=ad7d80, array=[107, 0, 0,
0, 0, 0, 0, 0, 0, 0, ..]}}}], of class class java.util.HashSet
2010-04-12 12:03:52,955 4632 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-45557:) Waiting for a distributed
sync block
2010-04-12 12:03:52,956 4633 TRACE
[org.infinispan.interceptors.InvocationContextInterceptor]
(Incoming-2,Infinispan-Cluster,eq-49171:) Invoked with command
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=ad7d80, 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 12:03:52,956 4633 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-49171:) Attempting to lock
CacheKey{data=ByteArray{size=18, hashCode=ad7d80, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0,
..]}} with acquisition timeout of 10000 millis
2010-04-12 12:03:52,956 4633 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-49171:) Successfully acquired lock!
2010-04-12 12:03:52,956 4633 TRACE [org.infinispan.container.EntryFactoryImpl]
(Incoming-2,Infinispan-Cluster,eq-49171:) Creating new entry.
2010-04-12 12:03:52,956 4633 TRACE [org.infinispan.interceptors.CallInterceptor]
(Incoming-2,Infinispan-Cluster,eq-49171:) Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=ad7d80, 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 12:03:52,956 4633 TRACE [org.infinispan.interceptors.ReplicationInterceptor]
(Incoming-2,Infinispan-Cluster,eq-49171:) LOCAL mode forced on invocation. Suppressing
clustered events.
2010-04-12 12:03:52,956 4633 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-49171:) Number of entries in context: 1
2010-04-12 12:03:52,956 4633 TRACE [org.infinispan.container.entries.ReadCommittedEntry]
(Incoming-2,Infinispan-Cluster,eq-49171:) Updating entry
(key=CacheKey{data=ByteArray{size=18, hashCode=ad7d80, 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 12:03:52,957 4634 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-49171:) Releasing lock on
[CacheKey{data=ByteArray{size=18, hashCode=ad7d80, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0,
..]}}] for owner Thread[Incoming-2,Infinispan-Cluster,eq-49171,5,Thread Pools]
2010-04-12 12:03:52,957 4634 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-49171:) Attempting to unlock
CacheKey{data=ByteArray{size=18, hashCode=ad7d80, array=[107, 0, 0, 0, 0, 0, 0, 0, 0, 0,
..]}}
2010-04-12 12:03:52,957 4634 TRACE [org.infinispan.marshall.jboss.JBossMarshaller]
(Incoming-2,Infinispan-Cluster,eq-49171:) Read obj class
java.util.concurrent.CopyOnWriteArraySet, of class class java.lang.Class
2010-04-12 12:03:52,960 4637 ERROR
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-49171:) Caught while requesting or applying state
org.infinispan.statetransfer.StateTransferException: Expected a delimiter, recieved class
java.util.concurrent.CopyOnWriteArraySet
Here, I'm logging each individual stream write and stream read. Where the hell is that
CopyOnWriteArraySet.class write coming from? It's not even reading an instance of that
class, but the class object itself.
Maybe this is something related to the latest JBMAR upgrade?? I'll revert to 1.2.0 and
see if it happens at all. Even though it's a bit random, it can be replicated it
relatively easily.
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
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