[infinispan-issues] [JBoss JIRA] Commented: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
Galder Zamarreno (JIRA)
jira-events at lists.jboss.org
Mon Apr 12 06:32:37 EDT 2010
[ https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12525115#action_12525115 ]
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 at 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 at 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 at 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 at 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 at 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 at 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
More information about the infinispan-issues
mailing list