[JBoss JIRA] Created: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
11:17 a.m.
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:
2010-04-12 11:09:44,501 4615 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Data container
is 9015524
2010-04-12 11:09:44,501 4615 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Initiating
state transfer process
2010-04-12 11:09:44,504 4618 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Trying to fetch state from eq-49043
2010-04-12 11:09:44,522 4636 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) Received state for cache named
'hotRodReplSync'. Attempting to apply state.
2010-04-12 11:09:44,522 4636 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying state
2010-04-12 11:09:44,534 4648 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Received request to
generate state for cache named 'hotRodReplSync'. Attempting to generate state.
2010-04-12 11:09:44,535 4649 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Generating state. Can
provide? true
2010-04-12 11:09:44,567 4681 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,568 4682 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 1 StoredEntries
to stream
2010-04-12 11:09:44,569 4683 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Transaction log size is
0
2010-04-12 11:09:44,570 4684 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Waiting for a distributed
sync block
2010-04-12 11:09:44,571 4685 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.interceptors.InvocationContextInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Invoked with command
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1} and InvocationContext
[NonTxInvocationContext{flags=[CACHE_MODE_LOCAL]}]
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to lock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}} with acquisition timeout of 10000 millis
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Successfully acquired lock!
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.EntryFactoryImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Creating new entry.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.CallInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.ReplicationInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) LOCAL mode forced on invocation. Suppressing
clustered events.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Number of entries in context: 1
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.entries.ReadCommittedEntry]
(Incoming-2,Infinispan-Cluster,eq-3491:) Updating entry
(key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}} removed=false valid=true changed=true created=true
value=CacheValue{data=ByteArray{size=18, array=[118, 45, 116, 101, 115, 82, 101, 112, 108,
105, ..]}, version=4294967297}]
2010-04-12 11:09:44,573 4687 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Releasing lock on
[CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}}] for owner Thread[Incoming-2,Infinispan-Cluster,eq-3491,5,Thread
Pools]
2010-04-12 11:09:44,573 4687 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to unlock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}}
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Integrating transaction log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) dests=[eq-49043],
command=StateTransferControlCommand{enabled=true}, mode=SYNCHRONOUS, timeout=10000
2010-04-12 11:09:44,577 4691 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Wrote version 410
2010-04-12 11:09:44,583 4697 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Read version 410
2010-04-12 11:09:44,591 4705 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Distributed sync block
received, proceeding with writing commit log
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.transaction.TransactionLog]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 0 pending
prepares to the stream
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,592 4706 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) State generated, closing
object stream
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher]
(Incoming-2,Infinispan-Cluster,eq-3491:) responses: [sender=eq-49043, retval=null,
received=true, suspected=false]
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying post-flush commits
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying pending prepares
2010-04-12 11:09:44,593 4707 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) State applied, closing object stream
2010-04-12 11:09:44,593 4707 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Successfully retrieved and applied state from eq-49043
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
11:17 a.m.
New subject: [JBoss JIRA] Updated: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno updated ISPN-397:
----------------------------------
Attachment: HotRodReplicationTest.testReplicatedPut-infinispan.log
HotRodReplicationTest-infinispan.log
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:
2010-04-12 11:09:44,501 4615 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Data container
is 9015524
2010-04-12 11:09:44,501 4615 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Initiating
state transfer process
2010-04-12 11:09:44,504 4618 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Trying to fetch state from eq-49043
2010-04-12 11:09:44,522 4636 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) Received state for cache named
'hotRodReplSync'. Attempting to apply state.
2010-04-12 11:09:44,522 4636 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying state
2010-04-12 11:09:44,534 4648 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Received request to
generate state for cache named 'hotRodReplSync'. Attempting to generate state.
2010-04-12 11:09:44,535 4649 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Generating state. Can
provide? true
2010-04-12 11:09:44,567 4681 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,568 4682 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 1 StoredEntries
to stream
2010-04-12 11:09:44,569 4683 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Transaction log size is
0
2010-04-12 11:09:44,570 4684 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Waiting for a distributed
sync block
2010-04-12 11:09:44,571 4685 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.interceptors.InvocationContextInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Invoked with command
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1} and InvocationContext
[NonTxInvocationContext{flags=[CACHE_MODE_LOCAL]}]
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to lock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}} with acquisition timeout of 10000 millis
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Successfully acquired lock!
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.EntryFactoryImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Creating new entry.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.CallInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.ReplicationInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) LOCAL mode forced on invocation. Suppressing
clustered events.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Number of entries in context: 1
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.entries.ReadCommittedEntry]
(Incoming-2,Infinispan-Cluster,eq-3491:) Updating entry
(key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}} removed=false valid=true changed=true created=true
value=CacheValue{data=ByteArray{size=18, array=[118, 45, 116, 101, 115, 82, 101, 112, 108,
105, ..]}, version=4294967297}]
2010-04-12 11:09:44,573 4687 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Releasing lock on
[CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}}] for owner Thread[Incoming-2,Infinispan-Cluster,eq-3491,5,Thread
Pools]
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to unlock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}}
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Integrating transaction log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) dests=[eq-49043],
command=StateTransferControlCommand{enabled=true}, mode=SYNCHRONOUS, timeout=10000
2010-04-12 11:09:44,577 4691 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Wrote version 410
2010-04-12 11:09:44,583 4697 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Read version 410
2010-04-12 11:09:44,591 4705 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Distributed sync block
received, proceeding with writing commit log
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.transaction.TransactionLog]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 0 pending
prepares to the stream
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,592 4706 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) State generated, closing
object stream
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher]
(Incoming-2,Infinispan-Cluster,eq-3491:) responses: [sender=eq-49043, retval=null,
received=true, suspected=false]
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying post-flush commits
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying pending prepares
2010-04-12 11:09:44,593 4707 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) State applied, closing object stream
2010-04-12 11:09:44,593 4707 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Successfully retrieved and applied state from eq-49043
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
11:30 a.m.
New subject: [JBoss JIRA] Commented: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno commented on ISPN-397:
---------------------------------------
Can't replicate it any more :(
I'll keep this around in case it appears again.
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:
2010-04-12 11:09:44,501 4615 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Data container
is 9015524
2010-04-12 11:09:44,501 4615 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Initiating
state transfer process
2010-04-12 11:09:44,504 4618 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Trying to fetch state from eq-49043
2010-04-12 11:09:44,522 4636 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) Received state for cache named
'hotRodReplSync'. Attempting to apply state.
2010-04-12 11:09:44,522 4636 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying state
2010-04-12 11:09:44,534 4648 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Received request to
generate state for cache named 'hotRodReplSync'. Attempting to generate state.
2010-04-12 11:09:44,535 4649 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Generating state. Can
provide? true
2010-04-12 11:09:44,567 4681 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,568 4682 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 1 StoredEntries
to stream
2010-04-12 11:09:44,569 4683 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Transaction log size is
0
2010-04-12 11:09:44,570 4684 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Waiting for a distributed
sync block
2010-04-12 11:09:44,571 4685 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.interceptors.InvocationContextInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Invoked with command
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1} and InvocationContext
[NonTxInvocationContext{flags=[CACHE_MODE_LOCAL]}]
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to lock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}} with acquisition timeout of 10000 millis
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Successfully acquired lock!
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.EntryFactoryImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Creating new entry.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.CallInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.ReplicationInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) LOCAL mode forced on invocation. Suppressing
clustered events.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Number of entries in context: 1
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.entries.ReadCommittedEntry]
(Incoming-2,Infinispan-Cluster,eq-3491:) Updating entry
(key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}} removed=false valid=true changed=true created=true
value=CacheValue{data=ByteArray{size=18, array=[118, 45, 116, 101, 115, 82, 101, 112, 108,
105, ..]}, version=4294967297}]
2010-04-12 11:09:44,573 4687 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Releasing lock on
[CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}}] for owner Thread[Incoming-2,Infinispan-Cluster,eq-3491,5,Thread
Pools]
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to unlock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}}
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Integrating transaction log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) dests=[eq-49043],
command=StateTransferControlCommand{enabled=true}, mode=SYNCHRONOUS, timeout=10000
2010-04-12 11:09:44,577 4691 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Wrote version 410
2010-04-12 11:09:44,583 4697 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Read version 410
2010-04-12 11:09:44,591 4705 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Distributed sync block
received, proceeding with writing commit log
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.transaction.TransactionLog]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 0 pending
prepares to the stream
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,592 4706 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) State generated, closing
object stream
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher]
(Incoming-2,Infinispan-Cluster,eq-3491:) responses: [sender=eq-49043, retval=null,
received=true, suspected=false]
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying post-flush commits
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying pending prepares
2010-04-12 11:09:44,593 4707 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) State applied, closing object stream
2010-04-12 11:09:44,593 4707 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Successfully retrieved and applied state from eq-49043
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
12:30 p.m.
New subject: [JBoss JIRA] Updated: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno updated ISPN-397:
----------------------------------
Description:
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
was:
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:
2010-04-12 11:09:44,501 4615 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Data container
is 9015524
2010-04-12 11:09:44,501 4615 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl] (HotRodWorker-2-1:) Initiating
state transfer process
2010-04-12 11:09:44,504 4618 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Trying to fetch state from eq-49043
2010-04-12 11:09:44,522 4636 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) Received state for cache named
'hotRodReplSync'. Attempting to apply state.
2010-04-12 11:09:44,522 4636 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying state
2010-04-12 11:09:44,534 4648 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Received request to
generate state for cache named 'hotRodReplSync'. Attempting to generate state.
2010-04-12 11:09:44,535 4649 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Generating state. Can
provide? true
2010-04-12 11:09:44,567 4681 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,568 4682 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 1 StoredEntries
to stream
2010-04-12 11:09:44,569 4683 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Transaction log size is
0
2010-04-12 11:09:44,570 4684 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Waiting for a distributed
sync block
2010-04-12 11:09:44,571 4685 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,572 4686 TRACE
[org.infinispan.interceptors.InvocationContextInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Invoked with command
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1} and InvocationContext
[NonTxInvocationContext{flags=[CACHE_MODE_LOCAL]}]
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to lock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}} with acquisition timeout of 10000 millis
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Successfully acquired lock!
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.EntryFactoryImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Creating new entry.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.CallInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Executing command:
PutKeyValueCommand{key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45,
116, 101, 115, 82, 101, 112, 108, 105, ..]}}, value=CacheValue{data=ByteArray{size=18,
array=[118, 45, 116, 101, 115, 82, 101, 112, 108, 105, ..]}, version=4294967297},
putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.ReplicationInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) LOCAL mode forced on invocation. Suppressing
clustered events.
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Number of entries in context: 1
2010-04-12 11:09:44,572 4686 TRACE [org.infinispan.container.entries.ReadCommittedEntry]
(Incoming-2,Infinispan-Cluster,eq-3491:) Updating entry
(key=CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}} removed=false valid=true changed=true created=true
value=CacheValue{data=ByteArray{size=18, array=[118, 45, 116, 101, 115, 82, 101, 112, 108,
105, ..]}, version=4294967297}]
2010-04-12 11:09:44,573 4687 TRACE [org.infinispan.interceptors.LockingInterceptor]
(Incoming-2,Infinispan-Cluster,eq-3491:) Releasing lock on
[CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82,
101, 112, 108, 105, ..]}}] for owner Thread[Incoming-2,Infinispan-Cluster,eq-3491,5,Thread
Pools]
2010-04-12 11:09:44,573 4687 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Attempting to unlock
CacheKey{data=ByteArray{size=18, hashCode=1faa614, array=[107, 45, 116, 101, 115, 82, 101,
112, 108, 105, ..]}}
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Integrating transaction log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,573 4687 TRACE
[org.infinispan.remoting.transport.jgroups.JGroupsTransport]
(Incoming-2,Infinispan-Cluster,eq-3491:) dests=[eq-49043],
command=StateTransferControlCommand{enabled=true}, mode=SYNCHRONOUS, timeout=10000
2010-04-12 11:09:44,577 4691 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(Incoming-2,Infinispan-Cluster,eq-3491:) Wrote version 410
2010-04-12 11:09:44,583 4697 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Read version 410
2010-04-12 11:09:44,591 4705 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Distributed sync block
received, proceeding with writing commit log
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-49043:) Wrote version 410
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.transaction.TransactionLog]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) Writing 0 pending
prepares to the stream
2010-04-12 11:09:44,591 4705 TRACE [org.infinispan.marshall.VersionAwareMarshaller]
(OOB-2,Infinispan-Cluster,eq-3491:) Read version 410
2010-04-12 11:09:44,592 4706 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(STREAMING_STATE_TRANSFER-sender-1,Infinispan-Cluster,eq-49043:) State generated, closing
object stream
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher]
(Incoming-2,Infinispan-Cluster,eq-3491:) responses: [sender=eq-49043, retval=null,
received=true, suspected=false]
2010-04-12 11:09:44,592 4706 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying post-flush commits
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Finished applying commit log
2010-04-12 11:09:44,593 4707 TRACE
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) Retrieving/Applying pending prepares
2010-04-12 11:09:44,593 4707 DEBUG
[org.infinispan.statetransfer.StateTransferManagerImpl]
(Incoming-2,Infinispan-Cluster,eq-3491:) State applied, closing object stream
2010-04-12 11:09:44,593 4707 INFO [org.infinispan.remoting.rpc.RpcManagerImpl]
(HotRodWorker-2-1:) Successfully retrieved and applied state from eq-49043
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
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
12:32 p.m.
New subject: [JBoss JIRA] Commented: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
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
12:34 p.m.
New subject: [JBoss JIRA] Updated: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno updated ISPN-397:
----------------------------------
Attachment: HotRodReplicationTest.testReplicatedPut-morelogging-infinispan.log
Added trace log with more logging.
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
12:57 p.m.
New subject: [JBoss JIRA] Commented: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno commented on ISPN-397:
---------------------------------------
Tried JBMAR 1.2.0.GA and the issue is still present, so it must be something else.
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
2:55 p.m.
New subject: [JBoss JIRA] Commented: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno commented on ISPN-397:
---------------------------------------
The only place where CopyOnWriteArraySet is used in Infinispan is in NotifyingFutureImpl
and hence can't see how that could the source of the issue here, hence I think this
could be a bug in JBMAR. It's worth noting that this exception comes right after
reading a HashSet containing the entries in the cache.
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
5 p.m.
New subject: [JBoss JIRA] Commented: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
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
5:02 p.m.
New subject: [JBoss JIRA] Updated: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno updated ISPN-397:
----------------------------------
Attachment: good-infinispan.log
bad-infinispan.log
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
Fix For: 4.1.0.BETA1
Attachments: bad-infinispan.log, good-infinispan.log,
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
5:02 p.m.
New subject: [JBoss JIRA] Updated: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno updated ISPN-397:
----------------------------------
Fix Version/s: 4.1.0.BETA1
Priority: Critical (was: Major)
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
Priority: Critical
Fix For: 4.1.0.BETA1
Attachments: bad-infinispan.log, good-infinispan.log,
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
5:37 p.m.
New subject: [JBoss JIRA] Commented: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno commented on ISPN-397:
---------------------------------------
In fact, JBMAR defines Long as the following, so it sometimes confuse the 2nd byte in the
cache key, 45 (0x2d), as a new type:
public static final int ID_LONG_CLASS = 0x2d;
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
Priority: Critical
Fix For: 4.1.0.BETA1
Attachments: bad-infinispan.log, good-infinispan.log,
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
8:57 a.m.
New subject: [JBoss JIRA] Resolved: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Galder Zamarreno resolved ISPN-397.
-----------------------------------
Resolution: Done
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
Priority: Critical
Fix For: 4.1.0.BETA1
Attachments: bad-infinispan.log, good-infinispan.log,
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
5:30 p.m.
New subject: [JBoss JIRA] Updated: (ISPN-397) StateTransferException: Expected a delimiter, recieved class java.util.concurrent.CopyOnWriteArraySet
[
https://jira.jboss.org/jira/browse/ISPN-397?page=com.atlassian.jira.plugi...
]
Manik Surtani updated ISPN-397:
-------------------------------
Fix Version/s: 4.1.0.ALPHA3
(was: 4.1.0.BETA1)
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
Priority: Critical
Fix For: 4.1.0.ALPHA3
Attachments: bad-infinispan.log, good-infinispan.log,
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
5117
days inactive
5127
days old
infinispan-issues@lists.jboss.org
13 comments
2 participants
participants (2)
-
Galder Zamarreno (JIRA) -
Manik Surtani (JIRA)