[ 
https://issues.apache.org/jira/browse/IGNITE-9238?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16716537#comment-16716537
 ] 

ASF GitHub Bot commented on IGNITE-9238:
----------------------------------------

Github user xtern closed the pull request at:

    https://github.com/apache/ignite/pull/4503


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

Reply via email to