You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "Pavel Pereslegin (JIRA)" <ji...@apache.org> on 2018/10/02 10:55:00 UTC
[jira] [Updated] (IGNITE-9015) [Test Failed]
IgniteAtomicLongChangingTopologySelfTest.testClientSetCreateCloseFailover
fails sometimes.
[ https://issues.apache.org/jira/browse/IGNITE-9015?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Pavel Pereslegin updated IGNITE-9015:
-------------------------------------
Fix Version/s: 2.8
> [Test Failed] IgniteAtomicLongChangingTopologySelfTest.testClientSetCreateCloseFailover fails sometimes.
> --------------------------------------------------------------------------------------------------------
>
> Key: IGNITE-9015
> URL: https://issues.apache.org/jira/browse/IGNITE-9015
> Project: Ignite
> Issue Type: Bug
> Affects Versions: 2.6
> Reporter: Pavel Pereslegin
> Assignee: Pavel Pereslegin
> Priority: Major
> Fix For: 2.8
>
> Attachments: Reproducer.java
>
>
> {color:grey}Please, see *UPDATE* below.{color}
> If constantly create/destroy caches and change the coordinator, PME could hang.
> Reproducer (it reproduces much better if you set cpu affinity to one core).
> {code:java}
> public class Reproducer extends GridCommonAbstractTest {
> /** */
> private static final int GRID_CNT = 5;
> /** */
> private static final String CACHE_NAME_PREF = "cache-";
> /**
> * @throws Exception If failed.
> */
> public void testClientCacheCreateDestroyFailover() throws Exception {
> startGridsMultiThreaded(GRID_CNT);
> Ignition.setClientMode(true);
> Ignite client = startGrid(GRID_CNT);
> Ignition.setClientMode(false);
> final AtomicBoolean finished = new AtomicBoolean();
> IgniteInternalFuture<?> fut = restartThread(finished);
> long stop = System.currentTimeMillis() + 60_000;
> IgniteCache<String, Boolean> defCache = client.createCache(ccfg(CACHE_NAME_PREF));
> try {
> int iter = 0;
> while (System.currentTimeMillis() < stop) {
> log.info("Iteration: " + iter++);
> try {
> for (int i = 0; i < 100; i++) {
> String cacheName = CACHE_NAME_PREF + i;
> CacheConfiguration<?, ?> ccfg = ccfg(cacheName);
> defCache.put(cacheName, Boolean.FALSE.equals(defCache.get(cacheName)));
> client.getOrCreateCache(ccfg).destroy();
> }
> }
> catch (IgniteClientDisconnectedException e) {
> e.reconnectFuture().get();
> }
> catch (CacheException e) {
> if (e.getCause() instanceof IgniteClientDisconnectedException)
> ((IgniteClientDisconnectedException)e.getCause()).reconnectFuture().get();
> else
> throw e;
> }
> }
> finished.set(true);
> fut.get();
> }
> finally {
> finished.set(true);
> IgniteCache c = client.cache(CACHE_NAME_PREF);
> if (c != null)
> c.destroy();
> }
> }
> /**
> * @param name Cache name.
> * @return Cache configuration.
> */
> private <K,V> CacheConfiguration<K,V> ccfg(String name) {
> CacheConfiguration<K,V> cacheCfg = new CacheConfiguration<>(name);
> cacheCfg.setBackups(1);
> cacheCfg.setCacheMode(PARTITIONED);
> cacheCfg.setAtomicityMode(TRANSACTIONAL);
> return cacheCfg;
> }
> /**
> * @param finished Finished flag.
> * @return Future.
> */
> private IgniteInternalFuture<?> restartThread(final AtomicBoolean finished) {
> return GridTestUtils.runAsync(new Callable<Object>() {
> @Override public Object call() throws Exception {
> while (!finished.get()) {
> for (int i = 0; i < GRID_CNT; i++) {
> log.info("Stop node: " + i);
> stopGrid(i);
> U.sleep(500);
> log.info("Start node: " + i);
> startGrid(i);
> if (finished.get())
> break;
> }
> }
> return null;
> }
> }, "restart-thread");
> }
> }
> {code}
> Typical log output:
> {noformat}
> [2018-07-17 11:52:45,249][INFO ][exchange-worker-#257%cache.Reproducer5%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=29209c33-9cb5-4732-acd4-932e5f600005, customEvt=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false]
> [2018-07-17 11:52:45,251][INFO ][exchange-worker-#257%cache.Reproducer5%][GridCacheProcessor] Started cache [name=cache-40, id=-433538905, memoryPolicyName=null, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:45,251][INFO ][exchange-worker-#257%cache.Reproducer5%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false]
> [2018-07-17 11:52:45,253][INFO ][exchange-worker-#455%cache.Reproducer2%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=true, evt=DISCOVERY_CUSTOM_EVT, evtNode=29209c33-9cb5-4732-acd4-932e5f600005, customEvt=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false]
> [2018-07-17 11:52:45,253][INFO ][exchange-worker-#455%cache.Reproducer2%][GridCacheProcessor] Started cache [name=cache-40, id=-433538905, memoryPolicyName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:45,254][INFO ][exchange-worker-#455%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,254][INFO ][exchange-worker-#455%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,255][INFO ][exchange-worker-#455%cache.Reproducer2%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=true]
> [2018-07-17 11:52:45,255][INFO ][exchange-worker-#619%cache.Reproducer0%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=29209c33-9cb5-4732-acd4-932e5f600005, customEvt=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false]
> [2018-07-17 11:52:45,256][INFO ][exchange-worker-#619%cache.Reproducer0%][GridCacheProcessor] Started cache [name=cache-40, id=-433538905, memoryPolicyName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:45,256][INFO ][exchange-worker-#619%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,256][INFO ][exchange-worker-#619%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,257][INFO ][exchange-worker-#509%cache.Reproducer3%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=29209c33-9cb5-4732-acd4-932e5f600005, customEvt=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false]
> [2018-07-17 11:52:45,257][INFO ][exchange-worker-#509%cache.Reproducer3%][GridCacheProcessor] Started cache [name=cache-40, id=-433538905, memoryPolicyName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:45,258][INFO ][exchange-worker-#509%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,258][INFO ][exchange-worker-#509%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,261][INFO ][sys-#464%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=20, minorTopVer=18], node=214d8ef6-bae8-4b6f-9947-33c451e00000, allReceived=false]
> [2018-07-17 11:52:45,261][INFO ][exchange-worker-#619%cache.Reproducer0%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false]
> [2018-07-17 11:52:45,261][INFO ][exchange-worker-#673%cache.Reproducer1%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=29209c33-9cb5-4732-acd4-932e5f600005, customEvt=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false]
> [2018-07-17 11:52:45,262][INFO ][exchange-worker-#673%cache.Reproducer1%][GridCacheProcessor] Started cache [name=cache-40, id=-433538905, memoryPolicyName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:45,263][INFO ][exchange-worker-#673%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,263][INFO ][exchange-worker-#673%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,263][INFO ][sys-#463%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=20, minorTopVer=18], node=1f04dca5-0424-460c-96f6-1736f0900003, allReceived=false]
> [2018-07-17 11:52:45,263][INFO ][exchange-worker-#509%cache.Reproducer3%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false]
> [2018-07-17 11:52:45,265][INFO ][sys-#460%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=20, minorTopVer=18], node=c6cbf88b-2f79-4562-813d-b630eb800001, allReceived=false]
> [2018-07-17 11:52:45,265][INFO ][exchange-worker-#673%cache.Reproducer1%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false]
> [2018-07-17 11:52:45,265][INFO ][exchange-worker-#564%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=b3ea935b-7eaf-440c-9408-346192500004, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true], topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], durationFromInit=62]
> [2018-07-17 11:52:45,265][INFO ][exchange-worker-#564%cache.Reproducer4%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], crd=false]
> [2018-07-17 11:52:45,266][INFO ][exchange-worker-#564%cache.Reproducer4%][GridCachePartitionExchangeManager] Skipping rebalancing (obsolete exchange ID) [top=AffinityTopologyVersion [topVer=20, minorTopVer=17], evt=DISCOVERY_CUSTOM_EVT, node=29209c33-9cb5-4732-acd4-932e5f600005]
> [2018-07-17 11:52:45,266][INFO ][exchange-worker-#564%cache.Reproducer4%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=29209c33-9cb5-4732-acd4-932e5f600005, customEvt=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false]
> [2018-07-17 11:52:45,266][INFO ][exchange-worker-#564%cache.Reproducer4%][GridCacheProcessor] Started cache [name=cache-40, id=-433538905, memoryPolicyName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:45,267][INFO ][exchange-worker-#564%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,267][INFO ][exchange-worker-#564%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,334][INFO ][exchange-worker-#564%cache.Reproducer4%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=false]
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] Performance suggestions for grid 'cache.Reproducer1' (fix if possible)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] To disable, set -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Disable checkpoints (remove 'checkpointSpi' from configuration)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Disable grid events (remove 'includeEventTypes' from configuration)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Enable G1 Garbage Collector (add '-XX:+UseG1GC' to JVM options)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Specify JVM heap max size (add '-Xmx<size>[g|G|m|M|k|K]' to JVM options)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Disable processing of calls to System.gc() (add '-XX:+DisableExplicitGC' to JVM options)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Decrease number of backups (set 'backups' to 0)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Enable ATOMIC mode if not using transactions (set 'atomicityMode' to ATOMIC)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] ^-- Disable assertions (remove '-ea' from JVM options)
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] Refer to this page for more performance suggestions: https://apacheignite.readme.io/docs/jvm-and-system-tuning
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1]
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat}
> [2018-07-17 11:52:45,335][INFO ][restart-thread-1][Reproducer1]
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][Reproducer1]
> >>> +------------------------------------------+
> >>> Ignite ver. 2.7.0-SNAPSHOT#19700101-sha1:DEV
> >>> +------------------------------------------+
> >>> OS name: Linux 4.13.0-45-generic amd64
> >>> CPU(s): 1
> >>> Heap: 3.8GB
> >>> VM name: 6154@xtern-DL5580
> >>> Ignite instance name: cache.Reproducer1
> >>> Local node [ID=C6CBF88B-2F79-4562-813D-B630EB800001, order=20, clientMode=false]
> >>> Local node addresses: [127.0.0.1]
> >>> Local ports: TCP:10802 TCP:45011 TCP:47504 UDP:50001
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][GridDiscoveryManager] Topology snapshot [ver=20, servers=5, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][GridDiscoveryManager] ^-- Node [id=C6CBF88B-2F79-4562-813D-B630EB800001, clusterState=ACTIVE]
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][root] Node started with the following configuration [id=c6cbf88b-2f79-4562-813d-b630eb800001, marshaller=org.apache.ignite.internal.binary.BinaryMarshaller@dbf682b, discovery=TcpDiscoverySpi [addrRslvr=null, sockTimeout=5000, ackTimeout=5000, marsh=JdkMarshaller [clsFilter=org.apache.ignite.marshaller.MarshallerUtils$1@729107f1], reconCnt=10, reconDelay=2000, maxAckTimeout=600000, forceSrvMode=false, clientReconnectDisabled=false, internalLsnr=null], binaryCfg=null, lateAff=true]
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][root] Stop node: 2
> [2018-07-17 11:52:45,336][INFO ][restart-thread-1][root] >>> Stopping grid [name=cache.Reproducer2, id=e0c5902c-6196-4a7d-b9de-1d007bd00002]
> [2018-07-17 11:52:45,338][INFO ][sys-#462%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=20, minorTopVer=18], node=b3ea935b-7eaf-440c-9408-346192500004, allReceived=true]
> [2018-07-17 11:52:45,338][INFO ][sys-#462%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> [2018-07-17 11:52:45,340][INFO ][sys-#462%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], err=null]
> [2018-07-17 11:52:45,341][INFO ][sys-#462%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=e0c5902c-6196-4a7d-b9de-1d007bd00002, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817543893, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true], topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], durationFromInit=93]
> [2018-07-17 11:52:45,344][INFO ][exchange-worker-#455%cache.Reproducer2%][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, node=29209c33-9cb5-4732-acd4-932e5f600005]
> [2018-07-17 11:52:45,346][INFO ][sys-#517%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=e0c5902c-6196-4a7d-b9de-1d007bd00002, resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> [2018-07-17 11:52:45,346][INFO ][sys-#517%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], err=null]
> [2018-07-17 11:52:45,346][INFO ][sys-#517%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=1f04dca5-0424-460c-96f6-1736f0900003, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true], topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], durationFromInit=83]
> [2018-07-17 11:52:45,347][INFO ][sys-#628%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=e0c5902c-6196-4a7d-b9de-1d007bd00002, resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> [2018-07-17 11:52:45,348][INFO ][sys-#628%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], err=null]
> [2018-07-17 11:52:45,348][INFO ][sys-#628%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=214d8ef6-bae8-4b6f-9947-33c451e00000, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true], topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], durationFromInit=83]
> [2018-07-17 11:52:45,349][INFO ][sys-#677%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=e0c5902c-6196-4a7d-b9de-1d007bd00002, resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> [2018-07-17 11:52:45,350][INFO ][sys-#677%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], err=null]
> [2018-07-17 11:52:45,350][INFO ][sys-#677%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=c6cbf88b-2f79-4562-813d-b630eb800001, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true], topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], durationFromInit=83]
> [2018-07-17 11:52:45,352][INFO ][exchange-worker-#619%cache.Reproducer0%][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, node=29209c33-9cb5-4732-acd4-932e5f600005]
> [2018-07-17 11:52:45,352][INFO ][exchange-worker-#673%cache.Reproducer1%][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, node=29209c33-9cb5-4732-acd4-932e5f600005]
> [2018-07-17 11:52:45,359][INFO ][sys-#566%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=e0c5902c-6196-4a7d-b9de-1d007bd00002, resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> [2018-07-17 11:52:45,360][INFO ][sys-#566%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], resVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], err=null]
> [2018-07-17 11:52:45,360][INFO ][sys-#566%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=b3ea935b-7eaf-440c-9408-346192500004, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true], topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], durationFromInit=90]
> [2018-07-17 11:52:45,366][INFO ][exchange-worker-#673%cache.Reproducer1%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=e0c5902c-6196-4a7d-b9de-1d007bd00002, customEvt=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false]
> [2018-07-17 11:52:45,366][INFO ][exchange-worker-#673%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,368][INFO ][exchange-worker-#509%cache.Reproducer3%][GridCachePartitionExchangeManager] Skipping rebalancing (obsolete exchange ID) [top=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, node=29209c33-9cb5-4732-acd4-932e5f600005]
> [2018-07-17 11:52:45,368][INFO ][exchange-worker-#509%cache.Reproducer3%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=e0c5902c-6196-4a7d-b9de-1d007bd00002, customEvt=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false]
> [2018-07-17 11:52:45,368][INFO ][exchange-worker-#509%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,372][INFO ][exchange-worker-#619%cache.Reproducer0%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=e0c5902c-6196-4a7d-b9de-1d007bd00002, customEvt=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false]
> [2018-07-17 11:52:45,372][INFO ][exchange-worker-#619%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,373][INFO ][exchange-worker-#564%cache.Reproducer4%][GridCachePartitionExchangeManager] Skipping rebalancing (obsolete exchange ID) [top=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, node=29209c33-9cb5-4732-acd4-932e5f600005]
> [2018-07-17 11:52:45,373][INFO ][exchange-worker-#564%cache.Reproducer4%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=e0c5902c-6196-4a7d-b9de-1d007bd00002, customEvt=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false]
> [2018-07-17 11:52:45,374][INFO ][exchange-worker-#564%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,375][INFO ][restart-thread-1][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], resVer=null, err=class org.apache.ignite.internal.IgniteInterruptedCheckedException: Node is stopping: cache.Reproducer2]
> [2018-07-17 11:52:45,375][INFO ][restart-thread-1][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=e0c5902c-6196-4a7d-b9de-1d007bd00002, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817565364, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=true], topVer=null, durationFromInit=1531817565374]
> [2018-07-17 11:52:45,375][ERROR][jvm-pause-detector-worker][Reproducer2] jvm-pause-detector-worker has been interrupted
> java.lang.InterruptedException: sleep interrupted
> at java.lang.Thread.sleep(Native Method)
> at org.apache.ignite.internal.LongJVMPauseDetector$1.run(LongJVMPauseDetector.java:97)
> [2018-07-17 11:52:45,388][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] Node left topology: TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:45,389][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] Topology snapshot [ver=21, servers=4, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:45,389][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] ^-- Node [id=1F04DCA5-0424-460C-96F6-1736F0900003, clusterState=ACTIVE]
> [2018-07-17 11:52:45,389][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:45,389][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:45,390][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] Node left topology: TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:45,390][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] Topology snapshot [ver=21, servers=4, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:45,391][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] ^-- Node [id=B3EA935B-7EAF-440C-9408-346192500004, clusterState=ACTIVE]
> [2018-07-17 11:52:45,391][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:45,391][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:45,392][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] Node left topology: TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:45,392][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] Topology snapshot [ver=21, servers=4, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:45,392][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] ^-- Node [id=214D8EF6-BAE8-4B6F-9947-33C451E00000, clusterState=ACTIVE]
> [2018-07-17 11:52:45,392][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:45,392][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:45,394][INFO ][tcp-disco-msg-worker-#132%cache.Reproducer1%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]]
> [2018-07-17 11:52:45,394][INFO ][tcp-disco-sock-reader-#137%cache.Reproducer2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:43677, rmtPort=43677
> [2018-07-17 11:52:45,394][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] Node left topology: TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:45,394][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] Topology snapshot [ver=21, servers=4, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:45,395][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] ^-- Node [id=C6CBF88B-2F79-4562-813D-B630EB800001, clusterState=ACTIVE]
> [2018-07-17 11:52:45,395][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:45,395][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:45,395][INFO ][tcp-disco-srvr-#97%cache.Reproducer3%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=45405]
> [2018-07-17 11:52:45,395][INFO ][tcp-disco-srvr-#97%cache.Reproducer3%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=45405]
> [2018-07-17 11:52:45,405][INFO ][tcp-disco-sock-reader-#139%cache.Reproducer3%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:45405, rmtPort=45405]
> [2018-07-17 11:52:45,440][INFO ][sys-#518%cache.Reproducer3%][ExchangeLatchManager] Become new coordinator 1f04dca5-0424-460c-96f6-1736f0900003
> [2018-07-17 11:52:45,440][INFO ][exchange-worker-#673%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19]]]
> [2018-07-17 11:52:45,440][INFO ][exchange-worker-#673%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,442][ERROR][exchange-worker-#673%cache.Reproducer1%][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=GridDhtPartitionsSingleMessage [parts={-2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=159, size=100], -1368047381=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=456, size=396], -433538905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=5, size=0]}, partCntrs={-2100569601=CachePartitionPartialCountersMap {}, -1368047381=CachePartitionPartialCountersMap {149=(0,3), 151=(0,3), 154=(0,3), 155=(0,3), 577=(0,3), 578=(0,3), 582=(0,3), 600=(0,3), 602=(0,3), 610=(0,3), 615=(0,3), 632=(0,3), 633=(0,3), 634=(0,3), 640=(0,2), 642=(0,2), 645=(0,2), 646=(0,2), 664=(0,2), 673=(0,3), 676=(0,3), 697=(0,3), 708=(0,2), 718=(0,2), 719=(0,2), 741=(0,2), 782=(0,2), 783=(0,2), 800=(0,2), 803=(0,2), 815=(0,2), 864=(0,2), 867=(0,2)}, -433538905=CachePartitionPartialCountersMap {}}, partsSizes={-1368047381={640=1, 577=1, 578=1, 642=1, 708=1, 645=1, 582=1, 646=1, 718=1, 782=1, 719=1, 783=1, 149=1, 151=1, 600=1, 664=1, 154=1, 602=1, 155=1, 800=1, 864=1, 673=1, 610=1, 803=1, 867=1, 676=1, 741=1, 615=1, 815=1, 632=1, 633=1, 697=1, 634=1}}, partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null, super=GridDhtPartitionsAbstractMessage [exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=c6cbf88b, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], lastVer=GridCacheVersion [topVer=143297545, order=1531817562741, nodeOrder=20], super=GridCacheMessage [msgId=5629, depInfo=null, err=null, skipPrepare=false]]]]]
> class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3260)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2977)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2860)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2703)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2662)
> 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:1536)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1643)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1223)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:732)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2484)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2364)
> at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
> at java.lang.Thread.run(Thread.java:748)
> [2018-07-17 11:52:45,442][INFO ][exchange-worker-#673%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Coordinator changed, send partitions to new coordinator [ver=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=e0c5902c-6196-4a7d-b9de-1d007bd00002, newCrd=1f04dca5-0424-460c-96f6-1736f0900003]
> [2018-07-17 11:52:45,442][INFO ][exchange-worker-#673%cache.Reproducer1%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false]
> [2018-07-17 11:52:45,443][INFO ][exchange-worker-#564%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19]]]
> [2018-07-17 11:52:45,443][INFO ][exchange-worker-#564%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,444][ERROR][exchange-worker-#564%cache.Reproducer4%][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=GridDhtPartitionsSingleMessage [parts={-2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=784, size=100], -1368047381=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=1316, size=430], -433538905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=5, size=0]}, partCntrs={-2100569601=CachePartitionPartialCountersMap {}, -1368047381=CachePartitionPartialCountersMap {148=(0,2), 149=(0,3), 151=(0,3), 152=(0,2), 153=(0,3), 577=(0,3), 578=(0,3), 579=(0,3), 580=(0,3), 581=(0,3), 582=(0,3), 601=(0,3), 602=(0,3), 610=(0,3), 612=(0,3), 613=(0,3), 632=(0,3), 640=(0,2), 641=(0,2), 643=(0,2), 655=(0,3), 672=(0,3), 673=(0,3), 674=(0,3), 675=(0,3), 679=(0,3), 704=(0,2), 705=(0,2), 706=(0,2), 707=(0,2), 708=(0,2), 710=(0,2), 717=(0,2), 718=(0,2), 737=(0,2), 738=(0,2), 741=(0,2), 742=(0,2), 743=(0,2), 751=(0,2), 780=(0,2), 783=(0,2), 800=(0,2), 802=(0,2), 804=(0,2), 813=(0,2), 814=(0,2), 815=(0,2), 864=(0,2), 875=(0,2), 876=(0,2), 878=(0,1)}, -433538905=CachePartitionPartialCountersMap {}}, partsSizes={-1368047381={704=1, 641=1, 705=1, 578=1, 706=1, 579=1, 643=1, 707=1, 580=1, 581=1, 710=1, 780=1, 717=1, 655=1, 783=1, 153=1, 601=1, 672=1, 864=1, 673=1, 737=1, 674=1, 738=1, 802=1, 675=1, 612=1, 804=1, 613=1, 742=1, 679=1, 743=1, 875=1, 876=1, 813=1, 814=1, 751=1, 815=1, 632=1}}, partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null, super=GridDhtPartitionsAbstractMessage [exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=b3ea935b, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], lastVer=GridCacheVersion [topVer=143297545, order=1531817562757, nodeOrder=16], super=GridCacheMessage [msgId=5631, depInfo=null, err=null, skipPrepare=false]]]]]
> class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3260)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2977)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2860)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2703)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2662)
> 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:1536)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1643)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1223)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:732)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2484)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2364)
> at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
> at java.lang.Thread.run(Thread.java:748)
> [2018-07-17 11:52:45,444][INFO ][exchange-worker-#564%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Coordinator changed, send partitions to new coordinator [ver=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=e0c5902c-6196-4a7d-b9de-1d007bd00002, newCrd=1f04dca5-0424-460c-96f6-1736f0900003]
> [2018-07-17 11:52:45,444][INFO ][exchange-worker-#564%cache.Reproducer4%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false]
> [2018-07-17 11:52:45,445][INFO ][exchange-worker-#509%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817565415, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19]]]
> [2018-07-17 11:52:45,445][INFO ][exchange-worker-#509%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,446][ERROR][exchange-worker-#509%cache.Reproducer3%][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=GridDhtPartitionsSingleMessage [parts={-2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=913, size=100], -1368047381=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=1541, size=406], -433538905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=5, size=0]}, partCntrs={-2100569601=CachePartitionPartialCountersMap {}, -1368047381=CachePartitionPartialCountersMap {152=(0,3), 153=(0,2), 154=(0,3), 155=(0,3), 156=(0,3), 158=(0,3), 159=(0,3), 578=(0,3), 579=(0,3), 580=(0,3), 583=(0,3), 601=(0,3), 602=(0,3), 611=(0,3), 612=(0,3), 614=(0,3), 615=(0,3), 632=(0,3), 634=(0,3), 635=(0,3), 640=(0,2), 641=(0,2), 642=(0,2), 643=(0,2), 644=(0,2), 645=(0,2), 647=(0,2), 655=(0,3), 675=(0,3), 676=(0,3), 677=(0,3), 678=(0,3), 696=(0,3), 697=(0,3), 704=(0,2), 707=(0,1), 709=(0,1), 736=(0,2), 737=(0,2), 738=(0,1), 740=(0,2), 750=(0,2), 768=(0,2), 769=(0,2), 771=(0,2), 772=(0,2), 780=(0,2), 781=(0,2), 783=(0,2), 801=(0,1), 803=(0,2), 805=(0,2), 812=(0,2), 814=(0,1), 866=(0,2), 867=(0,2), 874=(0,1), 876=(0,1), 877=(0,2), 879=(0,2)}, -433538905=CachePartitionPartialCountersMap {}}, partsSizes={-1368047381={640=1, 704=1, 768=1, 769=1, 579=1, 771=1, 580=1, 644=1, 772=1, 645=1, 583=1, 647=1, 780=1, 781=1, 655=1, 152=1, 601=1, 602=1, 156=1, 158=1, 159=1, 736=1, 737=1, 866=1, 611=1, 675=1, 612=1, 676=1, 740=1, 677=1, 805=1, 614=1, 678=1, 812=1, 877=1, 750=1, 879=1, 696=1, 635=1}}, partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null, super=GridDhtPartitionsAbstractMessage [exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=1f04dca5, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], lastVer=GridCacheVersion [topVer=143297545, order=1531817562757, nodeOrder=14], super=GridCacheMessage [msgId=5633, depInfo=null, err=null, skipPrepare=false]]]]]
> class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3260)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2977)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2860)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2703)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2662)
> 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:1536)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1643)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1223)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:732)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2484)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2364)
> at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
> at java.lang.Thread.run(Thread.java:748)
> [2018-07-17 11:52:45,446][INFO ][exchange-worker-#509%cache.Reproducer3%][GridDhtPartitionsExchangeFuture] Coordinator failed, node is new coordinator [ver=AffinityTopologyVersion [topVer=20, minorTopVer=19], prev=e0c5902c-6196-4a7d-b9de-1d007bd00002]
> [2018-07-17 11:52:45,447][INFO ][exchange-worker-#509%cache.Reproducer3%][InitNewCoordinatorFuture] Init new coordinator, node left [node=e0c5902c-6196-4a7d-b9de-1d007bd00002]
> [2018-07-17 11:52:45,447][INFO ][exchange-worker-#509%cache.Reproducer3%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false]
> [2018-07-17 11:52:45,447][INFO ][sys-#514%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=c6cbf88b-2f79-4562-813d-b630eb800001, nodeOrder=20, ver=AffinityTopologyVersion [topVer=20, minorTopVer=19]]
> [2018-07-17 11:52:45,447][INFO ][sys-#513%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=b3ea935b-7eaf-440c-9408-346192500004, nodeOrder=16, ver=AffinityTopologyVersion [topVer=20, minorTopVer=19]]
> [2018-07-17 11:52:45,447][INFO ][exchange-worker-#619%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19]]]
> [2018-07-17 11:52:45,447][INFO ][exchange-worker-#619%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:45,448][ERROR][exchange-worker-#619%cache.Reproducer0%][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=GridDhtPartitionsSingleMessage [parts={-2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=666, size=100], -1368047381=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=1036, size=382], -433538905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=20, minorTopVer=19], updateSeq=5, size=0]}, partCntrs={-2100569601=CachePartitionPartialCountersMap {}, -1368047381=CachePartitionPartialCountersMap {148=(0,3), 151=(0,3), 152=(0,3), 156=(0,3), 158=(0,3), 577=(0,3), 581=(0,3), 600=(0,3), 611=(0,3), 613=(0,3), 615=(0,3), 633=(0,3), 641=(0,2), 642=(0,2), 643=(0,2), 644=(0,2), 646=(0,2), 647=(0,2), 664=(0,2), 672=(0,3), 673=(0,3), 676=(0,3), 678=(0,3), 697=(0,3), 705=(0,2), 709=(0,2), 710=(0,2), 719=(0,2), 739=(0,2), 770=(0,2), 772=(0,2), 779=(0,2), 781=(0,2), 782=(0,2), 800=(0,2), 801=(0,2), 864=(0,2), 865=(0,2), 867=(0,2), 874=(0,2), 878=(0,2)}, -433538905=CachePartitionPartialCountersMap {}}, partsSizes={-1368047381={577=1, 641=1, 705=1, 642=1, 770=1, 643=1, 644=1, 772=1, 581=1, 709=1, 646=1, 710=1, 647=1, 779=1, 781=1, 782=1, 148=1, 151=1, 152=1, 664=1, 156=1, 158=1, 672=1, 800=1, 801=1, 865=1, 611=1, 739=1, 867=1, 613=1, 678=1, 615=1, 874=1, 878=1, 697=1}}, partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null, super=GridDhtPartitionsAbstractMessage [exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=214d8ef6, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], lastVer=GridCacheVersion [topVer=143297545, order=1531817562752, nodeOrder=18], super=GridCacheMessage [msgId=5634, depInfo=null, err=null, skipPrepare=false]]]]]
> class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3260)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2977)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2860)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2703)
> at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2662)
> 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:1536)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1643)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1223)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:732)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2484)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2364)
> at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
> at java.lang.Thread.run(Thread.java:748)
> [2018-07-17 11:52:45,449][INFO ][exchange-worker-#619%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Coordinator changed, send partitions to new coordinator [ver=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=e0c5902c-6196-4a7d-b9de-1d007bd00002, newCrd=1f04dca5-0424-460c-96f6-1736f0900003]
> [2018-07-17 11:52:45,449][INFO ][exchange-worker-#619%cache.Reproducer0%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], crd=false]
> [2018-07-17 11:52:45,449][INFO ][sys-#517%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=214d8ef6-bae8-4b6f-9947-33c451e00000, nodeOrder=18, ver=AffinityTopologyVersion [topVer=20, minorTopVer=19]]
> [2018-07-17 11:52:45,470][INFO ][sys-#512%cache.Reproducer3%][InitNewCoordinatorFuture] Init new coordinator future will skip remote node: TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:45,470][INFO ][sys-#512%cache.Reproducer3%][InitNewCoordinatorFuture] Try restore exchange result [awaited=[c6cbf88b-2f79-4562-813d-b630eb800001, 29209c33-9cb5-4732-acd4-932e5f600005, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000], joined=[], nodes=[29209c33-9cb5-4732-acd4-932e5f600005, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000, c6cbf88b-2f79-4562-813d-b630eb800001], discoAllNodes=[29209c33-9cb5-4732-acd4-932e5f600005, e0c5902c-6196-4a7d-b9de-1d007bd00002, 1f04dca5-0424-460c-96f6-1736f0900003, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000, c6cbf88b-2f79-4562-813d-b630eb800001]]
> [2018-07-17 11:52:45,470][INFO ][tcp-disco-sock-reader-#123%cache.Reproducer2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:56489, rmtPort=56489
> [2018-07-17 11:52:45,471][INFO ][sys-#573%cache.Reproducer4%][GridDhtPartitionsExchangeFuture] Send restore state response [node=1f04dca5-0424-460c-96f6-1736f0900003, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], hasState=false, affReq=false]
> [2018-07-17 11:52:45,472][INFO ][sys-#625%cache.Reproducer0%][GridDhtPartitionsExchangeFuture] Send restore state response [node=1f04dca5-0424-460c-96f6-1736f0900003, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], hasState=false, affReq=false]
> [2018-07-17 11:52:45,472][INFO ][sys-#679%cache.Reproducer1%][GridDhtPartitionsExchangeFuture] Send restore state response [node=1f04dca5-0424-460c-96f6-1736f0900003, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], hasState=false, affReq=false]
> [2018-07-17 11:52:45,473][INFO ][sys-#518%cache.Reproducer3%][InitNewCoordinatorFuture] Init new coordinator, received response [node=214d8ef6-bae8-4b6f-9947-33c451e00000, fullMsg=false, affReq=false]
> [2018-07-17 11:52:45,474][INFO ][sys-#511%cache.Reproducer3%][InitNewCoordinatorFuture] Init new coordinator, received response [node=b3ea935b-7eaf-440c-9408-346192500004, fullMsg=false, affReq=false]
> [2018-07-17 11:52:45,475][INFO ][sys-#515%cache.Reproducer3%][InitNewCoordinatorFuture] Init new coordinator, received response [node=c6cbf88b-2f79-4562-813d-b630eb800001, fullMsg=false, affReq=false]
> [2018-07-17 11:52:45,476][INFO ][restart-thread-1][GridCacheProcessor] Stopped cache [cacheName=ignite-sys-cache]
> [2018-07-17 11:52:45,480][INFO ][restart-thread-1][GridCacheProcessor] Stopped cache [cacheName=cache-]
> [2018-07-17 11:52:45,480][INFO ][restart-thread-1][GridCacheProcessor] Stopped cache [cacheName=cache-40]
> [2018-07-17 11:52:45,481][INFO ][restart-thread-1][GridDeploymentLocalStore] Removed undeployed class: GridDeployment [ts=1531817544096, depMode=SHARED, clsLdr=sun.misc.Launcher$AppClassLoader@18b4aac2, clsLdrId=709a077a461-e0c5902c-6196-4a7d-b9de-1d007bd00002, userVer=0, loc=true, sampleClsName=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap, pendingUndeploy=false, undeployed=true, usage=0]
> [2018-07-17 11:52:45,481][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager$6
> [2018-07-17 11:52:45,481][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1
> [2018-07-17 11:52:45,481][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.GridTopic$T6
> [2018-07-17 11:52:45,481][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtPartitionsEvictor$PartitionEvictionTask
> [2018-07-17 11:52:45,481][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.CachePartitionPartialCountersMap
> [2018-07-17 11:52:45,481][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtDemandedPartitionsMap
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap2
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.CachePartitionFullCountersMap
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionDemander
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.latch.ExchangeLatchManager
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.service.GridServiceProcessor$ServiceDeploymentPredicate
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.latch.ExchangeLatchManager
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class java.util.Collections$UnmodifiableMap
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.GridCacheProcessor$RemovedItemsCleanupTask$1
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ResendTimeoutObject$1
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.service.GridServiceProcessor$ServiceAssignmentsPredicate
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject$2
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionDemander
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1
> [2018-07-17 11:52:45,482][INFO ][restart-thread-1][GridDeploymentLocalStore] Class locally undeployed: class org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap
> [2018-07-17 11:52:45,484][INFO ][restart-thread-1][Reproducer2]
> >>> +-----------------------------------------------------+
> >>> Ignite ver. 2.7.0-SNAPSHOT#19700101-sha1:DEV stopped OK
> >>> +-----------------------------------------------------+
> >>> Ignite instance name: cache.Reproducer2
> >>> Grid uptime: 00:00:19.753
> [2018-07-17 11:52:45,485][INFO ][restart-thread-1][root] Topology version mismatch [node=cache.Reproducer1, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0]]
> [2018-07-17 11:52:46,333][ERROR][tcp-client-disco-sock-writer-#52%cache.Reproducer5%][TestTcpDiscoverySpi] Failed to send message: TcpDiscoveryClientMetricsUpdateMessage [super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=9822177a461-29209c33-9cb5-4732-acd4-932e5f600005, verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null, isClient=true]]
> java.net.SocketException: Socket is closed
> at java.net.Socket.getSendBufferSize(Socket.java:1215)
> at org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.socketStream(TcpDiscoverySpi.java:1476)
> at org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi.writeToSocket(TcpDiscoverySpi.java:1588)
> at org.apache.ignite.spi.discovery.tcp.ClientImpl$SocketWriter.body(ClientImpl.java:1316)
> at org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
> [2018-07-17 11:52:46,377][INFO ][sys-#514%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=c6cbf88b-2f79-4562-813d-b630eb800001, nodeOrder=20, ver=null]
> [2018-07-17 11:52:46,677][INFO ][tcp-disco-srvr-#97%cache.Reproducer3%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49245]
> [2018-07-17 11:52:46,677][INFO ][tcp-disco-srvr-#97%cache.Reproducer3%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49245]
> [2018-07-17 11:52:46,677][INFO ][tcp-disco-sock-reader-#141%cache.Reproducer3%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49245, rmtPort=49245]
> [2018-07-17 11:52:46,706][INFO ][disco-event-worker-#256%cache.Reproducer5%][GridDiscoveryManager] Node left topology: TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817543840, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:46,706][INFO ][disco-event-worker-#256%cache.Reproducer5%][GridDiscoveryManager] Topology snapshot [ver=21, servers=4, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:46,706][INFO ][disco-event-worker-#256%cache.Reproducer5%][GridDiscoveryManager] ^-- Node [id=29209C33-9CB5-4732-ACD4-932E5F600005, clusterState=ACTIVE]
> [2018-07-17 11:52:46,708][INFO ][disco-event-worker-#256%cache.Reproducer5%][GridDhtPartitionsExchangeFuture] Coordinator changed, send partitions to new coordinator [ver=AffinityTopologyVersion [topVer=20, minorTopVer=18], crd=e0c5902c-6196-4a7d-b9de-1d007bd00002, newCrd=1f04dca5-0424-460c-96f6-1736f0900003]
> [2018-07-17 11:52:46,708][INFO ][sys-#513%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=29209c33-9cb5-4732-acd4-932e5f600005, nodeOrder=6, ver=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> [2018-07-17 11:52:46,849][INFO ][sys-#517%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=214d8ef6-bae8-4b6f-9947-33c451e00000, nodeOrder=18, ver=null]
> [2018-07-17 11:52:46,866][INFO ][sys-#512%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=b3ea935b-7eaf-440c-9408-346192500004, nodeOrder=16, ver=null]
> [2018-07-17 11:52:47,487][INFO ][restart-thread-1][root] Topology version mismatch [node=cache.Reproducer3, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0]]
> [2018-07-17 11:52:49,688][INFO ][restart-thread-1][root] Topology version mismatch [node=cache.Reproducer4, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0]]
> [2018-07-17 11:52:51,691][INFO ][restart-thread-1][root] Topology version mismatch [node=cache.Reproducer5, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0]]
> [2018-07-17 11:52:53,693][INFO ][restart-thread-1][root] Topology version mismatch [node=cache.Reproducer0, exchVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0]]
> [2018-07-17 11:52:56,395][INFO ][restart-thread-1][root] Start node: 2
> [2018-07-17 11:52:56,419][INFO ][restart-thread-1][Reproducer2]
> >>> __________ ________________
> >>> / _/ ___/ |/ / _/_ __/ __/
> >>> _/ // (7 7 // / / / / _/
> >>> /___/\___/_/|_/___/ /_/ /___/
> >>>
> >>> ver. 2.7.0-SNAPSHOT#19700101-sha1:DEV
> >>> 2018 Copyright(C) Apache Software Foundation
> >>>
> >>> Ignite documentation: http://ignite.apache.org
> [2018-07-17 11:52:56,419][INFO ][restart-thread-1][Reproducer2] Config URL: n/a
> [2018-07-17 11:52:56,421][INFO ][restart-thread-1][Reproducer2] IgniteConfiguration [igniteInstanceName=cache.Reproducer2, pubPoolSize=8, svcPoolSize=8, callbackPoolSize=8, stripedPoolSize=8, sysPoolSize=8, mgmtPoolSize=4, igfsPoolSize=1, dataStreamerPoolSize=8, utilityCachePoolSize=8, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=8, igniteHome=/home/xtern/src/ignite, igniteWorkDir=/home/xtern/src/ignite/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@12bc6874, nodeId=ecef4400-64d6-4b8e-a1d7-3acfca700002, marsh=org.apache.ignite.internal.binary.BinaryMarshaller@1a740c6b, marshLocJobs=false, daemon=false, p2pEnabled=true, netTimeout=10000, sndRetryDelay=1000, sndRetryCnt=3, metricsHistSize=10000, metricsUpdateFreq=1000, metricsExpTime=9223372036854775807, discoSpi=TcpDiscoverySpi [addrRslvr=null, sockTimeout=0, ackTimeout=0, marsh=null, reconCnt=10, reconDelay=2000, maxAckTimeout=600000, forceSrvMode=false, clientReconnectDisabled=false, internalLsnr=null], segPlc=STOP, segResolveAttempts=2, waitForSegOnStart=true, allResolversPassReq=true, segChkFreq=10000, commSpi=TcpCommunicationSpi [connectGate=null, connPlc=null, enableForcibleNodeKill=false, enableTroubleshootingLog=false, srvLsnr=org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$2@56d3f6d1, locAddr=null, locHost=null, locPort=45010, locPortRange=100, shmemPort=-1, directBuf=true, directSndBuf=false, idleConnTimeout=600000, connTimeout=5000, maxConnTimeout=600000, reconCnt=10, sockSndBuf=32768, sockRcvBuf=32768, msgQueueLimit=0, slowClientQueueLimit=0, nioSrvr=null, shmemSrv=null, usePairedConnections=false, connectionsPerNode=1, tcpNoDelay=true, filterReachableAddresses=false, ackSndThreshold=32, unackedMsgsBufSize=0, sockWriteTimeout=2000, lsnr=null, boundTcpPort=-1, boundTcpShmemPort=-1, selectorsCnt=4, selectorSpins=0, addrRslvr=null, ctxInitLatch=java.util.concurrent.CountDownLatch@6aea639d[Count = 1], stopping=false, metricsLsnr=org.apache.ignite.spi.communication.tcp.TcpCommunicationMetricsListener@ba3ef78], evtSpi=MemoryEventStorageSpi [expireAgeMs=9223372036854775807, expireCnt=10000, filter=null], colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [lsnr=null], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@318ead33, addrRslvr=null, clientMode=false, rebalanceThreadPoolSize=1, txCfg=org.apache.ignite.configuration.TransactionConfiguration@7822b0ad, cacheSanityCheckEnabled=true, discoStartupDelay=60000, deployMode=SHARED, p2pMissedCacheSize=100, locHost=127.0.0.1, timeSrvPortBase=31100, timeSrvPortRange=100, failureDetectionTimeout=10000, clientFailureDetectionTimeout=10000, metricsLogFreq=0, hadoopCfg=null, connectorCfg=null, odbcCfg=null, warmupClos=null, atomicCfg=AtomicConfiguration [seqReserveSize=1000, cacheMode=PARTITIONED, backups=1, aff=null, grpName=null], classLdr=null, sslCtxFactory=null, platformCfg=null, binaryCfg=null, memCfg=null, pstCfg=null, dsCfg=DataStorageConfiguration [sysRegionInitSize=41943040, sysRegionMaxSize=104857600, pageSize=0, concLvl=0, dfltDataRegConf=DataRegionConfiguration [name=default, maxSize=3339038720, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=false, checkpointPageBufSize=0], storagePath=null, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, walSegments=10, walSegmentSize=67108864, walPath=db/wal, walArchivePath=db/wal/archive, metricsEnabled=false, walMode=LOG_ONLY, walTlbSize=131072, walBuffSize=0, walFlushFreq=2000, walFsyncDelay=1000, walRecordIterBuffSize=67108864, alwaysWriteFullPages=false, fileIOFactory=org.apache.ignite.internal.processors.cache.persistence.file.AsyncFileIOFactory@41edd2bf, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false], activeOnStart=true, autoActivation=true, longQryWarnTimeout=3000, sqlConnCfg=null, cliConnCfg=ClientConnectorConfiguration [host=null, port=10800, portRange=100, sockSndBufSize=0, sockRcvBufSize=0, tcpNoDelay=true, maxOpenCursorsPerConn=128, threadPoolSize=8, idleTimeout=0, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=false, useIgniteSslCtxFactory=true, sslClientAuth=false, sslCtxFactory=null], authEnabled=false, failureHnd=NoOpFailureHandler [], commFailureRslvr=null]
> [2018-07-17 11:52:56,421][INFO ][restart-thread-1][Reproducer2] Daemon mode: off
> [2018-07-17 11:52:56,421][INFO ][restart-thread-1][Reproducer2] OS: Linux 4.13.0-45-generic amd64
> [2018-07-17 11:52:56,421][INFO ][restart-thread-1][Reproducer2] OS user: xtern
> [2018-07-17 11:52:56,421][INFO ][restart-thread-1][Reproducer2] PID: 6154
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] Language runtime: Java Platform API Specification ver. 1.8
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] VM information: Java(TM) SE Runtime Environment 1.8.0_152-b16 Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 25.152-b16
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] VM total memory: 3.8GB
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] Remote Management [restart: off, REST: off, JMX (remote: off)]
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] Logger: GridTestLog4jLogger [quiet=false, config=null]
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] IGNITE_HOME=/home/xtern/src/ignite
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] VM arguments: [-ea, -DdomainJar=/home/xtern/src/ignite/modules/core/target/domainlib/domain.jar, -Djavax.management.builder.initial=org.apache.ignite.internal.tck.TCKMBeanServerBuilder, -Dorg.jsr107.tck.management.agentId=IgniteMBeanServer, -Djavax.cache.CacheManager=org.apache.ignite.cache.CacheManager, -Djavax.cache.Cache=org.apache.ignite.IgniteCache, -Djavax.cache.Cache.Entry=org.apache.ignite.internal.processors.cache.CacheEntryImpl, -Djavax.cache.annotation.CacheInvocationContext=javax.cache.annotation.impl.cdi.CdiCacheKeyInvocationContextImpl, -DIGNITE_QUIET=false, -Didea.test.cyclic.buffer.size=12641280, -javaagent:/home/xtern/tools/ide/idea-IU-181.4203.550/lib/idea_rt.jar=41623:/home/xtern/tools/ide/idea-IU-181.4203.550/bin, -Dfile.encoding=UTF-8]
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemCacheMemorySize property to change the setting.
> [2018-07-17 11:52:56,422][INFO ][restart-thread-1][Reproducer2] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache']]
> [2018-07-17 11:52:56,422][WARN ][restart-thread-1][Reproducer2] Peer class loading is enabled (disable it in production for performance and deployment consistency reasons)
> [2018-07-17 11:52:56,422][WARN ][restart-thread-1][Reproducer2] Please set system property '-Djava.net.preferIPv4Stack=true' to avoid possible problems in mixed environments.
> [2018-07-17 11:52:56,444][INFO ][restart-thread-1][Reproducer2] 3-rd party licenses can be found at: /home/xtern/src/ignite/libs/licenses
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor] Configured plugins:
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor] ^-- TestReconnectPlugin 1.0
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor] ^--
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor]
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor] ^-- StanByClusterTestProvider 1.0
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor] ^-- null
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor]
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor] ^-- PageMemory tracker plugin 1.0
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor] ^--
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][IgnitePluginProcessor]
> [2018-07-17 11:52:56,446][INFO ][restart-thread-1][FailureProcessor] Configured failure handler: [hnd=NoOpFailureHandler []]
> [2018-07-17 11:52:56,460][WARN ][pub-#715%cache.Reproducer2%][GridDiagnostic] Initial heap size is 250MB (should be no less than 512MB, use -Xms512m -Xmx512m).
> [2018-07-17 11:52:56,472][INFO ][restart-thread-1][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=45013, locHost=/127.0.0.1, selectorsCnt=4, selectorSpins=0, pairedConn=false]
> [2018-07-17 11:52:56,472][WARN ][restart-thread-1][TcpCommunicationSpi] Message queue limit is set to 0 which may lead to potential OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due to message queues growth on sender and receiver sides.
> [2018-07-17 11:52:56,507][WARN ][restart-thread-1][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival).
> [2018-07-17 11:52:56,507][INFO ][restart-thread-1][Reproducer2] Security status [authentication=off, tls/ssl=off]
> [2018-07-17 11:52:56,532][INFO ][restart-thread-1][ClientListenerProcessor] Client connector processor has started on TCP port 10801
> [2018-07-17 11:52:56,539][INFO ][restart-thread-1][Reproducer2] Non-loopback local IPs: 10.38.150.94, fe80:0:0:0:d5da:1e0d:1a57:c6a1%wlp2s0
> [2018-07-17 11:52:56,539][INFO ][restart-thread-1][Reproducer2] Enabled local MACs: 9CDA3EE8CADD
> [2018-07-17 11:52:56,559][INFO ][restart-thread-1][TestTcpDiscoverySpi] Connection check frequency is calculated: 3333
> [2018-07-17 11:52:56,560][INFO ][restart-thread-1][TestTcpDiscoverySpi] Successfully bound to TCP port [port=47501, localHost=/127.0.0.1, locNodeId=ecef4400-64d6-4b8e-a1d7-3acfca700002]
> [2018-07-17 11:52:57,781][INFO ][tcp-disco-srvr-#108%cache.Reproducer4%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=55221]
> [2018-07-17 11:52:57,781][INFO ][tcp-disco-srvr-#108%cache.Reproducer4%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=55221]
> [2018-07-17 11:52:57,782][INFO ][tcp-disco-sock-reader-#148%cache.Reproducer4%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:55221, rmtPort=55221]
> [2018-07-17 11:52:57,805][INFO ][tcp-disco-msg-worker-#132%cache.Reproducer1%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=0, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]]
> [2018-07-17 11:52:57,806][INFO ][tcp-disco-srvr-#146%cache.Reproducer2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=51235]
> [2018-07-17 11:52:57,806][INFO ][tcp-disco-srvr-#146%cache.Reproducer2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=51235]
> [2018-07-17 11:52:57,815][INFO ][tcp-disco-sock-reader-#139%cache.Reproducer3%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:45405, rmtPort=45405
> [2018-07-17 11:52:57,826][INFO ][tcp-disco-sock-reader-#148%cache.Reproducer4%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:55221, rmtPort=55221
> [2018-07-17 11:52:57,837][INFO ][tcp-disco-sock-reader-#149%cache.Reproducer2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:51235, rmtPort=51235]
> [2018-07-17 11:52:57,846][INFO ][tcp-disco-msg-worker-#145%cache.Reproducer2%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817577837, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]]
> [2018-07-17 11:52:57,847][INFO ][tcp-disco-srvr-#97%cache.Reproducer3%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=55483]
> [2018-07-17 11:52:57,847][INFO ][tcp-disco-srvr-#97%cache.Reproducer3%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=55483]
> [2018-07-17 11:52:57,851][INFO ][tcp-disco-sock-reader-#150%cache.Reproducer3%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:55483, rmtPort=55483]
> [2018-07-17 11:52:57,855][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:57,855][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] Topology snapshot [ver=22, servers=5, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:57,856][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] ^-- Node [id=1F04DCA5-0424-460C-96F6-1736F0900003, clusterState=ACTIVE]
> [2018-07-17 11:52:57,856][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:57,856][INFO ][disco-event-worker-#508%cache.Reproducer3%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:57,856][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:57,856][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] Topology snapshot [ver=22, servers=5, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:57,856][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] ^-- Node [id=B3EA935B-7EAF-440C-9408-346192500004, clusterState=ACTIVE]
> [2018-07-17 11:52:57,856][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:57,857][INFO ][disco-event-worker-#563%cache.Reproducer4%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:57,857][INFO ][disco-event-worker-#256%cache.Reproducer5%][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:57,857][INFO ][disco-event-worker-#256%cache.Reproducer5%][GridDiscoveryManager] Topology snapshot [ver=22, servers=5, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:57,857][INFO ][disco-event-worker-#256%cache.Reproducer5%][GridDiscoveryManager] ^-- Node [id=29209C33-9CB5-4732-ACD4-932E5F600005, clusterState=ACTIVE]
> [2018-07-17 11:52:57,857][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:57,857][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] Topology snapshot [ver=22, servers=5, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:57,858][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] ^-- Node [id=214D8EF6-BAE8-4B6F-9947-33C451E00000, clusterState=ACTIVE]
> [2018-07-17 11:52:57,858][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:57,858][INFO ][disco-event-worker-#618%cache.Reproducer0%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:57,859][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false]
> [2018-07-17 11:52:57,859][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] Topology snapshot [ver=22, servers=5, clients=1, CPUs=1, offheap=0.1GB, heap=3.8GB]
> [2018-07-17 11:52:57,859][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] ^-- Node [id=C6CBF88B-2F79-4562-813D-B630EB800001, clusterState=ACTIVE]
> [2018-07-17 11:52:57,859][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] Data Regions Configured:
> [2018-07-17 11:52:57,859][INFO ][disco-event-worker-#672%cache.Reproducer1%][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=3.1 GiB, persistenceEnabled=false]
> [2018-07-17 11:52:57,876][WARN ][restart-thread-1][Reproducer2] Nodes started on local machine require more than 80% of physical RAM what can lead to significant slowdown due to swapping (please decrease JVM heap size, data region size or checkpoint buffer size) [required=39517MB, available=15921MB]
> [2018-07-17 11:52:57,892][INFO ][exchange-worker-#727%cache.Reproducer2%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=ecef4400-64d6-4b8e-a1d7-3acfca700002, customEvt=null, allowMerge=true]
> [2018-07-17 11:52:57,892][INFO ][exchange-worker-#727%cache.Reproducer2%][GridCacheProcessor] Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647]
> [2018-07-17 11:52:57,902][INFO ][exchange-worker-#727%cache.Reproducer2%][GridCacheProcessor] Started cache [name=cache-, id=-1368047381, memoryPolicyName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:57,902][INFO ][exchange-worker-#727%cache.Reproducer2%][GridCacheProcessor] Started cache [name=cache-40, id=-433538905, memoryPolicyName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1]
> [2018-07-17 11:52:57,903][INFO ][exchange-worker-#727%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:57,903][INFO ][grid-nio-worker-tcp-comm-0-#499%cache.Reproducer3%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45012, rmtAddr=/127.0.0.1:55774]
> [2018-07-17 11:52:57,904][INFO ][grid-nio-worker-tcp-comm-0-#717%cache.Reproducer2%][TcpCommunicationSpi] Established outgoing communication connection [locAddr=/127.0.0.1:55774, rmtAddr=/127.0.0.1:45012]
> [2018-07-17 11:52:57,904][INFO ][exchange-worker-#727%cache.Reproducer2%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], waitTime=0ms, futInfo=NA]
> [2018-07-17 11:52:57,915][INFO ][exchange-worker-#727%cache.Reproducer2%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], crd=false]
> [2018-07-17 11:52:57,916][INFO ][sys-#516%cache.Reproducer3%][GridCachePartitionExchangeManager] Waiting for coordinator initialization [node=ecef4400-64d6-4b8e-a1d7-3acfca700002, nodeOrder=22, ver=AffinityTopologyVersion [topVer=22, minorTopVer=0]]
> [2018-07-17 11:53:05,252][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], node=29209c33-9cb5-4732-acd4-932e5f600005]. Consider changing TransactionConfiguration.txTimeoutOnPartitionMapSynchronization to non default value to avoid this message. Dumping pending objects that might be the cause:
> [2018-07-17 11:53:05,252][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=20, minorTopVer=17]
> [2018-07-17 11:53:05,253][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryCustomEvent [customMsg=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], topVer=20, nodeId8=29209c33, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565244]], crd=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817549811, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], discoEvt=DiscoveryCustomEvent [customMsg=DynamicCacheChangeBatch [id=4df1177a461-b5520c92-e601-4b0f-94d0-3c3163611012, reqs=[DynamicCacheChangeRequest [cacheName=cache-40, hasCfg=true, nodeId=29209c33-9cb5-4732-acd4-932e5f600005, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], topVer=20, nodeId8=29209c33, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565244]], nodeId=29209c33, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=92121288], init=true, lastVer=null, partReleaseFut=null, exchActions=ExchangeActions [startCaches=[cache-40], stopCaches=null, startGrps=[cache-40], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1531817565244, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=CLIENT, evtLatch=0, remaining=[c6cbf88b-2f79-4562-813d-b630eb800001, 1f04dca5-0424-460c-96f6-1736f0900003, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1298239340]]
> [2018-07-17 11:53:05,253][WARN ][exchange-worker-#257%cache.Reproducer5%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=5]
> [2018-07-17 11:53:05,254][WARN ][exchange-worker-#257%cache.Reproducer5%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817543840, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,254][WARN ][exchange-worker-#257%cache.Reproducer5%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817543840, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,254][WARN ][exchange-worker-#257%cache.Reproducer5%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,258][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Last 10 exchange futures (total: 504):
> [2018-07-17 11:53:05,258][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,258][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817543840, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,258][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817543840, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,259][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=false]
> [2018-07-17 11:53:05,259][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,259][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=16], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,259][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=15], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,259][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=14], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,259][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=13], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,259][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=12], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=0, lastExchangeTime=1531817530500, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,260][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Latch manager state: ExchangeLatchManager [serverLatches={}, clientLatches={}]
> [2018-07-17 11:53:05,260][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Pending transactions:
> [2018-07-17 11:53:05,260][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Pending explicit locks:
> [2018-07-17 11:53:05,260][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Pending cache futures:
> [2018-07-17 11:53:05,260][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Pending atomic cache futures:
> [2018-07-17 11:53:05,261][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Pending data streamer futures:
> [2018-07-17 11:53:05,261][WARN ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Pending transaction deadlock detection futures:
> [2018-07-17 11:53:05,285][INFO ][exchange-worker-#257%cache.Reproducer5%][diagnostic] Exchange future waiting for coordinator response [crd=1f04dca5-0424-460c-96f6-1736f0900003, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> Remote node information:
> General node info [id=1f04dca5-0424-460c-96f6-1736f0900003, client=false, discoTopVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], time=11:53:05.261]
> Partitions exchange info [readyVer=AffinityTopologyVersion [topVer=20, minorTopVer=18]]
> Last initialized exchange future: GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=1f04dca5, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], crd=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817584520, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=1f04dca5, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=806121989], init=true, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]]]]]], exchActions=null, affChangeMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], initTs=1531817565364, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=BECOME_CRD, evtLatch=0, remaining=[c6cbf88b-2f79-4562-813d-b630eb800001, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=149759729]]
> Communication SPI statistics [rmtNode=29209c33-9cb5-4732-acd4-932e5f600005]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=29209c33-9cb5-4732-acd4-932e5f600005, idx=0, connCnt=0, dummy=false], msgsSent=59, msgsAckedByRmt=32, msgsRcvd=59, lastAcked=32, reserveCnt=1, descIdHash=1308538101]
> Communication SPI clients:
> [node=29209c33-9cb5-4732-acd4-932e5f600005, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=0, bytesRcvd=212714, bytesSent=45257, bytesRcvd0=853, bytesSent0=0, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-0, igniteInstanceName=cache.Reproducer3, finished=false, hashCode=1737485016, interrupted=false, runner=grid-nio-worker-tcp-comm-0-#499%cache.Reproducer3%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=32, resendCnt=0, rcvCnt=59, sentCnt=59, reserved=true, lastAck=32, nodeLeft=false, node=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=32, resendCnt=0, rcvCnt=59, sentCnt=59, reserved=true, lastAck=32, nodeLeft=false, node=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], super=GridNioSessionImpl [locAddr=/127.0.0.1:45012, rmtAddr=/127.0.0.1:55726, createTime=1531817552561, closeTime=0, bytesSent=11911, bytesRcvd=8798, bytesSent0=0, bytesRcvd0=853, sndSchedTime=1531817552561, lastSndTime=1531817566876, lastRcvTime=1531817585261, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@1d286c1f, directMode=true], GridConnectionBytesVerifyFilter], accepted=true, markedForClose=false]], super=GridAbstractCommunicationClient [lastUsed=1531817552561, closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=0, keysCnt=1, bytesRcvd=212714, bytesRcvd0=853, bytesSent=45257, bytesSent0=0]
> Connection info [in=true, rmtAddr=/127.0.0.1:55726, locAddr=/127.0.0.1:45012, msgsSent=59, msgsAckedByRmt=32, descIdHash=1308538101, unackedMsgs=[GridNearSingleGetResponse, GridNearTxPrepareResponse, GridNearSingleGetResponse, GridNearTxPrepareResponse, GridNearSingleGetResponse], msgsRcvd=59, lastAcked=32, descIdHash=1308538101, bytesRcvd=8798, bytesRcvd0=853, bytesSent=11911, bytesSent0=0, opQueueSize=0]
> Exchange future: GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryCustomEvent [customMsg=null, affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], topVer=20, nodeId8=1f04dca5, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565244]], crd=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], discoEvt=DiscoveryCustomEvent [customMsg=null, affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], topVer=20, nodeId8=1f04dca5, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565244]], nodeId=29209c33, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=1442604495], init=true, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], futures=[]]]]]], exchActions=null, affChangeMsg=null, initTs=1531817565254, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=true, state=DONE, evtLatch=0, remaining=[c6cbf88b-2f79-4562-813d-b630eb800001, e0c5902c-6196-4a7d-b9de-1d007bd00002, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000], super=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=AffinityTopologyVersion [topVer=20, minorTopVer=18], hash=881383720]]
> Local communication statistics:
> Communication SPI statistics [rmtNode=1f04dca5-0424-460c-96f6-1736f0900003]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=1f04dca5-0424-460c-96f6-1736f0900003, idx=0, connCnt=-1, dummy=false], msgsSent=59, msgsAckedByRmt=32, msgsRcvd=60, lastAcked=32, reserveCnt=1, descIdHash=1533696363]
> Communication SPI clients:
> [node=1f04dca5-0424-460c-96f6-1736f0900003, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=0, bytesRcvd=1226531, bytesSent=27404, bytesRcvd0=9120, bytesSent0=853, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-0, igniteInstanceName=cache.Reproducer5, finished=false, hashCode=1302610201, interrupted=false, runner=grid-nio-worker-tcp-comm-0-#244%cache.Reproducer5%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=32, resendCnt=0, rcvCnt=60, sentCnt=59, reserved=true, lastAck=32, nodeLeft=false, node=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817549811, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], connected=false, connectCnt=1, queueLimit=4096, reserveCnt=1, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=32, resendCnt=0, rcvCnt=60, sentCnt=59, reserved=true, lastAck=32, nodeLeft=false, node=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817549811, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], connected=false, connectCnt=1, queueLimit=4096, reserveCnt=1, pairedConnections=false], super=GridNioSessionImpl [locAddr=/127.0.0.1:55726, rmtAddr=/127.0.0.1:45012, createTime=1531817552561, closeTime=0, bytesSent=8756, bytesRcvd=21003, bytesSent0=853, bytesRcvd0=9120, sndSchedTime=1531817552561, lastSndTime=1531817585261, lastRcvTime=1531817585272, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@edf0ac6, directMode=true], GridConnectionBytesVerifyFilter], accepted=false, markedForClose=false]], super=GridAbstractCommunicationClient [lastUsed=1531817552561, closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=0, keysCnt=1, bytesRcvd=1226531, bytesRcvd0=9120, bytesSent=27404, bytesSent0=853]
> Connection info [in=false, rmtAddr=/127.0.0.1:45012, locAddr=/127.0.0.1:55726, msgsSent=59, msgsAckedByRmt=32, descIdHash=1533696363, unackedMsgs=[GridNearSingleGetRequest, GridNearTxPrepareRequest, GridNearSingleGetRequest, GridNearTxPrepareRequest, GridNearSingleGetRequest], msgsRcvd=60, lastAcked=32, descIdHash=1533696363, bytesRcvd=21003, bytesRcvd0=9120, bytesSent=8756, bytesSent0=853, opQueueSize=0]
> [2018-07-17 11:53:05,442][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], node=c6cbf88b-2f79-4562-813d-b630eb800001]. Consider changing TransactionConfiguration.txTimeoutOnPartitionMapSynchronization to non default value to avoid this message. Dumping pending objects that might be the cause:
> [2018-07-17 11:53:05,443][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=20, minorTopVer=18]
> [2018-07-17 11:53:05,443][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=c6cbf88b, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], crd=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=c6cbf88b, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=1968380689], init=true, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]]]]]], exchActions=null, affChangeMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], initTs=1531817565364, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[1f04dca5-0424-460c-96f6-1736f0900003, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=993699778]]
> [2018-07-17 11:53:05,444][WARN ][exchange-worker-#673%cache.Reproducer1%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=4]
> [2018-07-17 11:53:05,444][WARN ][exchange-worker-#673%cache.Reproducer1%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,444][WARN ][exchange-worker-#673%cache.Reproducer1%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,444][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Last 10 exchange futures (total: 22):
> [2018-07-17 11:53:05,444][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,444][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,445][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,445][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,445][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,445][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=16], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,445][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=15], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,445][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=14], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,445][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=13], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=12], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817564353, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Latch manager state: ExchangeLatchManager [serverLatches={}, clientLatches={}]
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Pending transactions:
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Pending explicit locks:
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Pending cache futures:
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Pending atomic cache futures:
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Pending data streamer futures:
> [2018-07-17 11:53:05,451][WARN ][exchange-worker-#673%cache.Reproducer1%][diagnostic] Pending transaction deadlock detection futures:
> [2018-07-17 11:53:05,450][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], node=214d8ef6-bae8-4b6f-9947-33c451e00000]. Consider changing TransactionConfiguration.txTimeoutOnPartitionMapSynchronization to non default value to avoid this message. Dumping pending objects that might be the cause:
> [2018-07-17 11:53:05,452][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=20, minorTopVer=18]
> [2018-07-17 11:53:05,453][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=214d8ef6, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], crd=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=214d8ef6, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=1814282089], init=true, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]]]]]], exchActions=null, affChangeMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], initTs=1531817565364, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[c6cbf88b-2f79-4562-813d-b630eb800001, 1f04dca5-0424-460c-96f6-1736f0900003, b3ea935b-7eaf-440c-9408-346192500004], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=442764114]]
> [2018-07-17 11:53:05,453][WARN ][exchange-worker-#619%cache.Reproducer0%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=4]
> [2018-07-17 11:53:05,453][WARN ][exchange-worker-#619%cache.Reproducer0%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,453][WARN ][exchange-worker-#619%cache.Reproducer0%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,454][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Last 10 exchange futures (total: 191):
> [2018-07-17 11:53:05,454][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,454][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,454][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,454][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,454][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=16], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=15], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=14], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=13], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=12], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817556801, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Latch manager state: ExchangeLatchManager [serverLatches={}, clientLatches={}]
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Pending transactions:
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Pending explicit locks:
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Pending cache futures:
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Pending atomic cache futures:
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Pending data streamer futures:
> [2018-07-17 11:53:05,455][WARN ][exchange-worker-#619%cache.Reproducer0%][diagnostic] Pending transaction deadlock detection futures:
> [2018-07-17 11:53:05,450][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], node=1f04dca5-0424-460c-96f6-1736f0900003]. Consider changing TransactionConfiguration.txTimeoutOnPartitionMapSynchronization to non default value to avoid this message. Dumping pending objects that might be the cause:
> [2018-07-17 11:53:05,459][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=20, minorTopVer=18]
> [2018-07-17 11:53:05,460][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=1f04dca5, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], crd=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817584520, loc=true, ver=2.7.0#19700101-sha1:00000000, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=1f04dca5, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=806121989], init=true, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]]]]]], exchActions=null, affChangeMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], initTs=1531817565364, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=BECOME_CRD, evtLatch=0, remaining=[c6cbf88b-2f79-4562-813d-b630eb800001, b3ea935b-7eaf-440c-9408-346192500004, 214d8ef6-bae8-4b6f-9947-33c451e00000], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=149759729]]
> [2018-07-17 11:53:05,460][WARN ][exchange-worker-#509%cache.Reproducer3%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=4]
> [2018-07-17 11:53:05,460][WARN ][exchange-worker-#509%cache.Reproducer3%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,460][WARN ][exchange-worker-#509%cache.Reproducer3%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,460][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Last 10 exchange futures (total: 273):
> [2018-07-17 11:53:05,461][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,461][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,461][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817549907, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,461][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,461][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=16], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=15], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=14], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=13], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=12], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817549856, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Latch manager state: ExchangeLatchManager [serverLatches={}, clientLatches={}]
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Pending transactions:
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Pending explicit locks:
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Pending cache futures:
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Pending atomic cache futures:
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Pending data streamer futures:
> [2018-07-17 11:53:05,462][WARN ][exchange-worker-#509%cache.Reproducer3%][diagnostic] Pending transaction deadlock detection futures:
> [2018-07-17 11:53:05,450][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], node=b3ea935b-7eaf-440c-9408-346192500004]. Consider changing TransactionConfiguration.txTimeoutOnPartitionMapSynchronization to non default value to avoid this message. Dumping pending objects that might be the cause:
> [2018-07-17 11:53:05,466][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=20, minorTopVer=18]
> [2018-07-17 11:53:05,467][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=b3ea935b, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], crd=TcpDiscoveryNode [id=1f04dca5-0424-460c-96f6-1736f0900003, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47502], discPort=47502, order=14, intOrder=10, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], discoEvt=DiscoveryCustomEvent [customMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], affTopVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], topVer=20, nodeId8=b3ea935b, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1531817565354]], nodeId=e0c5902c, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=763810714], init=true, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], futures=[]]]]]], exchActions=null, affChangeMsg=CacheAffinityChangeMessage [id=d502177a461-b5520c92-e601-4b0f-94d0-3c3163611012, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], initTs=1531817565364, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[c6cbf88b-2f79-4562-813d-b630eb800001, 1f04dca5-0424-460c-96f6-1736f0900003, 214d8ef6-bae8-4b6f-9947-33c451e00000], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1055335804]]
> [2018-07-17 11:53:05,467][WARN ][exchange-worker-#564%cache.Reproducer4%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=4]
> [2018-07-17 11:53:05,468][WARN ][exchange-worker-#564%cache.Reproducer4%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,468][WARN ][exchange-worker-#564%cache.Reproducer4%][GridCachePartitionExchangeManager] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,468][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Last 10 exchange futures (total: 230):
> [2018-07-17 11:53:05,468][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=22, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=ecef4400-64d6-4b8e-a1d7-3acfca700002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=22, intOrder=14, lastExchangeTime=1531817577796, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,468][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=21, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,468][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=e0c5902c-6196-4a7d-b9de-1d007bd00002, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:47501], discPort=47501, order=12, intOrder=9, lastExchangeTime=1531817553269, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=false], done=false]
> [2018-07-17 11:53:05,469][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=18], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,469][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=17], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,469][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=16], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,469][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=15], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,469][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=14], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,469][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=13], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,469][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=20, minorTopVer=12], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=29209c33-9cb5-4732-acd4-932e5f600005, addrs=[127.0.0.1], sockAddrs=[/127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1531817553249, loc=false, ver=2.7.0#19700101-sha1:00000000, isClient=true], done=true]
> [2018-07-17 11:53:05,470][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Latch manager state: ExchangeLatchManager [serverLatches={}, clientLatches={}]
> [2018-07-17 11:53:05,470][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Pending transactions:
> [2018-07-17 11:53:05,470][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Pending explicit locks:
> [2018-07-17 11:53:05,470][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Pending cache futures:
> [2018-07-17 11:53:05,470][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Pending atomic cache futures:
> [2018-07-17 11:53:05,470][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Pending data streamer futures:
> [2018-07-17 11:53:05,470][WARN ][exchange-worker-#564%cache.Reproducer4%][diagnostic] Pending transaction deadlock detection futures:
> [2018-07-17 11:53:05,472][INFO ][grid-nio-worker-tcp-comm-2-#610%cache.Reproducer0%][diagnostic] Exchange future waiting for coordinator response [crd=1f04dca5-0424-460c-96f6-1736f0900003, topVer=AffinityTopologyVersion [topVer=20, minorTopVer=19]]
> {noformat}
> New coordinator (3) awaits restore state response from client node (5) on exchange ver 20.19, but the client cannot initialize exchange 20.19 because it is stuck at 20.18.
> *UPDATE 2018.09.07*
> After fixing [IGNITE-9227|https://issues.apache.org/jira/browse/IGNITE-9227] hanging is not reproduced, but the failover test (IgniteAtomicLongChangingTopologySelfTest.testClientSetCreateCloseFailover), which was disabled for this ticket, now fails sometimes with another reason:
> {noformat}
> Caused by: class org.apache.ignite.internal.processors.cache.CacheStoppedException: Failed to perform cache operation (cache is stopped): Failed to wait for topology update, cache group is stopping.
> at org.apache.ignite.internal.processors.cache.GridCacheProcessor.processCacheStopRequestOnExchangeDone(GridCacheProcessor.java:2303)
> at org.apache.ignite.internal.processors.cache.GridCacheProcessor.onExchangeDone(GridCacheProcessor.java:2380)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.onDone(GridDhtPartitionsExchangeFuture.java:1829)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.finishExchangeOnCoordinator(GridDhtPartitionsExchangeFuture.java:2997)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.onAllReceived(GridDhtPartitionsExchangeFuture.java:2779)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.processSingleMessage(GridDhtPartitionsExchangeFuture.java:2410)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.access$100(GridDhtPartitionsExchangeFuture.java:134)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture$2.apply(GridDhtPartitionsExchangeFuture.java:2242)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture$2.apply(GridDhtPartitionsExchangeFuture.java:2230)
> at org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:383)
> at org.apache.ignite.internal.util.future.GridFutureAdapter.listen(GridFutureAdapter.java:353)
> at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.onReceiveSingleMessage(GridDhtPartitionsExchangeFuture.java:2230)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager.processSinglePartitionUpdate(GridCachePartitionExchangeManager.java:1600)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager.access$1000(GridCachePartitionExchangeManager.java:140)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$2.onMessage(GridCachePartitionExchangeManager.java:351)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$2.onMessage(GridCachePartitionExchangeManager.java:331)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$MessageHandler.apply(GridCachePartitionExchangeManager.java:2971)
> at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$MessageHandler.apply(GridCachePartitionExchangeManager.java:2950)
> at org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:1056)
> at org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:581)
> at org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:380)
> at org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:306)
> at org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$100(GridCacheIoManager.java:101)
> at org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:295)
> at org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1569)
> at org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1197)
> at org.apache.ignite.internal.managers.communication.GridIoManager.access$4200(GridIoManager.java:127)
> at org.apache.ignite.internal.managers.communication.GridIoManager$9.run(GridIoManager.java:1093)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> ... 1 more
> {noformat}
> Reproducer attached.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)