[
https://issues.apache.org/jira/browse/IGNITE-9238?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16575932#comment-16575932
]
Pavel Pereslegin commented on IGNITE-9238:
------------------------------------------
Hello [~Jokser],
review this fix, please.
When coordinator checks exchange history, it can see updated affinity version,
but the exchange future on which the affinity version was updated is not fully
completed.
> 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
>
>
> 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)
