[ 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 -- 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

[ 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 -- 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

[ 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. -- 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

[ 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. -- 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

[ 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) -- 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

[ 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; -- 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

[ 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) -- 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