You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "Pavel Pereslegin (JIRA)" <ji...@apache.org> on 2018/10/31 12:13:00 UTC
[jira] [Updated] (IGNITE-9238) Test
GridTaskFailoverAffinityRunTest.testNodeRestartClient hangs when
coordinator forces client to reconnect on grid startup.
[ https://issues.apache.org/jira/browse/IGNITE-9238?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Pavel Pereslegin updated IGNITE-9238:
-------------------------------------
Ignite Flags: (was: Docs Required)
> 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
> Priority: Major
> Fix For: 2.7
>
> Attachments: Reproducer.java
>
>
> 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 for client exchange id is not completed and initial exchange version smaller then ready affinity version.
> Coordinator decides that there is not enough exchange history and forces client to reconnect (history is more than enough actually).
> Client was forced to server mode (forceSrvMode=true) and just stop exchange worker.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)