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