[infinispan-issues] [JBoss JIRA] Commented: (ISPN-765) Concurrent startup leading to rehashing issues
Tristan Tarrant (JIRA)
jira-events at lists.jboss.org
Sun Nov 21 11:23:54 EST 2010
[ https://jira.jboss.org/browse/ISPN-765?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12564464#comment-12564464 ]
Tristan Tarrant commented on ISPN-765:
--------------------------------------
Here are the traces:
COORDINATOR:
2010-11-21 16:58:26 GMS [DEBUG] new=[arrow-19518, arrow-44800], suspected=[], leaving=[], new view: [arrow-41664|1] [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 FLUSH [DEBUG] arrow-41664: flush coordinator is starting FLUSH with participants [arrow-41664]
2010-11-21 16:58:26 JGroupsDistSync [TRACE] Closing joinInProgress gate
2010-11-21 16:58:26 FLUSH [DEBUG] arrow-41664: received START_FLUSH, responded with FLUSH_COMPLETED to arrow-41664
2010-11-21 16:58:26 FLUSH [DEBUG] arrow-41664: FLUSH_COMPLETED from arrow-41664, completed true, flushMembers [arrow-41664], flushCompleted [arrow-41664]
2010-11-21 16:58:26 STABLE [DEBUG] suspending message garbage collection
2010-11-21 16:58:26 STABLE [DEBUG] resume task started, max_suspend_time=33000
2010-11-21 16:58:26 FLUSH [DEBUG] arrow-41664: all FLUSH_COMPLETED received
2010-11-21 16:58:26 NAKACK [DEBUG]
[setDigest()]
existing digest: arrow-41664: [3 : 8 (8)]
new digest: arrow-41664: [3 : 7 (7)], arrow-44800: [0 : 0], arrow-19518: [0 : 0]
resulting digest: arrow-41664: [3 : 8 (8)], arrow-44800: [0 : 0 (0)], arrow-19518: [0 : 0 (0)]
2010-11-21 16:58:26 GMS [DEBUG] arrow-41664: view is [arrow-41664|1] [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 FD_SOCK [DEBUG] VIEW_CHANGE received: [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 JGroupsTransport [INFO] Received new cluster view: [arrow-41664|1] [arrow-41664, arrow-19518, arrow-44800]
View changed: EventImpl{type=VIEW_CHANGED, newMembers=[arrow-41664, arrow-19518, arrow-44800], oldMembers=[arrow-41664], localAddress=arrow-41664, viewId=1, needsToRejoin=false, subgroupsMerged=null}
I am coordinator
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:26 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664] to [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 DistributionManagerImpl [INFO] This is a JOIN event! Wait for notification from new joiner arrow-44800
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:26 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664] to [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 DistributionManagerImpl [INFO] This is a JOIN event! Wait for notification from new joiner arrow-44800
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:26 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664] to [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 DistributionManagerImpl [INFO] This is a JOIN event! Wait for notification from new joiner arrow-44800
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:26 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664] to [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 DistributionManagerImpl [INFO] This is a JOIN event! Wait for notification from new joiner arrow-44800
2010-11-21 16:58:26 FLUSH [DEBUG] arrow-41664: installing view [arrow-41664|1] [arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 FD_SOCK [DEBUG] ping_dest is arrow-19518, pingable_mbrs=[arrow-41664, arrow-19518, arrow-44800]
2010-11-21 16:58:26 STABLE [DEBUG] resuming message garbage collection
2010-11-21 16:58:26 GMS [DEBUG] arrow-41664: sending RESUME event
2010-11-21 16:58:26 FLUSH [DEBUG] arrow-41664: received RESUME, sending STOP_FLUSH to all
2010-11-21 16:58:26 FLUSH [DEBUG] arrow-41664: received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
2010-11-21 16:58:26 JGroupsDistSync [TRACE] Releasing ReclosableLatch [State = 1, empty queue] gate
2010-11-21 16:58:26 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:26 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:26 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-19518]
2010-11-21 16:58:26 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:26 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] Allowing arrow-19518 to join
2010-11-21 16:58:26 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:26 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:26 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:26 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:26 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:26 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:26 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-19518]
2010-11-21 16:58:26 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:26 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-19518. Starting? true
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] Node topology info added(null). Topology info is TopologyInfo{address2TopologyInfo={arrow-19518=null}}
2010-11-21 16:58:26 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664}
2010-11-21 16:58:26 DistributionManagerImpl [TRACE] New CH is AbstractConsistentHash{caches=null, topologyInfo=null}
2010-11-21 16:58:26 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:28 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:28 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:28 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:28 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:28 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:28 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:29 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:29 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:29 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:29 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:29 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:29 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:29 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:29 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:29 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:29 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:29 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:29 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:30 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:30 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:30 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:30 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:30 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:30 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:31 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:31 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:31 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:31 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:31 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:31 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:33 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:33 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:33 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:33 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:33 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:33 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:35 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:35 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:35 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:35 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:35 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:35 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:36 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:36 DistributionManagerImpl [TRACE] Not alowing arrow-44800 to join since there is a join already in progress for node arrow-19518
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-19518]
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:36 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:36 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-19518. Starting? false
2010-11-21 16:58:36 DistributionManagerImpl [TRACE] New CH is DefaultConsistentHash{addresses ={493=arrow-19518, 3688=arrow-41664}, hash space =10240}
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:36 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:36 DistributionManagerImpl [TRACE] Allowing arrow-44800 to join
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:36 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:36 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:36 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? true
2010-11-21 16:58:36 DistributionManagerImpl [TRACE] Node topology info added(null). Topology info is TopologyInfo{address2TopologyInfo={arrow-44800=null, arrow-19518=null}}
2010-11-21 16:58:36 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:36 DistributionManagerImpl [TRACE] New CH is AbstractConsistentHash{caches=null, topologyInfo=null}
2010-11-21 16:58:36 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-19518]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Allowing arrow-19518 to join
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? false
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is DefaultConsistentHash{addresses ={493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}, hash space =10240}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-19518]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-19518. Starting? true
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Node topology info added(null). Topology info is TopologyInfo{address2TopologyInfo={arrow-19518=null}}
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is AbstractConsistentHash{caches=null, topologyInfo=null}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-19518]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-19518. Starting? false
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is DefaultConsistentHash{addresses ={493=arrow-19518, 3688=arrow-41664}, hash space =10240}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 GMS [DEBUG] received LEAVE_REQ for arrow-19518 from arrow-19518
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Allowing arrow-44800 to join
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? true
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Node topology info added(null). Topology info is TopologyInfo{address2TopologyInfo={arrow-44800=null, arrow-19518=null}}
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is AbstractConsistentHash{caches=null, topologyInfo=null}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? false
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is DefaultConsistentHash{addresses ={493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}, hash space =10240}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Allowing arrow-44800 to join
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? true
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Node topology info added(null). Topology info is TopologyInfo{address2TopologyInfo={arrow-44800=null}}
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is AbstractConsistentHash{caches=null, topologyInfo=null}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? false
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is DefaultConsistentHash{addresses ={3688=arrow-41664, 6414=arrow-44800}, hash space =10240}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 GMS [DEBUG] received LEAVE_REQ for arrow-44800 from arrow-44800
2010-11-21 16:58:47 GMS [DEBUG] new=[], suspected=[], leaving=[arrow-19518, arrow-44800], new view: [arrow-41664|2] [arrow-41664]
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-41664: flush coordinator is starting FLUSH with participants [arrow-41664]
2010-11-21 16:58:47 JGroupsDistSync [TRACE] Closing joinInProgress gate
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-41664: received START_FLUSH, responded with FLUSH_COMPLETED to arrow-41664
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-41664: FLUSH_COMPLETED from arrow-41664, completed true, flushMembers [arrow-41664], flushCompleted [arrow-41664]
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-41664: all FLUSH_COMPLETED received
2010-11-21 16:58:47 FD_SOCK [DEBUG] peer arrow-19518 closed socket gracefully
2010-11-21 16:58:47 FD_SOCK [DEBUG] ping_dest is arrow-44800, pingable_mbrs=[arrow-41664, arrow-44800]
2010-11-21 16:58:47 FD_SOCK [DEBUG] could not create socket to arrow-44800; suspecting arrow-44800
2010-11-21 16:58:47 FD_SOCK [DEBUG] suspecting arrow-44800 (own address is arrow-41664)
2010-11-21 16:58:47 FD_SOCK [DEBUG] ping_dest is null, pingable_mbrs=[arrow-41664]
2010-11-21 16:58:47 GMS [DEBUG] arrow-41664: view is [arrow-41664|2] [arrow-41664]
2010-11-21 16:58:47 NAKACK [DEBUG] removed arrow-44800 from xmit_table (not member anymore)
2010-11-21 16:58:47 NAKACK [DEBUG] removed arrow-19518 from xmit_table (not member anymore)
2010-11-21 16:58:47 FD_SOCK [DEBUG] VIEW_CHANGE received: [arrow-41664]
2010-11-21 16:58:47 JGroupsTransport [INFO] Received new cluster view: [arrow-41664|2] [arrow-41664]
View changed: EventImpl{type=VIEW_CHANGED, newMembers=[arrow-41664], oldMembers=[arrow-41664, arrow-19518, arrow-44800], localAddress=arrow-41664, viewId=2, needsToRejoin=false, subgroupsMerged=null}
I am coordinator
2010-11-21 16:58:47 TransactionTable [TRACE] Saw 2 leavers - kicking off a lock breaking task
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:47 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664, arrow-19518, arrow-44800] to [arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [INFO] This is a LEAVE event! Node arrow-44800 has just left
2010-11-21 16:58:47 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664}
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-19518 are [arrow-19518, arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-41664 are [arrow-41664, arrow-44800]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] arrow-41664 is looking for a new backup to replace arrow-44800
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-44800 are [arrow-44800, arrow-19518]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Leaver's (arrow-44800) main backup(arrow-19518) is looking for another backup as well.
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Nodes that need new backups are: [arrow-41664, arrow-19518]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] This node won't receive state
2010-11-21 16:58:47 DistributionManagerImpl [INFO] I arrow-41664 am participating in rehash, state providers [arrow-41664, arrow-19518], state receivers [arrow-19518, arrow-41664]
2010-11-21 16:58:47 TransactionLoggerImpl [INFO] Starting transaction logging
2010-11-21 16:58:47 TransactionTable [TRACE] Global transactions [] pertain to leavers list [arrow-44800, arrow-19518] and need to be killed
2010-11-21 16:58:47 TransactionTable [TRACE] Saw 2 leavers - kicking off a lock breaking task
2010-11-21 16:58:47 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:47 InvertedLeaveTask [DEBUG] Starting leave rehash[enabled=false,isReceiver=true,isSender=true] on node arrow-41664
2010-11-21 16:58:47 InvertedLeaveTask [INFO] Completed leave rehash on node arrow-41664 in 0 milliseconds
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:47 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664, arrow-19518, arrow-44800] to [arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [INFO] This is a LEAVE event! Node arrow-44800 has just left
2010-11-21 16:58:47 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664}
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-19518 are [arrow-19518, arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-41664 are [arrow-41664, arrow-44800]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] arrow-41664 is looking for a new backup to replace arrow-44800
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-44800 are [arrow-44800, arrow-19518]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Leaver's (arrow-44800) main backup(arrow-19518) is looking for another backup as well.
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Nodes that need new backups are: [arrow-41664, arrow-19518]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] This node won't receive state
2010-11-21 16:58:47 DistributionManagerImpl [INFO] I arrow-41664 am participating in rehash, state providers [arrow-41664, arrow-19518], state receivers [arrow-19518, arrow-41664]
2010-11-21 16:58:47 TransactionLoggerImpl [INFO] Starting transaction logging
2010-11-21 16:58:47 TransactionTable [TRACE] Global transactions [] pertain to leavers list [arrow-44800, arrow-19518] and need to be killed
2010-11-21 16:58:47 TransactionTable [TRACE] Saw 2 leavers - kicking off a lock breaking task
2010-11-21 16:58:47 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:47 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664, arrow-19518, arrow-44800] to [arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [INFO] This is a LEAVE event! Node arrow-44800 has just left
2010-11-21 16:58:47 AbstractWheelConsistentHash [TRACE] Position are: {3688=arrow-41664}
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-41664 are [arrow-41664, arrow-44800]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] arrow-41664 is looking for a new backup to replace arrow-44800
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-44800 are [arrow-44800, arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Leaver's (arrow-44800) main backup(arrow-41664) is looking for another backup as well.
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Nodes that need new backups are: [arrow-41664, arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] This node won't receive state
2010-11-21 16:58:47 DistributionManagerImpl [INFO] I arrow-41664 am participating in rehash, state providers [arrow-41664, arrow-41664], state receivers [arrow-41664, arrow-41664]
2010-11-21 16:58:47 TransactionLoggerImpl [INFO] Starting transaction logging
2010-11-21 16:58:47 TransactionTable [TRACE] Global transactions [] pertain to leavers list [arrow-44800, arrow-19518] and need to be killed
2010-11-21 16:58:47 TransactionTable [TRACE] Saw 2 leavers - kicking off a lock breaking task
2010-11-21 16:58:47 AbstractWheelConsistentHash [TRACE] Position are: {3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] view change received. Needs to re-join? false
2010-11-21 16:58:47 DistributionManagerImpl [INFO] Detected a view change. Member list changed from [arrow-41664, arrow-19518, arrow-44800] to [arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [INFO] This is a LEAVE event! Node arrow-44800 has just left
2010-11-21 16:58:47 AbstractWheelConsistentHash [TRACE] Position are: {3688=arrow-41664}
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Backups for arrow-41664 are [arrow-41664]
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] Nodes that need new backups are: []
2010-11-21 16:58:47 DistributionManagerImpl [TRACE] This node won't receive state
2010-11-21 16:58:47 DistributionManagerImpl [INFO] Not in same subspace, so ignoring leave event
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-41664: installing view [arrow-41664|2] [arrow-41664]
2010-11-21 16:58:47 InvertedLeaveTask [DEBUG] Starting leave rehash[enabled=false,isReceiver=true,isSender=true] on node arrow-41664
2010-11-21 16:58:47 InvertedLeaveTask [DEBUG] Starting leave rehash[enabled=false,isReceiver=true,isSender=true] on node arrow-41664
2010-11-21 16:58:47 InvertedLeaveTask [INFO] Completed leave rehash on node arrow-41664 in 7 milliseconds
2010-11-21 16:58:47 InvertedLeaveTask [INFO] Completed leave rehash on node arrow-41664 in 6 milliseconds
2010-11-21 16:58:47 TransactionTable [TRACE] Global transactions [] pertain to leavers list [arrow-44800, arrow-19518] and need to be killed
2010-11-21 16:58:47 GMS [DEBUG] arrow-41664: sending RESUME event
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-41664: received RESUME, sending STOP_FLUSH to all
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-41664: received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
2010-11-21 16:58:47 JGroupsDistSync [TRACE] Releasing ReclosableLatch [State = 1, empty queue] gate
2010-11-21 16:59:02 FLUSH [DEBUG] arrow-41664: suspect is arrow-44800, completed false, flushOkSet {}, flushMembers []
2010-11-21 16:59:02 RequestCorrelator [DEBUG] suspect=arrow-44800
SLAVE1:
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Starting distribution manager on arrow-19518
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? true
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Node topology info added(null). Topology info is TopologyInfo{address2TopologyInfo={arrow-44800=null}}
2010-11-21 16:58:46 DistributionManagerImpl [DEBUG] Setting joinComplete to false for node arrow-19518
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is AbstractConsistentHash{caches=null, topologyInfo=null}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 JoinTask [DEBUG] Commencing rehash on node: arrow-19518. Before start, dmi.joinComplete = false
2010-11-21 16:58:46 JoinTask [TRACE] Requesting old consistent hash from coordinator
2010-11-21 16:58:46 JGroupsTransport [TRACE] dests=[arrow-41664], command=RehashControlCommand{type=JOIN_REQ, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}, mode=SYNCHRONOUS, timeout=600000
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Replication task sending RehashControlCommand{type=JOIN_REQ, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to addresses [arrow-41664]
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] responses: [sender=arrow-41664, retval=SuccessfulResponse{responseValue=[arrow-41664]} , received=true, suspected=false]
2010-11-21 16:58:46 JoinTask [DEBUG] Retrieved old consistent hash address list [arrow-41664]
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {3688=arrow-41664}
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Installing new consistent hash DefaultConsistentHash{addresses ={493=arrow-19518, 3688=arrow-41664}, hash space =10240}
2010-11-21 16:58:46 RpcManagerImpl [TRACE] arrow-19518 broadcasting call RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to recipient list null
2010-11-21 16:58:46 JGroupsTransport [TRACE] dests=null, command=RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}, mode=SYNCHRONOUS, timeout=15000
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Replication task sending RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to addresses null
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [TRACE] Calling perform() on RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Informed of a JOIN by arrow-44800. Starting? false
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] New CH is DefaultConsistentHash{addresses ={493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}, hash space =10240}
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] real_dests=[arrow-44800, arrow-41664]
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] responses: [sender=arrow-44800, retval=ExceptionResponse, received=true, suspected=false]
[sender=arrow-41664, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
2010-11-21 16:58:46 RpcManagerImpl [ERROR] unexpected error while replicating
org.infinispan.manager.NamedCacheNotFoundException: Cache: volatileCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
2010-11-21 16:58:46 RpcManagerImpl [TRACE] arrow-19518 broadcasting call RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to recipient list null
2010-11-21 16:58:46 JGroupsTransport [TRACE] dests=null, command=RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}, mode=SYNCHRONOUS, timeout=15000
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Replication task sending RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-19518, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to addresses null
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] real_dests=[arrow-44800, arrow-41664]
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] responses: [sender=arrow-44800, retval=ExceptionResponse, received=true, suspected=false]
[sender=arrow-41664, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
2010-11-21 16:58:46 RpcManagerImpl [ERROR] unexpected error while replicating
org.infinispan.manager.NamedCacheNotFoundException: Cache: volatileCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
2010-11-21 16:58:46 JoinTask [ERROR] Caught exception!
org.infinispan.CacheException: org.infinispan.manager.NamedCacheNotFoundException: Cache: volatileCache
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:114)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:125)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:230)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:217)
at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:200)
at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:132)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:53)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:33)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.infinispan.manager.NamedCacheNotFoundException: Cache: volatileCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
... 3 more
2010-11-21 16:58:46 TransactionLoggerImpl [INFO] Stopping transaction logging
2010-11-21 16:58:46 DistributionManagerImpl [DEBUG] Setting joinComplete to true for node arrow-19518
2010-11-21 16:58:46 JoinTask [INFO] arrow-19518 completed join rehash in 78 milliseconds!
Unable to invoke method public void org.infinispan.distribution.DistributionManagerImpl.waitForJoinToComplete() throws java.lang.Throwable on object
org.infinispan.CacheException: Unable to invoke method public void org.infinispan.distribution.DistributionManagerImpl.waitForJoinToComplete() throws java.lang.Throwable on object
at org.infinispan.util.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:173)
at org.infinispan.factories.AbstractComponentRegistry$PrioritizedMethod.invoke(AbstractComponentRegistry.java:861)
at org.infinispan.factories.AbstractComponentRegistry.internalStart(AbstractComponentRegistry.java:680)
at org.infinispan.factories.AbstractComponentRegistry.start(AbstractComponentRegistry.java:582)
at org.infinispan.factories.ComponentRegistry.start(ComponentRegistry.java:148)
at org.infinispan.CacheDelegate.start(CacheDelegate.java:317)
at org.infinispan.manager.DefaultCacheManager.createCache(DefaultCacheManager.java:493)
at org.infinispan.manager.DefaultCacheManager.getCache(DefaultCacheManager.java:437)
at net.dataforte.infinipedia.Infinipedia.startCache(Infinipedia.java:137)
at net.dataforte.infinipedia.Infinipedia.main(Infinipedia.java:222)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.infinispan.util.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:170)
... 9 more
Caused by: org.infinispan.CacheException: Unexpected exception
at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:142)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:53)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:33)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.infinispan.CacheException: org.infinispan.manager.NamedCacheNotFoundException: Cache: volatileCache
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:114)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:125)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:230)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:217)
at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:200)
at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:132)
... 7 more
Caused by: org.infinispan.manager.NamedCacheNotFoundException: Cache: volatileCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
... 3 more
2010-11-21 16:58:46 JGroupsTransport [INFO] Disconnecting and closing JGroups Channel
2010-11-21 16:58:46 GMS [DEBUG] sending LEAVE request to arrow-41664 (local_addr=arrow-19518)
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [WARN] Cache named [volatileCache] exists but isn't in a state to handle invocations. Its state is FAILED.
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [WARN] Cache named [volatileCache] exists but isn't in a state to handle invocations. Its state is FAILED.
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [ERROR] Defined caches: []
2010-11-21 16:58:46 InboundInvocationHandlerImpl [INFO] Cache metadataCache is not defined. No point in waiting.
2010-11-21 16:58:46 InboundInvocationHandlerImpl [INFO] Cache named metadataCache does not exist on this cache manager!
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Unable to execute command, got invalid response
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Attempting to execute command: RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} [sender=arrow-44800]
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Enough waiting; replayIgnored = false, sr STATE_PREEXISTED
2010-11-21 16:58:46 InboundInvocationHandlerImpl [ERROR] Defined caches: []
2010-11-21 16:58:46 InboundInvocationHandlerImpl [INFO] Cache metadataCache is not defined. No point in waiting.
2010-11-21 16:58:46 InboundInvocationHandlerImpl [INFO] Cache named metadataCache does not exist on this cache manager!
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Unable to execute command, got invalid response
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-19518: received START_FLUSH but I am not flush participant, not responding
2010-11-21 16:58:47 GMS [DEBUG] arrow-19518:
2010-11-21 16:58:47 FD_SOCK [DEBUG] peer arrow-44800 closed socket gracefully
2010-11-21 16:58:47 FD_SOCK [DEBUG] ping_dest is arrow-41664, pingable_mbrs=[arrow-41664, arrow-19518]
2010-11-21 16:58:47 UDP [DEBUG] multicast socket closed
2010-11-21 16:58:47 UDP [DEBUG] receiver socket is closed, exception=java.net.SocketException: Socket closed
2010-11-21 16:58:47 UDP [DEBUG] multicast receiver thread terminated
2010-11-21 16:58:47 UDP [DEBUG] receiver socket is closed, exception=java.net.SocketException: Socket closed
2010-11-21 16:58:47 UDP [DEBUG] unicast receiver thread terminated
2010-11-21 16:58:47 FD_SOCK [DEBUG] socket to arrow-41664 was closed gracefully
2010-11-21 16:58:47 UDP [DEBUG] closing sockets and stopping threads
2010-11-21 16:58:47 JGroupsTransport [INFO] Stopping the RpcDispatcher
2010-11-21 16:58:47 ConstantObjectTable [TRACE] Externalizer reader and writer maps have been cleared and constant object table was stopped
2010-11-21 16:58:47 ComponentStatus [DEBUG] Ignoring call to stop() as current state is STOPPING
2010-11-21 16:58:47 GlobalComponentRegistry [TRACE] Reset volatile components. Registry now contains [org.infinispan.config.GlobalConfiguration, org.infinispan.jmx.CacheManagerJmxRegistration, java.lang.ClassLoader, org.infinispan.manager.EmbeddedCacheManager, org.infinispan.factories.GlobalComponentRegistry]
SLAVE2:
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Starting distribution manager on arrow-44800
2010-11-21 16:58:46 DistributionManagerImpl [DEBUG] Setting joinComplete to false for node arrow-44800
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {493=arrow-19518, 3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:46 JoinTask [DEBUG] Commencing rehash on node: arrow-44800. Before start, dmi.joinComplete = false
2010-11-21 16:58:46 JoinTask [TRACE] Requesting old consistent hash from coordinator
2010-11-21 16:58:46 JGroupsTransport [TRACE] dests=[arrow-41664], command=RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}, mode=SYNCHRONOUS, timeout=600000
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Replication task sending RehashControlCommand{type=JOIN_REQ, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to addresses [arrow-41664]
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] responses: [sender=arrow-41664, retval=SuccessfulResponse{responseValue=[arrow-41664]} , received=true, suspected=false]
2010-11-21 16:58:46 JoinTask [DEBUG] Retrieved old consistent hash address list [arrow-41664]
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {3688=arrow-41664}
2010-11-21 16:58:46 AbstractWheelConsistentHash [TRACE] Position are: {3688=arrow-41664, 6414=arrow-44800}
2010-11-21 16:58:46 DistributionManagerImpl [TRACE] Installing new consistent hash DefaultConsistentHash{addresses ={3688=arrow-41664, 6414=arrow-44800}, hash space =10240}
2010-11-21 16:58:46 RpcManagerImpl [TRACE] arrow-44800 broadcasting call RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to recipient list null
2010-11-21 16:58:46 JGroupsTransport [TRACE] dests=null, command=RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}, mode=SYNCHRONOUS, timeout=15000
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Replication task sending RehashControlCommand{type=JOIN_REHASH_START, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to addresses null
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] real_dests=[arrow-19518, arrow-41664]
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] responses: [sender=arrow-19518, retval=ExceptionResponse, received=true, suspected=false]
[sender=arrow-41664, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
2010-11-21 16:58:46 RpcManagerImpl [ERROR] unexpected error while replicating
org.infinispan.manager.NamedCacheNotFoundException: Cache: metadataCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
2010-11-21 16:58:46 RpcManagerImpl [TRACE] arrow-44800 broadcasting call RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to recipient list null
2010-11-21 16:58:46 JGroupsTransport [TRACE] dests=null, command=RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null}, mode=SYNCHRONOUS, timeout=15000
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] Replication task sending RehashControlCommand{type=JOIN_REHASH_END, sender=arrow-44800, state=null, oldConsistentHash=null, nodesLeft=null, consistentHash=null, txLogCommands=null, pendingPrepares=null, nodeTopologyInfo=null} to addresses null
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Wrote version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] real_dests=[arrow-19518, arrow-41664]
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 VersionAwareMarshaller [TRACE] Read version 420
2010-11-21 16:58:46 CommandAwareRpcDispatcher [TRACE] responses: [sender=arrow-19518, retval=ExceptionResponse, received=true, suspected=false]
[sender=arrow-41664, retval=SuccessfulResponse{responseValue=null} , received=true, suspected=false]
2010-11-21 16:58:46 RpcManagerImpl [ERROR] unexpected error while replicating
org.infinispan.manager.NamedCacheNotFoundException: Cache: metadataCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
2010-11-21 16:58:46 JoinTask [ERROR] Caught exception!
org.infinispan.CacheException: org.infinispan.manager.NamedCacheNotFoundException: Cache: metadataCache
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:114)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:125)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:230)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:217)
at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:200)
at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:132)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:53)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:33)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.infinispan.manager.NamedCacheNotFoundException: Cache: metadataCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
... 3 more
2010-11-21 16:58:46 TransactionLoggerImpl [INFO] Stopping transaction logging
2010-11-21 16:58:46 DistributionManagerImpl [DEBUG] Setting joinComplete to true for node arrow-44800
2010-11-21 16:58:46 JoinTask [INFO] arrow-44800 completed join rehash in 62 milliseconds!
Unable to invoke method public void org.infinispan.distribution.DistributionManagerImpl.waitForJoinToComplete() throws java.lang.Throwable on object
org.infinispan.CacheException: Unable to invoke method public void org.infinispan.distribution.DistributionManagerImpl.waitForJoinToComplete() throws java.lang.Throwable on object
at org.infinispan.util.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:173)
at org.infinispan.factories.AbstractComponentRegistry$PrioritizedMethod.invoke(AbstractComponentRegistry.java:861)
at org.infinispan.factories.AbstractComponentRegistry.internalStart(AbstractComponentRegistry.java:680)
at org.infinispan.factories.AbstractComponentRegistry.start(AbstractComponentRegistry.java:582)
at org.infinispan.factories.ComponentRegistry.start(ComponentRegistry.java:148)
at org.infinispan.CacheDelegate.start(CacheDelegate.java:317)
at org.infinispan.manager.DefaultCacheManager.createCache(DefaultCacheManager.java:493)
at org.infinispan.manager.DefaultCacheManager.getCache(DefaultCacheManager.java:437)
at net.dataforte.infinipedia.Infinipedia.startCache(Infinipedia.java:138)
at net.dataforte.infinipedia.Infinipedia.main(Infinipedia.java:222)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.infinispan.util.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:170)
... 9 more
Caused by: org.infinispan.CacheException: Unexpected exception
at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:142)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:53)
at org.infinispan.distribution.RehashTask.call(RehashTask.java:33)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.infinispan.CacheException: org.infinispan.manager.NamedCacheNotFoundException: Cache: metadataCache
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:114)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:125)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:230)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:217)
at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:200)
at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:132)
... 7 more
Caused by: org.infinispan.manager.NamedCacheNotFoundException: Cache: metadataCache
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:72)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:177)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:149)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:575)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:486)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:362)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:771)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:136)
at org.jgroups.JChannel.up(JChannel.java:1453)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:887)
at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:483)
at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:151)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
at org.jgroups.protocols.FC.up(FC.java:494)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:888)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
at org.jgroups.protocols.UNICAST.up(UNICAST.java:309)
at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:813)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:671)
at org.jgroups.protocols.BARRIER.up(BARRIER.java:120)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:177)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:270)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:210)
at org.jgroups.protocols.Discovery.up(Discovery.java:283)
at org.jgroups.protocols.PING.up(PING.java:67)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1009)
at org.jgroups.protocols.TP.access$100(TP.java:56)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1549)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1531)
... 3 more
2010-11-21 16:58:46 JGroupsTransport [INFO] Disconnecting and closing JGroups Channel
2010-11-21 16:58:46 GMS [DEBUG] sending LEAVE request to arrow-41664 (local_addr=arrow-44800)
2010-11-21 16:58:47 FLUSH [DEBUG] arrow-44800: received START_FLUSH but I am not flush participant, not responding
2010-11-21 16:58:47 GMS [DEBUG] arrow-44800:
2010-11-21 16:58:47 UDP [DEBUG] receiver socket is closed, exception=java.net.SocketException: Socket closed
2010-11-21 16:58:47 UDP [DEBUG] multicast receiver thread terminated
2010-11-21 16:58:47 UDP [DEBUG] multicast socket closed
2010-11-21 16:58:47 UDP [DEBUG] receiver socket is closed, exception=java.net.SocketException: Socket closed
2010-11-21 16:58:47 UDP [DEBUG] unicast receiver thread terminated
2010-11-21 16:58:47 UDP [DEBUG] closing sockets and stopping threads
2010-11-21 16:58:47 FD_SOCK [DEBUG] socket to arrow-41664 was closed gracefully
2010-11-21 16:58:47 JGroupsTransport [INFO] Stopping the RpcDispatcher
2010-11-21 16:58:47 ConstantObjectTable [TRACE] Externalizer reader and writer maps have been cleared and constant object table was stopped
2010-11-21 16:58:47 ComponentStatus [DEBUG] Ignoring call to stop() as current state is STOPPING
2010-11-21 16:58:47 GlobalComponentRegistry [TRACE] Reset volatile components. Registry now contains [org.infinispan.config.GlobalConfiguration, org.infinispan.jmx.CacheManagerJmxRegistration, java.lang.ClassLoader, org.infinispan.manager.EmbeddedCacheManager, org.infinispan.factories.GlobalComponentRegistry]
> Concurrent startup leading to rehashing issues
> ----------------------------------------------
>
> Key: ISPN-765
> URL: https://jira.jboss.org/browse/ISPN-765
> Project: Infinispan
> Issue Type: Bug
> Components: Distributed Cache
> Affects Versions: 4.2.0.BETA1
> Reporter: Galder Zamarreño
> Assignee: Mircea Markus
> Fix For: 4.2.0.CR1
>
>
> From ISPN-762, there seems to be a rehashing problem when several distributed caches are started concurrently:
> Logs can be found in: https://jira.jboss.org/secure/attachment/12338527/topologycache.diff
> "Even though all the caches are defined in the right place, there is still a problem during starting 3 nodes at a time. Look at the errors coming from the log files:
> * wp-60814 log:
> 2010-11-08 14:29:26,687 INFO [org.infinispan.distribution.DistributionManagerImpl] (Incoming-2,wp-60814) This is a JOIN event! Wait for notification from new joiner wp-59660
> 2010-11-08 14:31:26,668 ERROR [org.infinispan.distribution.JoinTask] (Rehasher-wp-60814) Caught exception!
> org.infinispan.CacheException: org.infinispan.util.concurrent.TimeoutException: Timed out after 120 seconds waiting for a response from wp-34493
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommands(CommandAwareRpcDispatcher.java:122)
> at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:403)
> at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:101)
> at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:125)
> at org.infinispan.distribution.JoinTask.retrieveOldCH(JoinTask.java:192)
> at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:87)
> at org.infinispan.distribution.RehashTask.call(RehashTask.java:53)
> at org.infinispan.distribution.RehashTask.call(RehashTask.java:33)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:619)
> Caused by: org.infinispan.util.concurrent.TimeoutException: Timed out after 120 seconds waiting for a response from wp-34493
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher$ReplicationTask.call(CommandAwareRpcDispatcher.java:304)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommands(CommandAwareRpcDispatcher.java:120)
> ... 12 more
> * wp-34493 log:
> 2010-11-08 14:29:26,654 INFO [org.infinispan.distribution.DistributionManagerImpl] (Incoming-2,wp-34493) This is a JOIN event! Wait for notification from
> new joiner wp-59660
> 2010-11-08 14:29:36,759 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (InfinispanServer-Main) Execution error:
> org.infinispan.util.concurrent.TimeoutException: Timed out waiting for valid responses!
> at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:421)
> at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:101)
> ...
> at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273)
> at org.infinispan.CacheDelegate.putIfAbsent(CacheDelegate.java:453)
> at org.infinispan.CacheSupport.putIfAbsent(CacheSupport.java:40)
> at org.infinispan.server.hotrod.HotRodServer$$anonfun$1.apply(HotRodServer.scala:85)
> at org.infinispan.server.hotrod.HotRodServer$$anonfun$1.apply(HotRodServer.scala:75)
> at org.infinispan.server.hotrod.HotRodServer.isViewUpdated(HotRodServer.scala:102)
> at org.infinispan.server.hotrod.HotRodServer.org$infinispan$server$hotrod$HotRodServer$$updateTopologyView(HotRodServer.scala:97)
> at org.infinispan.server.hotrod.HotRodServer.addSelfToTopologyView(HotRodServer.scala:75)
> at org.infinispan.server.hotrod.HotRodServer.startTransport(HotRodServer.scala:63)
> at org.infinispan.server.core.AbstractProtocolServer.start(AbstractProtocolServer.scala:70)
> at org.infinispan.server.hotrod.HotRodServer.start(HotRodServer.scala:44)
> ...
> * wp-59660 log:
> 2010-11-08 14:29:26,699 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (InfinispanServer-Main) Received new cluster view: [wp-34493|2] [wp-34493, wp-60814, wp-59660]
> 2010-11-08 14:29:26,756 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (InfinispanServer-Main) Cache local address is wp-59660, physical addresses are [10.0.36.136:34302]
> 2010-11-08 14:29:26,851 ERROR [org.infinispan.remoting.InboundInvocationHandlerImpl] (OOB-2,wp-59660) Defined caches: [___hotRodTopologyCache]
> 2010-11-08 14:29:26,851 INFO [org.infinispan.remoting.InboundInvocationHandlerImpl] (OOB-2,wp-59660) Will try and wait for the cache to start
> 2010-11-08 14:29:56,864 INFO [org.infinispan.remoting.InboundInvocationHandlerImpl] (OOB-2,wp-59660) Cache named ___hotRodTopologyCache does not exist on this cache manager!
> 2010-11-08 14:49:26,897 ERROR [org.infinispan.distribution.JoinTask] (Rehasher-wp-59660) Caught exception!
> org.infinispan.CacheException: Unable to retrieve old consistent hash from coordinator even after several attempts at sleeping and retrying!
> at org.infinispan.distribution.JoinTask.retrieveOldCH(JoinTask.java:218)
> at org.infinispan.distribution.JoinTask.performRehash(JoinTask.java:87)
> at org.infinispan.distribution.RehashTask.call(RehashTask.java:53)
> at org.infinispan.distribution.RehashTask.call(RehashTask.java:33)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:619)
> The first node reaches rehashRpcTimeout=120000 while waiting on the old hash. The second one reaches 10s timeout during adding himself to the topology view. And the third one fails on retrieving old hash, but after much longer time = 20min.
> It looks as though we had a kind of deadlock."
--
This message is automatically generated by JIRA.
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the infinispan-issues
mailing list