[
https://jira.jboss.org/browse/ISPN-765?page=com.atlassian.jira.plugin.sys...
]
Tristan Tarrant edited comment on ISPN-765 at 11/29/10 8:11 AM:
----------------------------------------------------------------
<snipped> and converted to attachments
was (Author: NadirX):
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
Priority: Critical
Fix For: 4.2.0.CR3, 4.2.0.Final
Attachments: infinispan-jgroups.xml, infinispan.xml
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