Pavel Pereslegin created IGNITE-9238:
----------------------------------------
Summary: Test
GridTaskFailoverAffinityRunTest.testNodeRestartClient hangs when coordinator
forces client to reconnect on grid startup.
Key: IGNITE-9238
URL: https://issues.apache.org/jira/browse/IGNITE-9238
Project: Ignite
Issue Type: Bug
Affects Versions: 2.6
Reporter: Pavel Pereslegin
Assignee: Pavel Pereslegin
Fix For: 2.7
Example of such hang on TC:
https://ci.ignite.apache.org/viewLog.html?buildId=1605243&tab=buildResultsDiv&buildTypeId=IgniteTests24Java8_ComputeGrid
Log output:
{noformat}
[2018-08-07 12:20:09,804][WARN
][sys-#12799%internal.GridTaskFailoverAffinityRunTest1%][GridCachePartitionExchangeManager]
Client node tries to connect but its exchange info is cleaned up from exchange
history. Consider increasing 'IGNITE_EXCHANGE_HISTORY_SIZE' property or start
clients in smaller batches. Current settings and versions:
[IGNITE_EXCHANGE_HISTORY_SIZE=1000, initVer=AffinityTopologyVersion [topVer=3,
minorTopVer=0], readyVer=AffinityTopologyVersion [topVer=4, minorTopVer=0]].
[2018-08-07 12:20:09,804][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=511d5932-5f22-4919-807d-575c7f600001,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=3, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644409739, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], durationFromInit=21]
[2018-08-07 12:20:09,806][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][time]
Finished exchange init [topVer=AffinityTopologyVersion [topVer=3,
minorTopVer=0], crd=true]
[2018-08-07 12:20:09,807][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=4, minorTopVer=0], force=false, evt=NODE_JOINED,
node=6b9a7a1d-07bf-4d20-882a-8462ada00003]
[2018-08-07 12:20:09,811][INFO
][sys-#12798%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Finish exchange future [startVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=0],
err=null]
[2018-08-07 12:20:09,813][INFO
][sys-#12798%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=a3206c1f-6d57-4fd6-8aa5-e22f3b400002,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode
[id=a3206c1f-6d57-4fd6-8aa5-e22f3b400002, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47503], discPort=47503, order=4, intOrder=4,
lastExchangeTime=1533644409779, loc=true, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], durationFromInit=41]
[2018-08-07 12:20:09,814][INFO
][grid-starter-testNodeRestartClient-1][GridTaskFailoverAffinityRunTest1] To
start Console Management & Monitoring run ignitevisorcmd.{sh|bat}
[2018-08-07 12:20:09,815][INFO
][grid-starter-testNodeRestartClient-1][GridTaskFailoverAffinityRunTest1]
[2018-08-07 12:20:09,815][INFO
][grid-starter-testNodeRestartClient-1][GridTaskFailoverAffinityRunTest1]
>>> +-------------------------------------------------------------------------------+
>>> Ignite ver.
>>> 2.7.0-SNAPSHOT#20180807-sha1:e96616f580930f267eab44f75d410fa29a876bcb
>>> +-------------------------------------------------------------------------------+
>>> OS name: Linux 4.4.0-128-generic amd64
>>> CPU(s): 5
>>> Heap: 2.0GB
>>> VM name: 20126@8790182f15a5
>>> Ignite instance name: internal.GridTaskFailoverAffinityRunTest1
>>> Local node [ID=511D5932-5F22-4919-807D-575C7F600001, order=2,
>>> clientMode=false]
>>> Local node addresses: [127.0.0.1]
>>> Local ports: TCP:10801 TCP:45821 TCP:47501
[2018-08-07 12:20:09,816][INFO
][grid-starter-testNodeRestartClient-1][GridDiscoveryManager] Topology snapshot
[ver=2, servers=1, clients=1, CPUs=5, offheap=0.1GB, heap=2.0GB]
[2018-08-07 12:20:09,816][INFO
][grid-starter-testNodeRestartClient-1][GridDiscoveryManager] ^-- Node
[id=511D5932-5F22-4919-807D-575C7F600001, clusterState=ACTIVE]
[2018-08-07 12:20:09,816][INFO
][grid-starter-testNodeRestartClient-1][GridDiscoveryManager] Data Regions
Configured:
[2018-08-07 12:20:09,816][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][GridCachePartitionExchangeManager]
Rebalancing scheduled [order=[ignite-sys-cache, default],
top=AffinityTopologyVersion [topVer=4, minorTopVer=0], force=false,
evt=NODE_JOINED, node=a3206c1f-6d57-4fd6-8aa5-e22f3b400002]
[2018-08-07 12:20:09,816][INFO
][grid-starter-testNodeRestartClient-1][GridDiscoveryManager] ^-- default
[initSize=256.0 MiB, maxSize=18.9 GiB, persistenceEnabled=false]
[2018-08-07 12:20:09,817][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionDemander]
Starting rebalancing [grp=ignite-sys-cache, mode=SYNC,
fromNode=511d5932-5f22-4919-807d-575c7f600001, partitionsCount=100,
topology=AffinityTopologyVersion [topVer=4, minorTopVer=0], rebalanceId=1]
[2018-08-07 12:20:09,817][INFO ][grid-starter-testNodeRestartClient-1][root]
Node started with the following configuration
[id=511d5932-5f22-4919-807d-575c7f600001, marshaller=BinaryMarshaller [],
discovery=TcpDiscoverySpi [addrRslvr=null, sockTimeout=5000, ackTimeout=5000,
marsh=JdkMarshaller
[clsFilter=org.apache.ignite.marshaller.MarshallerUtils$1@4ce70299],
reconCnt=10, reconDelay=2000, maxAckTimeout=600000, forceSrvMode=false,
clientReconnectDisabled=false, internalLsnr=null], binaryCfg=null, lateAff=true]
[2018-08-07 12:20:09,821][INFO
][sys-#12797%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Received full message, will finish exchange
[node=511d5932-5f22-4919-807d-575c7f600001, resVer=AffinityTopologyVersion
[topVer=4, minorTopVer=0]]
[2018-08-07 12:20:09,822][INFO
][sys-#12797%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Received full message, need merge [curFut=AffinityTopologyVersion [topVer=3,
minorTopVer=0], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=0]]
[2018-08-07 12:20:09,822][INFO
][sys-#12797%internal.GridTaskFailoverAffinityRunTest3%][GridCachePartitionExchangeManager]
Merge exchange future on finish [curFut=AffinityTopologyVersion [topVer=3,
minorTopVer=0], mergedFut=AffinityTopologyVersion [topVer=4, minorTopVer=0],
evt=NODE_JOINED, evtNode=a3206c1f-6d57-4fd6-8aa5-e22f3b400002,
evtNodeClient=false]
[2018-08-07 12:20:09,823][INFO
][utility-#12803%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionDemander]
Completed (final) rebalancing [fromNode=511d5932-5f22-4919-807d-575c7f600001,
cacheOrGroup=ignite-sys-cache, topology=AffinityTopologyVersion [topVer=4,
minorTopVer=0], time=10 ms]
[2018-08-07 12:20:09,823][INFO
][utility-#12803%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionDemander]
Completed rebalance future: RebalanceFuture [grp=CacheGroupContext
[grp=ignite-sys-cache], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], rebalanceId=1]
[2018-08-07 12:20:09,823][INFO
][utility-#12803%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionDemander]
Starting rebalancing [grp=default, mode=SYNC,
fromNode=511d5932-5f22-4919-807d-575c7f600001, partitionsCount=691,
topology=AffinityTopologyVersion [topVer=4, minorTopVer=0], rebalanceId=1]
[2018-08-07 12:20:09,826][INFO
][sys-#12804%internal.GridTaskFailoverAffinityRunTest0%][GridDeploymentLocalStore]
Class locally deployed: class org.apache.ignite.IgniteCheckedException
[2018-08-07 12:20:09,829][INFO
][sys-#12797%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finish exchange future [startVer=AffinityTopologyVersion [topVer=3,
minorTopVer=0], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=0],
err=null]
[2018-08-07 12:20:09,831][INFO
][sys-#12807%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionDemander]
Completed (final) rebalancing [fromNode=511d5932-5f22-4919-807d-575c7f600001,
cacheOrGroup=default, topology=AffinityTopologyVersion [topVer=4,
minorTopVer=0], time=10 ms]
[2018-08-07 12:20:09,831][INFO
][sys-#12807%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionDemander]
Completed rebalance future: RebalanceFuture [grp=CacheGroupContext
[grp=default], topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0],
rebalanceId=1]
[2018-08-07 12:20:09,834][INFO
][grid-starter-testNodeRestartClient-2][GridTaskFailoverAffinityRunTest2] To
start Console Management & Monitoring run ignitevisorcmd.{sh|bat}
[2018-08-07 12:20:09,834][INFO
][grid-starter-testNodeRestartClient-2][GridTaskFailoverAffinityRunTest2]
[2018-08-07 12:20:09,834][INFO
][grid-starter-testNodeRestartClient-2][GridTaskFailoverAffinityRunTest2]
>>> +-------------------------------------------------------------------------------+
>>> Ignite ver.
>>> 2.7.0-SNAPSHOT#20180807-sha1:e96616f580930f267eab44f75d410fa29a876bcb
>>> +-------------------------------------------------------------------------------+
>>> OS name: Linux 4.4.0-128-generic amd64
>>> CPU(s): 5
>>> Heap: 2.0GB
>>> VM name: 20126@8790182f15a5
>>> Ignite instance name: internal.GridTaskFailoverAffinityRunTest2
>>> Local node [ID=A3206C1F-6D57-4FD6-8AA5-E22F3B400002, order=4,
>>> clientMode=false]
>>> Local node addresses: [127.0.0.1]
>>> Local ports: TCP:10803 TCP:45822 TCP:47503
[2018-08-07 12:20:09,836][INFO
][grid-starter-testNodeRestartClient-2][GridDiscoveryManager] Topology snapshot
[ver=4, servers=3, clients=1, CPUs=5, offheap=0.1GB, heap=2.0GB]
[2018-08-07 12:20:09,836][INFO
][grid-starter-testNodeRestartClient-2][GridDiscoveryManager] ^-- Node
[id=A3206C1F-6D57-4FD6-8AA5-E22F3B400002, clusterState=ACTIVE]
[2018-08-07 12:20:09,836][INFO
][grid-starter-testNodeRestartClient-2][GridDiscoveryManager] Data Regions
Configured:
[2018-08-07 12:20:09,837][INFO
][grid-starter-testNodeRestartClient-2][GridDiscoveryManager] ^-- default
[initSize=256.0 MiB, maxSize=18.9 GiB, persistenceEnabled=false]
[2018-08-07 12:20:09,837][INFO ][grid-starter-testNodeRestartClient-2][root]
Node started with the following configuration
[id=a3206c1f-6d57-4fd6-8aa5-e22f3b400002, marshaller=BinaryMarshaller [],
discovery=TcpDiscoverySpi [addrRslvr=null, sockTimeout=5000, ackTimeout=5000,
marsh=JdkMarshaller
[clsFilter=org.apache.ignite.marshaller.MarshallerUtils$1@2a10d3f1],
reconCnt=10, reconDelay=2000, maxAckTimeout=600000, forceSrvMode=false,
clientReconnectDisabled=false, internalLsnr=null], binaryCfg=null, lateAff=true]
[2018-08-07 12:20:09,838][INFO
][sys-#12797%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=6b9a7a1d-07bf-4d20-882a-8462ada00003,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=3, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644409779, loc=true, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], durationFromInit=71]
[2018-08-07 12:20:09,839][INFO
][sys-#12804%internal.GridTaskFailoverAffinityRunTest0%][GridDhtPartitionsExchangeFuture]
Finish exchange future [startVer=AffinityTopologyVersion [topVer=3,
minorTopVer=0], resVer=null, err=class
org.apache.ignite.internal.IgniteNeedReconnectException: Node need try to
reconnect [nodeId=7406e013-ddf7-44d1-b4e2-2ff707800000]]
[2018-08-07 12:20:09,840][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridCachePartitionExchangeManager]
Rebalancing scheduled [order=[ignite-sys-cache, default],
top=AffinityTopologyVersion [topVer=4, minorTopVer=0], force=false,
evt=NODE_JOINED, node=6b9a7a1d-07bf-4d20-882a-8462ada00003]
[2018-08-07 12:20:09,840][INFO
][sys-#12804%internal.GridTaskFailoverAffinityRunTest0%][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=7406e013-ddf7-44d1-b4e2-2ff707800000,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=3, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], done=true], topVer=null, durationFromInit=40]
[2018-08-07 12:20:09,840][WARN
][exchange-worker-#12674%internal.GridTaskFailoverAffinityRunTest0%][GridCachePartitionExchangeManager]
Local node received IgniteClientDisconnectedCheckedException or
IgniteNeedReconnectException exception but doesn't support reconnect, stopping
node: Node need try to reconnect [nodeId=7406e013-ddf7-44d1-b4e2-2ff707800000]
[2018-08-07
12:20:09,843][ERROR][exchange-worker-#12674%internal.GridTaskFailoverAffinityRunTest0%][IgniteTestResources]
Critical system error detected. Will be handled accordingly to configured
handler [hnd=class o.a.i.failure.NoOpFailureHandler, failureCtx=FailureContext
[type=SYSTEM_WORKER_TERMINATION, err=java.lang.IllegalStateException: Thread
partition-exchanger is terminated unexpectedly]]
java.lang.IllegalStateException: Thread partition-exchanger is terminated
unexpectedly
at
org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2388)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
at java.lang.Thread.run(Thread.java:748)
[2018-08-07 12:20:09,840][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionDemander]
Starting rebalancing [grp=ignite-sys-cache, mode=SYNC,
fromNode=511d5932-5f22-4919-807d-575c7f600001, partitionsCount=100,
topology=AffinityTopologyVersion [topVer=4, minorTopVer=0], rebalanceId=1]
[2018-08-07 12:20:09,849][INFO
][utility-#12811%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionDemander]
Completed (final) rebalancing [fromNode=511d5932-5f22-4919-807d-575c7f600001,
cacheOrGroup=ignite-sys-cache, topology=AffinityTopologyVersion [topVer=4,
minorTopVer=0], time=0 ms]
[2018-08-07 12:20:09,849][INFO
][utility-#12811%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionDemander]
Completed rebalance future: RebalanceFuture [grp=CacheGroupContext
[grp=ignite-sys-cache], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], rebalanceId=1]
[2018-08-07 12:20:09,850][INFO
][utility-#12811%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionDemander]
Starting rebalancing [grp=default, mode=SYNC,
fromNode=511d5932-5f22-4919-807d-575c7f600001, partitionsCount=668,
topology=AffinityTopologyVersion [topVer=4, minorTopVer=0], rebalanceId=1]
[2018-08-07 12:20:09,863][INFO
][sys-#12814%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionDemander]
Completed (final) rebalancing [fromNode=511d5932-5f22-4919-807d-575c7f600001,
cacheOrGroup=default, topology=AffinityTopologyVersion [topVer=4,
minorTopVer=0], time=21 ms]
[2018-08-07 12:20:09,864][INFO
][sys-#12814%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionDemander]
Completed rebalance future: RebalanceFuture [grp=CacheGroupContext
[grp=default], topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0],
rebalanceId=1]
[2018-08-07 12:20:09,868][INFO
][grid-starter-testNodeRestartClient-3][GridTaskFailoverAffinityRunTest3] To
start Console Management & Monitoring run ignitevisorcmd.{sh|bat}
[2018-08-07 12:20:09,868][INFO
][grid-starter-testNodeRestartClient-3][GridTaskFailoverAffinityRunTest3]
[2018-08-07 12:20:09,869][INFO
][grid-starter-testNodeRestartClient-3][GridTaskFailoverAffinityRunTest3]
>>> +-------------------------------------------------------------------------------+
>>> Ignite ver.
>>> 2.7.0-SNAPSHOT#20180807-sha1:e96616f580930f267eab44f75d410fa29a876bcb
>>> +-------------------------------------------------------------------------------+
>>> OS name: Linux 4.4.0-128-generic amd64
>>> CPU(s): 5
>>> Heap: 2.0GB
>>> VM name: 20126@8790182f15a5
>>> Ignite instance name: internal.GridTaskFailoverAffinityRunTest3
>>> Local node [ID=6B9A7A1D-07BF-4D20-882A-8462ADA00003, order=3,
>>> clientMode=false]
>>> Local node addresses: [127.0.0.1]
>>> Local ports: TCP:10802 TCP:45823 TCP:47502
[2018-08-07 12:20:09,870][INFO
][grid-starter-testNodeRestartClient-3][GridDiscoveryManager] Topology snapshot
[ver=3, servers=2, clients=1, CPUs=5, offheap=0.1GB, heap=2.0GB]
[2018-08-07 12:20:09,870][INFO
][grid-starter-testNodeRestartClient-3][GridDiscoveryManager] ^-- Node
[id=6B9A7A1D-07BF-4D20-882A-8462ADA00003, clusterState=ACTIVE]
[2018-08-07 12:20:09,871][INFO
][grid-starter-testNodeRestartClient-3][GridDiscoveryManager] Data Regions
Configured:
[2018-08-07 12:20:09,871][INFO
][grid-starter-testNodeRestartClient-3][GridDiscoveryManager] ^-- default
[initSize=256.0 MiB, maxSize=18.9 GiB, persistenceEnabled=false]
[2018-08-07 12:20:09,871][INFO ][grid-starter-testNodeRestartClient-3][root]
Node started with the following configuration
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, marshaller=BinaryMarshaller [],
discovery=TcpDiscoverySpi [addrRslvr=null, sockTimeout=5000, ackTimeout=5000,
marsh=JdkMarshaller
[clsFilter=org.apache.ignite.marshaller.MarshallerUtils$1@55f3cf54],
reconCnt=10, reconDelay=2000, maxAckTimeout=600000, forceSrvMode=false,
clientReconnectDisabled=false, internalLsnr=null], binaryCfg=null, lateAff=true]
[2018-08-07 12:20:09,873][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][root] Waiting
for topology map update
[igniteInstanceName=internal.GridTaskFailoverAffinityRunTest3, cache=default,
cacheId=1544803905, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0],
p=0, affNodesCnt=2, ownersCnt=2,
affNodes=[a3206c1f-6d57-4fd6-8aa5-e22f3b400002,
6b9a7a1d-07bf-4d20-882a-8462ada00003],
owners=[511d5932-5f22-4919-807d-575c7f600001,
6b9a7a1d-07bf-4d20-882a-8462ada00003], topFut=GridDhtPartitionsExchangeFuture
[firstDiscoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644409779, loc=true, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], topVer=3, nodeId8=6b9a7a1d, msg=null, type=NODE_JOINED,
tstamp=1533644409759], crd=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], exchId=GridDhtPartitionExchangeId
[topVer=AffinityTopologyVersion [topVer=3, minorTopVer=0],
discoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644409779, loc=true, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], topVer=3, nodeId8=6b9a7a1d, msg=null, type=NODE_JOINED,
tstamp=1533644409759], nodeId=6b9a7a1d, evt=NODE_JOINED], added=true,
initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
hash=654856101], init=true, lastVer=null,
partReleaseFut=AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]PartitionReleaseFuture [topVer=,
futures=[ExplicitLockReleaseFuture [topVer=, futures=[]],
AtomicUpdateReleaseFuture [topVer=, futures=[]], DataStreamerReleaseFuture
[topVer=, futures=[]], LocalTxReleaseFuture [topVer=, futures=[]],
AllTxReleaseFuture [topVer=, futures=[RemoteTxReleaseFuture [topVer=,
futures=[]]]]]], exchActions=null, affChangeMsg=null, initTs=1533644409759,
centralizedAff=false, forceAffReassignment=false, exchangeLocE=null,
cacheChangeFailureMsgSent=false, done=true, state=DONE, evtLatch=0,
remaining=HashSet [511d5932-5f22-4919-807d-575c7f600001],
super=GridFutureAdapter [ignoreInterrupts=false, state=DONE,
res=AffinityTopologyVersion [topVer=4, minorTopVer=0], hash=1958488372]],
locNode=TcpDiscoveryNode [id=6b9a7a1d-07bf-4d20-882a-8462ada00003,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502],
discPort=47502, order=3, intOrder=3, lastExchangeTime=1533644409779, loc=true,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]]
[2018-08-07 12:20:10,883][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][root] Waiting
for topology map update
[igniteInstanceName=internal.GridTaskFailoverAffinityRunTest3, cache=default,
cacheId=1544803905, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0],
p=0, affNodesCnt=2, ownersCnt=2,
affNodes=[a3206c1f-6d57-4fd6-8aa5-e22f3b400002,
6b9a7a1d-07bf-4d20-882a-8462ada00003],
owners=[511d5932-5f22-4919-807d-575c7f600001,
6b9a7a1d-07bf-4d20-882a-8462ada00003], topFut=GridDhtPartitionsExchangeFuture
[firstDiscoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644410787, loc=true, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], topVer=3, nodeId8=6b9a7a1d, msg=null, type=NODE_JOINED,
tstamp=1533644409759], crd=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], exchId=GridDhtPartitionExchangeId
[topVer=AffinityTopologyVersion [topVer=3, minorTopVer=0],
discoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644410787, loc=true, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], topVer=3, nodeId8=6b9a7a1d, msg=null, type=NODE_JOINED,
tstamp=1533644409759], nodeId=6b9a7a1d, evt=NODE_JOINED], added=true,
initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
hash=654856101], init=true, lastVer=null,
partReleaseFut=AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]AffinityTopologyVersion [topVer=3,
minorTopVer=0]PartitionReleaseFuture [topVer=,
futures=[ExplicitLockReleaseFuture [topVer=, futures=[]],
AtomicUpdateReleaseFuture [topVer=, futures=[]], DataStreamerReleaseFuture
[topVer=, futures=[]], LocalTxReleaseFuture [topVer=, futures=[]],
AllTxReleaseFuture [topVer=, futures=[RemoteTxReleaseFuture [topVer=,
futures=[]]]]]], exchActions=null, affChangeMsg=null, initTs=1533644409759,
centralizedAff=false, forceAffReassignment=false, exchangeLocE=null,
cacheChangeFailureMsgSent=false, done=true, state=DONE, evtLatch=0,
remaining=HashSet [511d5932-5f22-4919-807d-575c7f600001],
super=GridFutureAdapter [ignoreInterrupts=false, state=DONE,
res=AffinityTopologyVersion [topVer=4, minorTopVer=0], hash=1958488372]],
locNode=TcpDiscoveryNode [id=6b9a7a1d-07bf-4d20-882a-8462ada00003,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502],
discPort=47502, order=3, intOrder=3, lastExchangeTime=1533644410787, loc=true,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]]
[2018-08-07 12:20:11,361][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][time]
Started exchange init [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], crd=true, evt=DISCOVERY_CUSTOM_EVT,
evtNode=511d5932-5f22-4919-807d-575c7f600001,
customEvt=CacheAffinityChangeMessage
[id=ac255541561-79c0720f-9c27-432a-8af7-32f26ff16b00,
topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0], exchId=null,
partsMsg=null, exchangeNeeded=true], allowMerge=false]
[2018-08-07 12:20:11,363][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][time]
Started exchange init [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT,
evtNode=511d5932-5f22-4919-807d-575c7f600001,
customEvt=CacheAffinityChangeMessage
[id=ac255541561-79c0720f-9c27-432a-8af7-32f26ff16b00,
topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0], exchId=null,
partsMsg=null, exchangeNeeded=true], allowMerge=false]
[2018-08-07 12:20:11,364][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][time]
Started exchange init [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT,
evtNode=511d5932-5f22-4919-807d-575c7f600001,
customEvt=CacheAffinityChangeMessage
[id=ac255541561-79c0720f-9c27-432a-8af7-32f26ff16b00,
topVer=AffinityTopologyVersion [topVer=4, minorTopVer=0], exchId=null,
partsMsg=null, exchangeNeeded=true], allowMerge=false]
[2018-08-07 12:20:11,435][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA]
[2018-08-07 12:20:11,449][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA]
[2018-08-07 12:20:11,464][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA]
[2018-08-07 12:20:11,464][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Finished waiting for partitions release latch: ServerLatch [permits=0,
pendingAcks=HashSet [], super=CompletableLatch [id=exchange,
topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]]]
[2018-08-07 12:20:11,465][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA]
[2018-08-07 12:20:11,466][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][time]
Finished exchange init [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], crd=true]
[2018-08-07 12:20:11,466][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Finished waiting for partitions release latch: ClientLatch
[coordinator=TcpDiscoveryNode [id=511d5932-5f22-4919-807d-575c7f600001,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47501],
discPort=47501, order=2, intOrder=2, lastExchangeTime=1533644409759, loc=false,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false], ackSent=true,
super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1]]]
[2018-08-07 12:20:11,467][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA]
[2018-08-07 12:20:11,467][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finished waiting for partitions release latch: ClientLatch
[coordinator=TcpDiscoveryNode [id=511d5932-5f22-4919-807d-575c7f600001,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47501],
discPort=47501, order=2, intOrder=2, lastExchangeTime=1533644409749, loc=false,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false], ackSent=true,
super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1]]]
[2018-08-07 12:20:11,468][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA]
[2018-08-07 12:20:11,469][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][time]
Finished exchange init [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], crd=false]
[2018-08-07 12:20:11,469][INFO
][sys-#12796%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Coordinator received single message [ver=AffinityTopologyVersion [topVer=4,
minorTopVer=1], node=a3206c1f-6d57-4fd6-8aa5-e22f3b400002, allReceived=false]
[2018-08-07 12:20:11,470][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][time]
Finished exchange init [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], crd=false]
[2018-08-07 12:20:11,471][INFO
][sys-#12799%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Coordinator received single message [ver=AffinityTopologyVersion [topVer=4,
minorTopVer=1], node=6b9a7a1d-07bf-4d20-882a-8462ada00003, allReceived=true]
[2018-08-07 12:20:11,471][INFO
][sys-#12799%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]]
[2018-08-07 12:20:11,476][INFO
][sys-#12799%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Finish exchange future [startVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1],
err=null]
[2018-08-07 12:20:11,478][INFO
][sys-#12820%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Received full message, will finish exchange
[node=511d5932-5f22-4919-807d-575c7f600001, resVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1]]
[2018-08-07 12:20:11,478][INFO
][sys-#12799%internal.GridTaskFailoverAffinityRunTest1%][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=511d5932-5f22-4919-807d-575c7f600001,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644411360, loc=true, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], durationFromInit=111]
[2018-08-07 12:20:11,478][INFO
][sys-#12821%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Received full message, will finish exchange
[node=511d5932-5f22-4919-807d-575c7f600001, resVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1]]
[2018-08-07 12:20:11,480][INFO
][sys-#12821%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Finish exchange future [startVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1],
err=null]
[2018-08-07 12:20:11,481][INFO
][sys-#12821%internal.GridTaskFailoverAffinityRunTest2%][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=a3206c1f-6d57-4fd6-8aa5-e22f3b400002,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409759, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], durationFromInit=111]
[2018-08-07 12:20:11,478][INFO
][sys-#12820%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finish exchange future [startVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1],
err=null]
[2018-08-07 12:20:11,481][INFO
][exchange-worker-#12789%internal.GridTaskFailoverAffinityRunTest2%][GridCachePartitionExchangeManager]
Skipping rebalancing (no affinity changes) [top=AffinityTopologyVersion
[topVer=4, minorTopVer=1], rebTopVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], evt=DISCOVERY_CUSTOM_EVT,
evtNode=511d5932-5f22-4919-807d-575c7f600001, client=false]
[2018-08-07 12:20:11,482][INFO
][sys-#12820%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=6b9a7a1d-07bf-4d20-882a-8462ada00003,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=1], durationFromInit=121]
[2018-08-07 12:20:11,483][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridCachePartitionExchangeManager]
Skipping rebalancing (no affinity changes) [top=AffinityTopologyVersion
[topVer=4, minorTopVer=1], rebTopVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], evt=DISCOVERY_CUSTOM_EVT,
evtNode=511d5932-5f22-4919-807d-575c7f600001, client=false]
[2018-08-07 12:20:11,503][INFO
][exchange-worker-#12782%internal.GridTaskFailoverAffinityRunTest1%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=4, minorTopVer=1], force=false, evt=DISCOVERY_CUSTOM_EVT,
node=511d5932-5f22-4919-807d-575c7f600001]
[2018-08-07 12:20:11,510][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][root] Finished
waiting for topology map update
[igniteInstanceName=internal.GridTaskFailoverAffinityRunTest3, p=0,
duration=1633ms]
[2018-08-07
12:20:41,515][ERROR][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][root]
Failed to wait for exchange [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=0], node=internal.GridTaskFailoverAffinityRunTest0]
class org.apache.ignite.internal.IgniteFutureTimeoutCheckedException: Timeout
was reached before computation completed.
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:242)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get(GridFutureAdapter.java:159)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get(GridFutureAdapter.java:151)
at
org.apache.ignite.testframework.junits.common.GridCommonAbstractTest.awaitPartitionMapExchange(GridCommonAbstractTest.java:627)
at
org.apache.ignite.testframework.junits.common.GridCommonAbstractTest.awaitPartitionMapExchange(GridCommonAbstractTest.java:551)
at
org.apache.ignite.testframework.junits.common.GridCommonAbstractTest.awaitPartitionMapExchange(GridCommonAbstractTest.java:535)
at
org.apache.ignite.testframework.junits.common.GridCommonAbstractTest.startGridsMultiThreaded(GridCommonAbstractTest.java:524)
at
org.apache.ignite.testframework.junits.common.GridCommonAbstractTest.startGridsMultiThreaded(GridCommonAbstractTest.java:508)
at
org.apache.ignite.internal.GridTaskFailoverAffinityRunTest.nodeRestart(GridTaskFailoverAffinityRunTest.java:108)
at
org.apache.ignite.internal.GridTaskFailoverAffinityRunTest.testNodeRestartClient(GridTaskFailoverAffinityRunTest.java:101)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at junit.framework.TestCase.runTest(TestCase.java:176)
at
org.apache.ignite.testframework.junits.GridAbstractTest.runTestInternal(GridAbstractTest.java:2156)
at
org.apache.ignite.testframework.junits.GridAbstractTest.access$000(GridAbstractTest.java:143)
at
org.apache.ignite.testframework.junits.GridAbstractTest$5.run(GridAbstractTest.java:2071)
at java.lang.Thread.run(Thread.java:748)
[2018-08-07 12:20:41,526][INFO
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][root]
awaitPartitionMapExchange finished
[2018-08-07 12:20:41,529][INFO ][restart-thread-1][root] >>> Stopping grid
[name=internal.GridTaskFailoverAffinityRunTest2,
id=a3206c1f-6d57-4fd6-8aa5-e22f3b400002]
[2018-08-07 12:20:41,529][INFO ][restart-thread-2][root] >>> Stopping grid
[name=internal.GridTaskFailoverAffinityRunTest1,
id=511d5932-5f22-4919-807d-575c7f600001]
[2018-08-07 12:20:41,538][INFO
][disco-event-worker-#12673%internal.GridTaskFailoverAffinityRunTest0%][GridDiscoveryManager]
Node left topology: TcpDiscoveryNode [id=a3206c1f-6d57-4fd6-8aa5-e22f3b400002,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47503],
discPort=47503, order=4, intOrder=4, lastExchangeTime=1533644409729, loc=false,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]
[2018-08-07 12:20:41,539][INFO
][disco-event-worker-#12673%internal.GridTaskFailoverAffinityRunTest0%][GridDiscoveryManager]
Topology snapshot [ver=5, servers=2, clients=1, CPUs=5, offheap=0.1GB,
heap=2.0GB]
[2018-08-07 12:20:41,539][INFO
][disco-event-worker-#12673%internal.GridTaskFailoverAffinityRunTest0%][GridDiscoveryManager]
^-- Node [id=7406E013-DDF7-44D1-B4E2-2FF707800000, clusterState=ACTIVE]
[2018-08-07 12:20:41,541][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
Node left topology: TcpDiscoveryNode [id=a3206c1f-6d57-4fd6-8aa5-e22f3b400002,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47503],
discPort=47503, order=4, intOrder=4, lastExchangeTime=1533644409749, loc=false,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]
[2018-08-07 12:20:41,541][INFO
][tcp-disco-sock-reader-#1859%internal.GridTaskFailoverAffinityRunTest2%][TestTcpDiscoverySpi]
Finished serving remote node connection [rmtAddr=/127.0.0.1:52239,
rmtPort=52239
[2018-08-07 12:20:41,541][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
Topology snapshot [ver=5, servers=2, clients=1, CPUs=5, offheap=0.1GB,
heap=2.0GB]
[2018-08-07 12:20:41,542][INFO
][tcp-disco-msg-worker-#1847%internal.GridTaskFailoverAffinityRunTest3%][TestTcpDiscoverySpi]
New next node [newNext=TcpDiscoveryNode
[id=7406e013-ddf7-44d1-b4e2-2ff707800000, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=1, intOrder=1,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false]]
[2018-08-07 12:20:41,542][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
^-- Node [id=6B9A7A1D-07BF-4D20-882A-8462ADA00003, clusterState=ACTIVE]
[2018-08-07 12:20:41,542][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
Data Regions Configured:
[2018-08-07 12:20:41,543][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
^-- default [initSize=256.0 MiB, maxSize=18.9 GiB, persistenceEnabled=false]
[2018-08-07 12:20:41,542][INFO
][tcp-disco-srvr-#1836%internal.GridTaskFailoverAffinityRunTest0%][TestTcpDiscoverySpi]
TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=45115]
[2018-08-07 12:20:41,544][INFO
][tcp-disco-srvr-#1836%internal.GridTaskFailoverAffinityRunTest0%][TestTcpDiscoverySpi]
TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1,
rmtPort=45115]
[2018-08-07 12:20:41,544][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][time]
Started exchange init [topVer=AffinityTopologyVersion [topVer=5,
minorTopVer=0], crd=false, evt=NODE_LEFT,
evtNode=a3206c1f-6d57-4fd6-8aa5-e22f3b400002, customEvt=null, allowMerge=true]
[2018-08-07 12:20:41,544][INFO
][tcp-disco-sock-reader-#1863%internal.GridTaskFailoverAffinityRunTest0%][TestTcpDiscoverySpi]
Started serving remote node connection [rmtAddr=/127.0.0.1:45115,
rmtPort=45115]
[2018-08-07 12:20:41,545][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=5, minorTopVer=0], waitTime=0ms, futInfo=NA]
[2018-08-07 12:20:41,547][INFO ][restart-thread-1][GridCacheProcessor] Stopped
cache [cacheName=default]
[2018-08-07 12:20:41,547][INFO ][restart-thread-1][GridCacheProcessor] Stopped
cache [cacheName=ignite-sys-cache]
[2018-08-07 12:20:41,548][INFO ][restart-thread-1][GridDeploymentLocalStore]
Removed undeployed class: GridDeployment [ts=1533644409800, depMode=SHARED,
clsLdr=IsolatedClassLoader{roleName='test'},
clsLdrId=00d45541561-a3206c1f-6d57-4fd6-8aa5-e22f3b400002, userVer=0, loc=true,
sampleClsName=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap,
pendingUndeploy=false, undeployed=true, usage=0]
[2018-08-07 12:20:41,549][INFO
][tcp-disco-sock-reader-#1854%internal.GridTaskFailoverAffinityRunTest1%][TestTcpDiscoverySpi]
Finished serving remote node connection [rmtAddr=/127.0.0.1:37414,
rmtPort=37414
[2018-08-07 12:20:41,549][INFO
][disco-event-worker-#12673%internal.GridTaskFailoverAffinityRunTest0%][GridDiscoveryManager]
Node left topology: TcpDiscoveryNode [id=511d5932-5f22-4919-807d-575c7f600001,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47501],
discPort=47501, order=2, intOrder=2, lastExchangeTime=1533644409729, loc=false,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]
[2018-08-07 12:20:41,549][INFO
][tcp-disco-msg-worker-#1835%internal.GridTaskFailoverAffinityRunTest0%][TestTcpDiscoverySpi]
New next node [newNext=TcpDiscoveryNode
[id=6b9a7a1d-07bf-4d20-882a-8462ada00003, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=3, intOrder=3,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false]]
[2018-08-07 12:20:41,550][INFO
][disco-event-worker-#12673%internal.GridTaskFailoverAffinityRunTest0%][GridDiscoveryManager]
Topology snapshot [ver=6, servers=1, clients=1, CPUs=5, offheap=0.1GB,
heap=2.0GB]
[2018-08-07 12:20:41,550][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionDemander
[2018-08-07 12:20:41,551][INFO
][disco-event-worker-#12673%internal.GridTaskFailoverAffinityRunTest0%][GridDiscoveryManager]
Coordinator changed [prev=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], cur=TcpDiscoveryNode [id=6b9a7a1d-07bf-4d20-882a-8462ada00003,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502],
discPort=47502, order=3, intOrder=3, lastExchangeTime=1533644409729, loc=false,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]]
[2018-08-07 12:20:41,551][INFO
][tcp-disco-srvr-#1849%internal.GridTaskFailoverAffinityRunTest3%][TestTcpDiscoverySpi]
TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49162]
[2018-08-07 12:20:41,552][INFO
][disco-event-worker-#12673%internal.GridTaskFailoverAffinityRunTest0%][GridDiscoveryManager]
^-- Node [id=7406E013-DDF7-44D1-B4E2-2FF707800000, clusterState=ACTIVE]
[2018-08-07 12:20:41,551][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap2
[2018-08-07 12:20:41,552][INFO
][tcp-disco-srvr-#1849%internal.GridTaskFailoverAffinityRunTest3%][TestTcpDiscoverySpi]
TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1,
rmtPort=49162]
[2018-08-07 12:20:41,553][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.CachePartitionFullCountersMap
[2018-08-07 12:20:41,553][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionDemander
[2018-08-07 12:20:41,553][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class java.util.Collections$UnmodifiableMap
[2018-08-07 12:20:41,554][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.GridCacheProcessor$RemovedItemsCleanupTask$1
[2018-08-07 12:20:41,554][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap
[2018-08-07 12:20:41,554][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ResendTimeoutObject$1
[2018-08-07 12:20:41,554][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.service.GridServiceProcessor$ServiceAssignmentsPredicate
[2018-08-07 12:20:41,555][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap
[2018-08-07 12:20:41,555][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap
[2018-08-07 12:20:41,555][INFO ][restart-thread-1][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap
[2018-08-07 12:20:41,555][INFO
][tcp-disco-sock-reader-#1864%internal.GridTaskFailoverAffinityRunTest3%][TestTcpDiscoverySpi]
Started serving remote node connection [rmtAddr=/127.0.0.1:49162,
rmtPort=49162]
[2018-08-07 12:20:41,556][INFO ][restart-thread-2][GridCacheProcessor] Stopped
cache [cacheName=default]
[2018-08-07 12:20:41,556][INFO ][restart-thread-2][GridCacheProcessor] Stopped
cache [cacheName=ignite-sys-cache]
[2018-08-07 12:20:41,558][INFO ][restart-thread-2][GridDeploymentLocalStore]
Removed undeployed class: GridDeployment [ts=1533644409779, depMode=SHARED,
clsLdr=IsolatedClassLoader{roleName='test'},
clsLdrId=3fc45541561-511d5932-5f22-4919-807d-575c7f600001, userVer=0, loc=true,
sampleClsName=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap,
pendingUndeploy=false, undeployed=true, usage=0]
[2018-08-07 12:20:41,559][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap
[2018-08-07 12:20:41,559][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ResendTimeoutObject$1
[2018-08-07 12:20:41,559][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.service.GridServiceProcessor$ServiceAssignmentsPredicate
[2018-08-07 12:20:41,560][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.CachePartitionPartialCountersMap
[2018-08-07 12:20:41,560][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class org.apache.ignite.internal.GridTopic$T6
[2018-08-07 12:20:41,560][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtDemandedPartitionsMap
[2018-08-07 12:20:41,560][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.service.GridServiceProcessor$ServiceDeploymentPredicate
[2018-08-07 12:20:41,561][INFO ][restart-thread-2][GridDeploymentLocalStore]
Class locally undeployed: class
org.apache.ignite.internal.processors.cache.GridCacheProcessor$RemovedItemsCleanupTask$1
[2018-08-07 12:20:41,561][INFO
][restart-thread-1][GridTaskFailoverAffinityRunTest2]
>>> +------------------------------------------------------------------------------------------+
>>> Ignite ver.
>>> 2.7.0-SNAPSHOT#20180807-sha1:e96616f580930f267eab44f75d410fa29a876bcb
>>> stopped OK
>>> +------------------------------------------------------------------------------------------+
>>> Ignite instance name: internal.GridTaskFailoverAffinityRunTest2
>>> Grid uptime: 00:00:31.725
[2018-08-07 12:20:41,563][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
Node left topology: TcpDiscoveryNode [id=511d5932-5f22-4919-807d-575c7f600001,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47501],
discPort=47501, order=2, intOrder=2, lastExchangeTime=1533644409749, loc=false,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]
[2018-08-07 12:20:41,563][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
Topology snapshot [ver=6, servers=1, clients=1, CPUs=5, offheap=0.1GB,
heap=2.0GB]
[2018-08-07 12:20:41,564][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
Coordinator changed [prev=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], cur=TcpDiscoveryNode [id=6b9a7a1d-07bf-4d20-882a-8462ada00003,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502],
discPort=47502, order=3, intOrder=3, lastExchangeTime=1533644441555, loc=true,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false]]
[2018-08-07 12:20:41,564][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
^-- Node [id=6B9A7A1D-07BF-4D20-882A-8462ADA00003, clusterState=ACTIVE]
[2018-08-07 12:20:41,565][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
Data Regions Configured:
[2018-08-07 12:20:41,564][INFO ][restart-thread-1][root] Topology version
mismatch [node=internal.GridTaskFailoverAffinityRunTest3,
exchVer=AffinityTopologyVersion [topVer=4, minorTopVer=1],
topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0]]
[2018-08-07 12:20:41,564][INFO
][restart-thread-2][GridTaskFailoverAffinityRunTest1]
>>> +------------------------------------------------------------------------------------------+
>>> Ignite ver.
>>> 2.7.0-SNAPSHOT#20180807-sha1:e96616f580930f267eab44f75d410fa29a876bcb
>>> stopped OK
>>> +------------------------------------------------------------------------------------------+
>>> Ignite instance name: internal.GridTaskFailoverAffinityRunTest1
>>> Grid uptime: 00:00:31.745
[2018-08-07 12:20:41,565][INFO
][disco-event-worker-#12785%internal.GridTaskFailoverAffinityRunTest3%][GridDiscoveryManager]
^-- default [initSize=256.0 MiB, maxSize=18.9 GiB, persistenceEnabled=false]
[2018-08-07 12:20:41,568][INFO
][sys-#12809%internal.GridTaskFailoverAffinityRunTest3%][ExchangeLatchManager]
Become new coordinator 6b9a7a1d-07bf-4d20-882a-8462ada00003
[2018-08-07 12:20:41,568][INFO ][restart-thread-2][root] Topology version
mismatch [node=internal.GridTaskFailoverAffinityRunTest3,
exchVer=AffinityTopologyVersion [topVer=4, minorTopVer=1],
topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0]]
[2018-08-07 12:20:41,568][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finished waiting for partitions release latch: ClientLatch
[coordinator=TcpDiscoveryNode [id=6b9a7a1d-07bf-4d20-882a-8462ada00003,
addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502],
discPort=47502, order=3, intOrder=3, lastExchangeTime=1533644441555, loc=true,
ver=2.7.0#20180807-sha1:e96616f5, isClient=false], ackSent=true,
super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=5,
minorTopVer=0]]]
[2018-08-07 12:20:41,569][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Finished waiting for partition release future [topVer=AffinityTopologyVersion
[topVer=5, minorTopVer=0], waitTime=0ms, futInfo=NA]
[2018-08-07
12:20:41,573][ERROR][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][TcpCommunicationSpi]
Failed to send message to remote node [node=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8,
ordered=false, timeout=0, skipOnTimeout=false, msg=GridCacheMessage [msgId=745,
depInfo=null, err=null, skipPrepare=false]GridDhtPartitionsAbstractMessage
[exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=5,
minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode
[id=a3206c1f-6d57-4fd6-8aa5-e22f3b400002, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47503], discPort=47503, order=4, intOrder=4,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], topVer=5, nodeId8=6b9a7a1d, msg=Node left: TcpDiscoveryNode
[id=a3206c1f-6d57-4fd6-8aa5-e22f3b400002, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47503], discPort=47503, order=4, intOrder=4,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], type=NODE_LEFT, tstamp=1533644441543], nodeId=a3206c1f,
evt=NODE_LEFT], lastVer=GridCacheVersion [topVer=0, order=1533644409719,
nodeOrder=0], super=]GridDhtPartitionsSingleMessage [parts=HashMap
{1544803905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion
[topVer=4, minorTopVer=1], updateSeq=676, size=668],
-2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion
[topVer=4, minorTopVer=1], updateSeq=107, size=100]}, partCntrs=HashMap
{1544803905=CachePartitionPartialCountersMap {},
-2100569601=CachePartitionPartialCountersMap {}}, partsSizes=null,
partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null,
super=]]]
class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException:
Failed to send message (node left topology): TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3250)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2967)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2850)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2693)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2652)
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1643)
at
org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:1715)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1170)
at
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendLocalPartitions(GridDhtPartitionsExchangeFuture.java:1579)
at
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1686)
at
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1255)
at
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:749)
at
org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2497)
at
org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2377)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
at java.lang.Thread.run(Thread.java:748)
[2018-08-07
12:20:41,573][ERROR][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][TcpCommunicationSpi]
Failed to send message to remote node [node=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], msg=GridIoMessage [plc=0, topic=TOPIC_JOB, topicOrd=0,
ordered=false, timeout=0, skipOnTimeout=false, msg=GridJobExecuteRequest
[subjId=7406e013-ddf7-44d1-b4e2-2ff707800000,
sesId=6fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000,
jobId=9fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000,
startTaskTime=1533644441523, timeout=9223372036854775807,
taskName=org.apache.ignite.internal.GridTaskFailoverAffinityRunTest$TestJob,
userVer=0,
taskClsName=org.apache.ignite.internal.GridTaskFailoverAffinityRunTest$TestJob,
ldrParticipants=null, cpSpi=null, createTime=1533644441566,
clsLdrId=22c45541561-7406e013-ddf7-44d1-b4e2-2ff707800000, depMode=SHARED,
dynamicSiblings=false, forceLocDep=false, sesFullSup=false, internal=false,
topPred=null, part=0, topVer=AffinityTopologyVersion [topVer=2, minorTopVer=0],
execName=null]]]
class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException:
Failed to send message (node left topology): TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3250)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2967)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2850)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2693)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2652)
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1643)
at
org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:1715)
at
org.apache.ignite.internal.processors.task.GridTaskWorker.sendRequest(GridTaskWorker.java:1423)
at
org.apache.ignite.internal.processors.task.GridTaskWorker.processMappedJobs(GridTaskWorker.java:660)
at
org.apache.ignite.internal.processors.task.GridTaskWorker.body(GridTaskWorker.java:532)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
at
org.apache.ignite.internal.processors.task.GridTaskProcessor.startTask(GridTaskProcessor.java:760)
at
org.apache.ignite.internal.processors.task.GridTaskProcessor.execute(GridTaskProcessor.java:452)
at
org.apache.ignite.internal.processors.closure.GridClosureProcessor.affinityCall(GridClosureProcessor.java:514)
at
org.apache.ignite.internal.IgniteComputeImpl.affinityCallAsync0(IgniteComputeImpl.java:340)
at
org.apache.ignite.internal.IgniteComputeImpl.affinityCallAsync(IgniteComputeImpl.java:313)
at
org.apache.ignite.internal.GridTaskFailoverAffinityRunTest.nodeRestart(GridTaskFailoverAffinityRunTest.java:137)
[2018-08-07 12:20:41,579][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][GridDhtPartitionsExchangeFuture]
Coordinator failed, node is new coordinator [ver=AffinityTopologyVersion
[topVer=5, minorTopVer=0], prev=511d5932-5f22-4919-807d-575c7f600001]
at
org.apache.ignite.internal.GridTaskFailoverAffinityRunTest.testNodeRestartClient(GridTaskFailoverAffinityRunTest.java:101)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at junit.framework.TestCase.runTest(TestCase.java:176)
at
org.apache.ignite.testframework.junits.GridAbstractTest.runTestInternal(GridAbstractTest.java:2156)
at
org.apache.ignite.testframework.junits.GridAbstractTest.access$000(GridAbstractTest.java:143)
at
org.apache.ignite.testframework.junits.GridAbstractTest$5.run(GridAbstractTest.java:2071)
at java.lang.Thread.run(Thread.java:748)
[2018-08-07 12:20:41,585][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][InitNewCoordinatorFuture]
Init new coordinator, node left [node=511d5932-5f22-4919-807d-575c7f600001]
[2018-08-07 12:20:41,585][INFO
][sys-#12812%internal.GridTaskFailoverAffinityRunTest3%][InitNewCoordinatorFuture]
Init new coordinator future will skip remote node: TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409749, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false]
[2018-08-07 12:20:41,585][INFO
][sys-#12812%internal.GridTaskFailoverAffinityRunTest3%][InitNewCoordinatorFuture]
Try restore exchange result [awaited=[7406e013-ddf7-44d1-b4e2-2ff707800000],
joined=[], nodes=[7406e013-ddf7-44d1-b4e2-2ff707800000],
discoAllNodes=[7406e013-ddf7-44d1-b4e2-2ff707800000,
511d5932-5f22-4919-807d-575c7f600001, 6b9a7a1d-07bf-4d20-882a-8462ada00003]]
[2018-08-07 12:20:41,585][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][GridTaskWorker]
Failed to send job request because remote node left grid (if failover is
enabled, will attempt fail-over to another node) [node=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], taskName=o.a.i.i.GridTaskFailoverAffinityRunTest$TestJob,
taskSesId=6fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000,
jobSesId=9fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000]
[2018-08-07 12:20:41,587][INFO
][grid-nio-worker-tcp-comm-1-#12662%internal.GridTaskFailoverAffinityRunTest0%][TcpCommunicationSpi]
Accepted incoming communication connection [locAddr=/127.0.0.1:45820,
rmtAddr=/127.0.0.1:37706]
[2018-08-07 12:20:41,587][INFO
][exchange-worker-#12786%internal.GridTaskFailoverAffinityRunTest3%][time]
Finished exchange init [topVer=AffinityTopologyVersion [topVer=5,
minorTopVer=0], crd=false]
[2018-08-07 12:20:41,588][INFO
][grid-nio-worker-tcp-comm-1-#12761%internal.GridTaskFailoverAffinityRunTest3%][TcpCommunicationSpi]
Established outgoing communication connection [locAddr=/127.0.0.1:37706,
rmtAddr=/127.0.0.1:45820]
[2018-08-07 12:20:41,588][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][GridTaskWorker]
Failed to send job request because remote node left grid (if fail-over is
enabled, will attempt fail-over to another node) [node=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], taskName=o.a.i.i.GridTaskFailoverAffinityRunTest$TestJob,
taskSesId=6fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000,
jobSesId=9fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000]
[2018-08-07 12:20:41,590][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][GridTaskWorker]
Failed to send job request because remote node left grid (if fail-over is
enabled, will attempt fail-over to another node) [node=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], taskName=o.a.i.i.GridTaskFailoverAffinityRunTest$TestJob,
taskSesId=6fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000,
jobSesId=9fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000]
[2018-08-07 12:20:41,591][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][GridTaskWorker]
Failed to send job request because remote node left grid (if fail-over is
enabled, will attempt fail-over to another node) [node=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], taskName=o.a.i.i.GridTaskFailoverAffinityRunTest$TestJob,
taskSesId=6fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000,
jobSesId=9fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000]
[2018-08-07 12:20:41,592][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][GridTaskWorker]
Failed to send job request because remote node left grid (if fail-over is
enabled, will attempt fail-over to another node) [node=TcpDiscoveryNode
[id=511d5932-5f22-4919-807d-575c7f600001, addrs=ArrayList [127.0.0.1],
sockAddrs=HashSet [/127.0.0.1:47501], discPort=47501, order=2, intOrder=2,
lastExchangeTime=1533644409729, loc=false, ver=2.7.0#20180807-sha1:e96616f5,
isClient=false], taskName=o.a.i.i.GridTaskFailoverAffinityRunTest$TestJob,
taskSesId=6fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000,
jobSesId=9fa55541561-7406e013-ddf7-44d1-b4e2-2ff707800000]
[2018-08-07 12:20:41,593][WARN
][test-runner-#12637%internal.GridTaskFailoverAffinityRunTest%][AlwaysFailoverSpi]
Job failover failed because number of maximum failover attempts for affinity
call is exceeded [failedJob=C2
[c=o.a.i.i.GridTaskFailoverAffinityRunTest$TestJob@23aa8593],
maxFailoverAttempts=5]
...
{noformat}
Coordinator receives single message from client, exchange future is not
completed and initial exchange version on client is smaller then ready affinity
version on coordinator.
Coordinator forces client to reconnect.
But client was forced to server mode (forceSrvMode=true) and incorrectly
handles this case.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
