ignite-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Amelchev Nikita (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (IGNITE-9837) Test BinaryMetadataUpdatesFlowTest.testConcurrentMetadataUpdates is flaky in master.
Date Fri, 12 Oct 2018 08:35:00 GMT

     [ https://issues.apache.org/jira/browse/IGNITE-9837?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Amelchev Nikita updated IGNITE-9837:
------------------------------------
    Description: 
The test _BinaryMetadataUpdatesFlowTest.testConcurrentMetadataUpdates_ is flaky in master. Sometimes it fails by timeout (5min). [Example of fail.|https://ci.ignite.apache.org/viewLog.html?buildId=2042133&tab=buildResultsDiv&buildTypeId=IgniteTests24Java8_BinaryObjects#testNameId4314129944736732856] 

UPDATE:

When the test is starting node from the previous test wasn't stopped. Previous tests have threads to start and stop nodes. After tests, it only interrupts this threads but doesn't wait for threads cancellation and stopping all nodes.

Here is the full log:
(Node with name BinaryMetadataUpdatesFlowTest2 is from the previous test and doesn't correctly stopped)
{noformat}
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,523][INFO ][main][root] >>> Starting test: BinaryMetadataUpdatesFlowTest#testConcurrentMetadataUpdates <<<
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,538][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 
[04:08:45] :	[Step 4/5] 
[04:08:45] :	[Step 4/5] >>> __________ ________________ 
[04:08:45] :	[Step 4/5] >>> / _/ ___/ |/ / _/_ __/ __/ 
[04:08:45] :	[Step 4/5] >>> _/ // (7 7 // / / / / _/ 
[04:08:45] :	[Step 4/5] >>> /___/\___/_/|_/___/ /_/ /___/ 
[04:08:45] :	[Step 4/5] >>> 
[04:08:45] :	[Step 4/5] >>> ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b
[04:08:45] :	[Step 4/5] >>> 2018 Copyright(C) Apache Software Foundation
[04:08:45] :	[Step 4/5] >>> 
[04:08:45] :	[Step 4/5] >>> Ignite documentation: http://ignite.apache.org
[04:08:45] :	[Step 4/5] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,539][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Config URL: n/a
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,540][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] IgniteConfiguration [igniteInstanceName=binary.BinaryMetadataUpdatesFlowTest0, pubPoolSize=24, svcPoolSize=24, callbackPoolSize=24, stripedPoolSize=24, sysPoolSize=24, mgmtPoolSize=4, igfsPoolSize=24, dataStreamerPoolSize=24, utilityCachePoolSize=24, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=24, igniteHome=/data/teamcity/work/9198da4c51c3e112, igniteWorkDir=/data/teamcity/work/9198da4c51c3e112/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@1640190a, nodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000, marsh=BinaryMarshaller [], marshLocJobs=false, daemon=false, p2pEnabled=false, 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=org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$FirstConnectionPolicy@46b8261, enableForcibleNodeKill=false, enableTroubleshootingLog=false, locAddr=null, locHost=null, locPort=45310, 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, boundTcpPort=-1, boundTcpShmemPort=-1, selectorsCnt=12, selectorSpins=0, addrRslvr=null, ctxInitLatch=java.util.concurrent.CountDownLatch@33179221[Count = 1], stopping=false], evtSpi=MemoryEventStorageSpi [expireAgeMs=9223372036854775807, expireCnt=10000, filter=null], colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@76582a, addrRslvr=null, encryptionSpi=org.apache.ignite.spi.encryption.noop.NoopEncryptionSpi@e66ca60, clientMode=false, rebalanceThreadPoolSize=1, txCfg=TransactionConfiguration [txSerEnabled=false, dfltIsolation=REPEATABLE_READ, dfltConcurrency=PESSIMISTIC, dfltTxTimeout=0, txTimeoutOnPartitionMapExchange=0, pessimisticTxLogSize=0, pessimisticTxLogLinger=10000, tmLookupClsName=null, txManagerFactory=null, useJtaSync=false], 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=BinaryConfiguration [idMapper=null, nameMapper=BinaryBaseNameMapper [isSimpleName=true], serializer=null, compactFooter=true], memCfg=null, pstCfg=null, dsCfg=DataStorageConfiguration [sysRegionInitSize=41943040, sysRegionMaxSize=104857600, pageSize=0, concLvl=0, dfltDataRegConf=DataRegionConfiguration [name=default, maxSize=20274432409, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=false, checkpointPageBufSize=0], dataRegions=null, storagePath=null, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, maxWalArchiveSize=1073741824, 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@d82f038, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false, walCompactionLevel=1], 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=24, idleTimeout=0, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=false, useIgniteSslCtxFactory=true, sslClientAuth=false, sslCtxFactory=null], mvccVacuumThreadCnt=2, mvccVacuumFreq=5000, authEnabled=false, failureHnd=AbstractFailureHandler [ignoredFailureTypes=EmptySet []]NoOpFailureHandler [super=], commFailureRslvr=null]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,549][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Daemon mode: off
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,549][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] OS: Linux 4.4.0-134-generic amd64
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] OS user: teamcity
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] PID: 3032
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Language runtime: Java Platform API Specification ver. 1.8
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM information: Java(TM) SE Runtime Environment 1.8.0_181-b13 Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 25.181-b13
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM total memory: 1.8GB
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Remote Management [restart: off, REST: off, JMX (remote: off)]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Logger: GridTestLog4jLogger [quiet=false, config=null]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,552][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] IGNITE_HOME=/data/teamcity/work/9198da4c51c3e112
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,552][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM arguments: [-DIGNITE_DUMP_THREADS_ON_FAILURE=false, -DMono=/usr/bin/mono-sgen, -DMono4.0_x64=/usr/lib/mono/4.0, -DMono4.5_x64=/usr/lib/mono/4.5, -DMonoVersion=5.4.1.6, -Dagent.home.dir=/home/teamcity/agent, -Dagent.name=publicagent07_9096, -Dagent.ownPort=9096, -Dagent.work.dir=/data/teamcity/work, -Dbuild.number=3986, -Dbuild.vcs.number=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dbuild.vcs.number.1=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dbuild.vcs.number.GitHubApacheIgnite=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dclassworlds.conf=/data/teamcity/temp/buildTmp/teamcity.m2.conf, -Dcom.jetbrains.maven.watcher.report.file=/data/teamcity/temp/buildTmp/maven-build-info.xml, -Djava.io.tmpdir=/data/teamcity/temp/buildTmp, -Dmaven.home=/home/teamcity/agent/tools/maven.3.5.3, -Dmaven.multiModuleProjectDirectory=/data/teamcity/work/9198da4c51c3e112, -Dmaven.repo.local=/home/teamcity/.m2/repository, -Dteamcity.agent.cpuBenchmark=459, -Dteamcity.agent.dotnet.agent_url=http://localhost:9096/RPC2, -Dteamcity.agent.dotnet.build_id=2046426, -Dteamcity.auth.password=*******, -Dteamcity.auth.userId=TeamCityBuildId=2046426, -Dteamcity.build.changedFiles.file=/data/teamcity/temp/buildTmp/changedFiles6946597736255042765.txt, -Dteamcity.build.checkoutDir=/data/teamcity/work/9198da4c51c3e112, -Dteamcity.build.id=2046426, -Dteamcity.build.properties.file=/data/teamcity/temp/buildTmp/teamcity.build4716211550817389630.properties, -Dteamcity.build.tempDir=/data/teamcity/temp/buildTmp, -Dteamcity.build.workingDir=/data/teamcity/work/9198da4c51c3e112, -Dteamcity.buildConfName=Binary Objects, -Dteamcity.buildType.id=IgniteTests24Java8_BinaryObjects, -Dteamcity.configuration.properties.file=/data/teamcity/temp/buildTmp/teamcity.config817725141007444616.properties, -Dteamcity.maven.watcher.home=/home/teamcity/agent/plugins/mavenPlugin/maven-watcher-jdk16, -Dteamcity.projectName=Ignite Tests 2.4+ (Java 8/9/10/11), -Dteamcity.runner.properties.file=/data/teamcity/temp/buildTmp/teamcity.runner8345643043879360132.properties, -Dteamcity.tests.recentlyFailedTests.file=/data/teamcity/temp/buildTmp/testsToRunFirst6462377036881887019.txt, -Dteamcity.version=2017.2.3 (build 51047), -ea, -Xms2g, -Xmx2g, -XX:+HeapDumpOnOutOfMemoryError, -XX:+AggressiveOpts, -DIGNITE_TEST_HOME="/data/teamcity/work/9198da4c51c3e112", -DIGNITE_UPDATE_NOTIFIER=false, -DIGNITE_NO_DISCO_ORDER=true, -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true, -DIGNITE_QUIET=false, -Djava.net.preferIPv4Stack=true]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,557][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemRegionInitialSize property to change the setting.
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,557][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache'], in 'default' dataRegion: ['default']]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,559][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 3-rd party licenses can be found at: /data/teamcity/work/9198da4c51c3e112/libs/licenses
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,563][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] Configured plugins:
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,563][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- TestReconnectPlugin 1.0
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- StanByClusterTestProvider 1.0
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- null
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- PageMemory tracker plugin 1.0
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,566][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][FailureProcessor] Configured failure handler: [hnd=NoOpFailureHandler [super=AbstractFailureHandler [ignoredFailureTypes=EmptySet []]]]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,568][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=45310, locHost=/127.0.0.1, selectorsCnt=12, selectorSpins=0, pairedConn=false]
[04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,568][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][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.
[04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,572][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival).
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,572][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Security status [authentication=off, tls/ssl=off]
[04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,575][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgniteCacheDatabaseSharedManager] DataRegionConfiguration.maxWalArchiveSize instead DataRegionConfiguration.walHistorySize would be used for removing old archive wal files
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,575][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][PartitionsEvictManager] Evict partition permits=6
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,578][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][ClientListenerProcessor] Client connector processor has started on TCP port 10800
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,579][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Non-loopback local IPs: 172.17.0.7
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,579][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Enabled local MACs: 0242AC110007
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,580][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TestTcpDiscoverySpi] Connection check threshold is calculated: 10000
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,581][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TestTcpDiscoverySpi] Successfully bound to TCP port [port=47500, localHost=/127.0.0.1, locNodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,583][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49708]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,583][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49708]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,584][INFO ][tcp-disco-sock-reader-#1412%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49708, rmtPort=49708]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,586][INFO ][tcp-disco-sock-reader-#1412%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49708, rmtPort=49708
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,589][INFO ][tcp-disco-msg-worker-#1400%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=0, intOrder=50, lastExchangeTime=1539133725576, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,590][INFO ][tcp-disco-srvr-#1411%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=32807]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,590][INFO ][tcp-disco-srvr-#1411%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=32807]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,591][INFO ][tcp-disco-sock-reader-#1413%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:32807, rmtPort=32807]
[04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,549][WARN ][jvm-pause-detector-worker][BinaryMetadataUpdatesFlowTest0] Possible too long JVM pause: 911 milliseconds.
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,550][INFO ][tcp-disco-sock-reader-#1407%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:58389, rmtPort=58389
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,550][INFO ][tcp-disco-sock-reader-#1403%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:45328, rmtPort=45328
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,636][INFO ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,637][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=45980]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,637][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=45980]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,638][INFO ][tcp-disco-sock-reader-#1414%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:45980, rmtPort=45980]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,640][INFO ][disco-notifier-worker-#19455%binary.BinaryMetadataUpdatesFlowTest0%][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, crdVer=1539133558282, topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]], crdNode=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,642][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], mvccCrd=MvccCoordinator [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, crdVer=1539133558282, topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]], mvccCrdChange=true, crd=false, evt=NODE_JOINED, evtNode=8fb16dc0-3515-4a02-8069-6c11c7b00000, customEvt=null, allowMerge=true]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,643][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][msg] Components activation performed in 0 ms.
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,645][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647, mvcc=false], encryptionEnabled=false]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,648][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Started cache [name=default, id=1544803905, memoryPolicyName=default, mode=REPLICATED, atomicity=ATOMIC, backups=2147483647, mvcc=false], encryptionEnabled=false]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,649][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Starting caches on local join performed in 5 ms.
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,649][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Skipped waiting for partitions release future (local node is joining) [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,651][INFO ][grid-nio-worker-tcp-comm-0-#19352%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45624]
[04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,651][WARN ][grid-nio-worker-tcp-comm-0-#19352%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,853][INFO ][grid-nio-worker-tcp-comm-1-#19353%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45626]
[04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,854][WARN ][grid-nio-worker-tcp-comm-1-#19353%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,055][INFO ][grid-nio-worker-tcp-comm-2-#19354%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45628]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,055][WARN ][grid-nio-worker-tcp-comm-2-#19354%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,257][INFO ][grid-nio-worker-tcp-comm-3-#19355%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45634]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,257][WARN ][grid-nio-worker-tcp-comm-3-#19355%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,458][INFO ][grid-nio-worker-tcp-comm-4-#19356%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45642]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,459][WARN ][grid-nio-worker-tcp-comm-4-#19356%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,461][ERROR][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=GridCacheMessage [msgId=207323, depInfo=null, err=null, skipPrepare=false]GridDhtPartitionsAbstractMessage [exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133727156, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], topVer=98, nodeId8=8fb16dc0, msg=null, type=NODE_JOINED, tstamp=1539133726640], nodeId=8fb16dc0, evt=NODE_JOINED], lastVer=GridCacheVersion [topVer=0, order=1539133725566, nodeOrder=0], super=]GridDhtPartitionsSingleMessage [parts=HashMap {1544803905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=1, size=0], -2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=1, size=0]}, partCntrs=HashMap {1544803905=CachePartitionPartialCountersMap {}, -2100569601=CachePartitionPartialCountersMap {}}, partsSizes=null, partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null, activeQryTrackers=GridLongList [idx=0, arr=[]], super=]]]
[04:08:47]W:	[org.apache.ignite:ignite-core] class org.apache.ignite.IgniteCheckedException: Failed to connect to node (is node still alive?). Make sure that each ComputeTask and cache Transaction has a timeout set in order to prevent parties from waiting forever in case of network issues [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=[/127.0.0.1:45312]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3459)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2987)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2870)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2713)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2672)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1656)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:1731)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1170)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendLocalPartitions(GridDhtPartitionsExchangeFuture.java:1662)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1793)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1316)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:781)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2666)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2538)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
[04:08:47]W:	[org.apache.ignite:ignite-core] at java.lang.Thread.run(Thread.java:748)
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,478][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Pinging node: 0a7ffe6b-4f53-4e4b-a316-600ab6900002
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,479][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36227]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,480][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36227]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,481][INFO ][tcp-disco-sock-reader-#1416%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36227, rmtPort=36227]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,483][INFO ][tcp-disco-sock-reader-#1416%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36227, rmtPort=36227
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,684][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=40821]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,685][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=40821]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,686][INFO ][tcp-disco-sock-reader-#1417%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:40821, rmtPort=40821]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,687][INFO ][tcp-disco-sock-reader-#1417%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:40821, rmtPort=40821
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,888][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=59890]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,888][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=59890]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,889][INFO ][tcp-disco-sock-reader-#1418%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:59890, rmtPort=59890]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,890][INFO ][tcp-disco-sock-reader-#1418%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:59890, rmtPort=59890
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,091][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=55784]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,092][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=55784]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,093][INFO ][tcp-disco-sock-reader-#1419%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:55784, rmtPort=55784]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,094][INFO ][tcp-disco-sock-reader-#1419%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:55784, rmtPort=55784
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,295][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=60102]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,295][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=60102]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,296][INFO ][tcp-disco-sock-reader-#1420%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:60102, rmtPort=60102]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,297][INFO ][tcp-disco-sock-reader-#1420%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:60102, rmtPort=60102
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,498][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49142]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,498][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49142]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,499][INFO ][tcp-disco-sock-reader-#1421%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49142, rmtPort=49142]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,500][INFO ][tcp-disco-sock-reader-#1421%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49142, rmtPort=49142
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,700][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36918]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,701][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36918]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,701][INFO ][tcp-disco-sock-reader-#1422%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36918, rmtPort=36918]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,702][INFO ][tcp-disco-sock-reader-#1422%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36918, rmtPort=36918
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,903][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=43219]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,904][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=43219]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,904][INFO ][tcp-disco-sock-reader-#1423%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:43219, rmtPort=43219]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,905][INFO ][tcp-disco-sock-reader-#1423%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:43219, rmtPort=43219
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,110][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=41921]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,110][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=41921]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,112][INFO ][tcp-disco-sock-reader-#1424%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:41921, rmtPort=41921]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,113][INFO ][tcp-disco-sock-reader-#1424%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:41921, rmtPort=41921
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,314][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36591]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,314][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36591]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,315][INFO ][tcp-disco-sock-reader-#1425%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36591, rmtPort=36591]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,316][INFO ][tcp-disco-sock-reader-#1425%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36591, rmtPort=36591
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,517][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=44022]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,517][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=44022]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,518][INFO ][tcp-disco-sock-reader-#1426%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:44022, rmtPort=44022]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,518][INFO ][tcp-disco-sock-reader-#1426%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:44022, rmtPort=44022
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,719][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=52890]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,719][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=52890]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,720][INFO ][tcp-disco-sock-reader-#1427%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:52890, rmtPort=52890]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,720][INFO ][tcp-disco-sock-reader-#1427%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:52890, rmtPort=52890
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,921][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49179]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,921][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49179]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,922][INFO ][tcp-disco-sock-reader-#1428%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49179, rmtPort=49179]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,922][INFO ][tcp-disco-sock-reader-#1428%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49179, rmtPort=49179
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,118][INFO ][node-resurrection-thread][TestTcpDiscoverySpi] No verification for local node leave has been received from coordinator (will stop node anyway).
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,121][INFO ][tcp-disco-sock-reader-#1405%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:50382, rmtPort=50382
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,121][INFO ][tcp-disco-sock-reader-#1414%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:45980, rmtPort=45980
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,122][INFO ][node-resurrection-thread][MvccProcessorImpl] Attempting to stop inactive vacuum.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,123][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Finished node ping [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, res=false, time=2654ms]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,124][INFO ][node-resurrection-thread][BinaryMetadataUpdatesFlowTest2] 
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,124][WARN ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Failed to ping node (status check will be initiated): 0a7ffe6b-4f53-4e4b-a316-600ab6900002
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] >>> +------------------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> Ignite ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b82387a971e282fe52a5ef86edc92e09d stopped OK
[04:08:50] :	[Step 4/5] >>> +------------------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> Ignite instance name: binary.BinaryMetadataUpdatesFlowTest2
[04:08:50] :	[Step 4/5] >>> Grid uptime: 00:00:05.075
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,124][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Sending Single Message performed in 3474 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,125][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], crd=false]
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,130][WARN ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Failed to send message to next node [msg=TcpDiscoveryStatusCheckMessage [creatorNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], failedNodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, status=0, super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=ffb929b5661-8fb16dc0-3515-4a02-8069-6c11c7b00000, verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], errMsg=Failed to send message to next node [msg=TcpDiscoveryStatusCheckMessage [creatorNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], failedNodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, status=0, super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=ffb929b5661-8fb16dc0-3515-4a02-8069-6c11c7b00000, verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=ClusterNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, order=93, addr=[127.0.0.1], daemon=false]]]
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,133][WARN ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Local node has detected failed nodes and started cluster-wide procedure. To speed up failure detection please see 'Failure Detection' section under javadoc for 'TcpDiscoverySpi'
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,134][INFO ][disco-notifier-worker-#19455%binary.BinaryMetadataUpdatesFlowTest0%][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [nodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000, crdVer=1539133558287, topVer=AffinityTopologyVersion [topVer=99, minorTopVer=0]], crdNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,135][WARN ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Node FAILED: TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,136][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Topology snapshot [ver=99, locNode=8fb16dc0, servers=1, clients=0, state=ACTIVE, CPUs=24, offheap=19.0GB, heap=2.0GB]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,136][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Coordinator changed [prev=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], cur=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,139][INFO ][sys-#19459%binary.BinaryMetadataUpdatesFlowTest0%][ExchangeLatchManager] Become new coordinator 8fb16dc0-3515-4a02-8069-6c11c7b00000
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,139][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Coordinator failed, node is new coordinator [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0], prev=0a7ffe6b-4f53-4e4b-a316-600ab6900002]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,140][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Init new coordinator, node left [node=0a7ffe6b-4f53-4e4b-a316-600ab6900002]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,149][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Init new coordinator future will skip remote node: TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,149][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Try restore exchange result [awaited=[], joined=[], nodes=[], discoAllNodes=[0a7ffe6b-4f53-4e4b-a316-600ab6900002, 8fb16dc0-3515-4a02-8069-6c11c7b00000]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,150][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] New coordinator restore state finished [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,150][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Coordinator received all messages, try merge [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,151][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridCachePartitionExchangeManager] Merge exchange future [curFut=AffinityTopologyVersion [topVer=98, minorTopVer=0], mergedFut=AffinityTopologyVersion [topVer=99, minorTopVer=0], evt=NODE_FAILED, evtNode=0a7ffe6b-4f53-4e4b-a316-600ab6900002, evtNodeClient=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,151][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Exchanges merging performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,152][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=99, minorTopVer=0]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,152][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][CacheAffinitySharedManager] Affinity recalculation (on server left) performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,153][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Affinity changes (coordinator) applied in 1 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Partitions validation performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Partitions assignment performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Detecting lost partitions performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Preparing Full Message performed in 2 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Sending Full Message to all nodes performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=99, minorTopVer=0], err=null]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,158][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Detecting lost partitions performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,158][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=8fb16dc0-3515-4a02-8069-6c11c7b00000, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=99, minorTopVer=0], durationFromInit=3515]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,159][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=99, minorTopVer=0], force=false, evt=NODE_JOINED, node=8fb16dc0-3515-4a02-8069-6c11c7b00000]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,162][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat}
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,162][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Data Regions Configured:
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,163][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] ^-- default [initSize=256.0 MiB, maxSize=18.9 GiB, persistence=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,163][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] >>> +-------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> Ignite ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b82387a971e282fe52a5ef86edc92e09d
[04:08:50] :	[Step 4/5] >>> +-------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> OS name: Linux 4.4.0-134-generic amd64
[04:08:50] :	[Step 4/5] >>> CPU(s): 24
[04:08:50] :	[Step 4/5] >>> Heap: 2.0GB
[04:08:50] :	[Step 4/5] >>> VM name: 3032@6bca1cd484ee
[04:08:50] :	[Step 4/5] >>> Ignite instance name: binary.BinaryMetadataUpdatesFlowTest0
[04:08:50] :	[Step 4/5] >>> Local node [ID=8FB16DC0-3515-4A02-8069-6C11C7B00000, order=98, clientMode=false]
[04:08:50] :	[Step 4/5] >>> Local node addresses: [127.0.0.1]
[04:08:50] :	[Step 4/5] >>> Local ports: TCP:10800 TCP:45310 TCP:47500{noformat}

  was:
The test _BinaryMetadataUpdatesFlowTest.testConcurrentMetadataUpdates_ is flaky in master. Sometimes it fails by timeout (5min). [Example of fail.|https://ci.ignite.apache.org/viewLog.html?buildId=2042133&tab=buildResultsDiv&buildTypeId=IgniteTests24Java8_BinaryObjects#testNameId4314129944736732856] 

UPDATE:

When test started node from the previous test wasn't stopped. Previous tests have threads to start and stop nodes. After tests, it only interrupts this threads but doesn't wait for threads cancellation and stopping all nodes.

Here is the full log:
(Node with name BinaryMetadataUpdatesFlowTest2 is from the previous test and doesn't correctly stopped)
{noformat}
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,523][INFO ][main][root] >>> Starting test: BinaryMetadataUpdatesFlowTest#testConcurrentMetadataUpdates <<<
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,538][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 
[04:08:45] :	[Step 4/5] 
[04:08:45] :	[Step 4/5] >>> __________ ________________ 
[04:08:45] :	[Step 4/5] >>> / _/ ___/ |/ / _/_ __/ __/ 
[04:08:45] :	[Step 4/5] >>> _/ // (7 7 // / / / / _/ 
[04:08:45] :	[Step 4/5] >>> /___/\___/_/|_/___/ /_/ /___/ 
[04:08:45] :	[Step 4/5] >>> 
[04:08:45] :	[Step 4/5] >>> ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b
[04:08:45] :	[Step 4/5] >>> 2018 Copyright(C) Apache Software Foundation
[04:08:45] :	[Step 4/5] >>> 
[04:08:45] :	[Step 4/5] >>> Ignite documentation: http://ignite.apache.org
[04:08:45] :	[Step 4/5] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,539][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Config URL: n/a
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,540][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] IgniteConfiguration [igniteInstanceName=binary.BinaryMetadataUpdatesFlowTest0, pubPoolSize=24, svcPoolSize=24, callbackPoolSize=24, stripedPoolSize=24, sysPoolSize=24, mgmtPoolSize=4, igfsPoolSize=24, dataStreamerPoolSize=24, utilityCachePoolSize=24, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=24, igniteHome=/data/teamcity/work/9198da4c51c3e112, igniteWorkDir=/data/teamcity/work/9198da4c51c3e112/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@1640190a, nodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000, marsh=BinaryMarshaller [], marshLocJobs=false, daemon=false, p2pEnabled=false, 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=org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$FirstConnectionPolicy@46b8261, enableForcibleNodeKill=false, enableTroubleshootingLog=false, locAddr=null, locHost=null, locPort=45310, 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, boundTcpPort=-1, boundTcpShmemPort=-1, selectorsCnt=12, selectorSpins=0, addrRslvr=null, ctxInitLatch=java.util.concurrent.CountDownLatch@33179221[Count = 1], stopping=false], evtSpi=MemoryEventStorageSpi [expireAgeMs=9223372036854775807, expireCnt=10000, filter=null], colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@76582a, addrRslvr=null, encryptionSpi=org.apache.ignite.spi.encryption.noop.NoopEncryptionSpi@e66ca60, clientMode=false, rebalanceThreadPoolSize=1, txCfg=TransactionConfiguration [txSerEnabled=false, dfltIsolation=REPEATABLE_READ, dfltConcurrency=PESSIMISTIC, dfltTxTimeout=0, txTimeoutOnPartitionMapExchange=0, pessimisticTxLogSize=0, pessimisticTxLogLinger=10000, tmLookupClsName=null, txManagerFactory=null, useJtaSync=false], 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=BinaryConfiguration [idMapper=null, nameMapper=BinaryBaseNameMapper [isSimpleName=true], serializer=null, compactFooter=true], memCfg=null, pstCfg=null, dsCfg=DataStorageConfiguration [sysRegionInitSize=41943040, sysRegionMaxSize=104857600, pageSize=0, concLvl=0, dfltDataRegConf=DataRegionConfiguration [name=default, maxSize=20274432409, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=false, checkpointPageBufSize=0], dataRegions=null, storagePath=null, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, maxWalArchiveSize=1073741824, 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@d82f038, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false, walCompactionLevel=1], 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=24, idleTimeout=0, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=false, useIgniteSslCtxFactory=true, sslClientAuth=false, sslCtxFactory=null], mvccVacuumThreadCnt=2, mvccVacuumFreq=5000, authEnabled=false, failureHnd=AbstractFailureHandler [ignoredFailureTypes=EmptySet []]NoOpFailureHandler [super=], commFailureRslvr=null]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,549][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Daemon mode: off
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,549][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] OS: Linux 4.4.0-134-generic amd64
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] OS user: teamcity
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] PID: 3032
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Language runtime: Java Platform API Specification ver. 1.8
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM information: Java(TM) SE Runtime Environment 1.8.0_181-b13 Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 25.181-b13
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM total memory: 1.8GB
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Remote Management [restart: off, REST: off, JMX (remote: off)]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Logger: GridTestLog4jLogger [quiet=false, config=null]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,552][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] IGNITE_HOME=/data/teamcity/work/9198da4c51c3e112
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,552][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM arguments: [-DIGNITE_DUMP_THREADS_ON_FAILURE=false, -DMono=/usr/bin/mono-sgen, -DMono4.0_x64=/usr/lib/mono/4.0, -DMono4.5_x64=/usr/lib/mono/4.5, -DMonoVersion=5.4.1.6, -Dagent.home.dir=/home/teamcity/agent, -Dagent.name=publicagent07_9096, -Dagent.ownPort=9096, -Dagent.work.dir=/data/teamcity/work, -Dbuild.number=3986, -Dbuild.vcs.number=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dbuild.vcs.number.1=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dbuild.vcs.number.GitHubApacheIgnite=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dclassworlds.conf=/data/teamcity/temp/buildTmp/teamcity.m2.conf, -Dcom.jetbrains.maven.watcher.report.file=/data/teamcity/temp/buildTmp/maven-build-info.xml, -Djava.io.tmpdir=/data/teamcity/temp/buildTmp, -Dmaven.home=/home/teamcity/agent/tools/maven.3.5.3, -Dmaven.multiModuleProjectDirectory=/data/teamcity/work/9198da4c51c3e112, -Dmaven.repo.local=/home/teamcity/.m2/repository, -Dteamcity.agent.cpuBenchmark=459, -Dteamcity.agent.dotnet.agent_url=http://localhost:9096/RPC2, -Dteamcity.agent.dotnet.build_id=2046426, -Dteamcity.auth.password=*******, -Dteamcity.auth.userId=TeamCityBuildId=2046426, -Dteamcity.build.changedFiles.file=/data/teamcity/temp/buildTmp/changedFiles6946597736255042765.txt, -Dteamcity.build.checkoutDir=/data/teamcity/work/9198da4c51c3e112, -Dteamcity.build.id=2046426, -Dteamcity.build.properties.file=/data/teamcity/temp/buildTmp/teamcity.build4716211550817389630.properties, -Dteamcity.build.tempDir=/data/teamcity/temp/buildTmp, -Dteamcity.build.workingDir=/data/teamcity/work/9198da4c51c3e112, -Dteamcity.buildConfName=Binary Objects, -Dteamcity.buildType.id=IgniteTests24Java8_BinaryObjects, -Dteamcity.configuration.properties.file=/data/teamcity/temp/buildTmp/teamcity.config817725141007444616.properties, -Dteamcity.maven.watcher.home=/home/teamcity/agent/plugins/mavenPlugin/maven-watcher-jdk16, -Dteamcity.projectName=Ignite Tests 2.4+ (Java 8/9/10/11), -Dteamcity.runner.properties.file=/data/teamcity/temp/buildTmp/teamcity.runner8345643043879360132.properties, -Dteamcity.tests.recentlyFailedTests.file=/data/teamcity/temp/buildTmp/testsToRunFirst6462377036881887019.txt, -Dteamcity.version=2017.2.3 (build 51047), -ea, -Xms2g, -Xmx2g, -XX:+HeapDumpOnOutOfMemoryError, -XX:+AggressiveOpts, -DIGNITE_TEST_HOME="/data/teamcity/work/9198da4c51c3e112", -DIGNITE_UPDATE_NOTIFIER=false, -DIGNITE_NO_DISCO_ORDER=true, -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true, -DIGNITE_QUIET=false, -Djava.net.preferIPv4Stack=true]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,557][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemRegionInitialSize property to change the setting.
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,557][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache'], in 'default' dataRegion: ['default']]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,559][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 3-rd party licenses can be found at: /data/teamcity/work/9198da4c51c3e112/libs/licenses
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,563][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] Configured plugins:
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,563][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- TestReconnectPlugin 1.0
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- StanByClusterTestProvider 1.0
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- null
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- PageMemory tracker plugin 1.0
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,566][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][FailureProcessor] Configured failure handler: [hnd=NoOpFailureHandler [super=AbstractFailureHandler [ignoredFailureTypes=EmptySet []]]]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,568][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=45310, locHost=/127.0.0.1, selectorsCnt=12, selectorSpins=0, pairedConn=false]
[04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,568][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][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.
[04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,572][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival).
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,572][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Security status [authentication=off, tls/ssl=off]
[04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,575][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgniteCacheDatabaseSharedManager] DataRegionConfiguration.maxWalArchiveSize instead DataRegionConfiguration.walHistorySize would be used for removing old archive wal files
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,575][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][PartitionsEvictManager] Evict partition permits=6
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,578][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][ClientListenerProcessor] Client connector processor has started on TCP port 10800
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,579][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Non-loopback local IPs: 172.17.0.7
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,579][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Enabled local MACs: 0242AC110007
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,580][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TestTcpDiscoverySpi] Connection check threshold is calculated: 10000
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,581][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TestTcpDiscoverySpi] Successfully bound to TCP port [port=47500, localHost=/127.0.0.1, locNodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,583][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49708]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,583][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49708]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,584][INFO ][tcp-disco-sock-reader-#1412%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49708, rmtPort=49708]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,586][INFO ][tcp-disco-sock-reader-#1412%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49708, rmtPort=49708
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,589][INFO ][tcp-disco-msg-worker-#1400%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=0, intOrder=50, lastExchangeTime=1539133725576, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,590][INFO ][tcp-disco-srvr-#1411%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=32807]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,590][INFO ][tcp-disco-srvr-#1411%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=32807]
[04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,591][INFO ][tcp-disco-sock-reader-#1413%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:32807, rmtPort=32807]
[04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,549][WARN ][jvm-pause-detector-worker][BinaryMetadataUpdatesFlowTest0] Possible too long JVM pause: 911 milliseconds.
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,550][INFO ][tcp-disco-sock-reader-#1407%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:58389, rmtPort=58389
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,550][INFO ][tcp-disco-sock-reader-#1403%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:45328, rmtPort=45328
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,636][INFO ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,637][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=45980]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,637][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=45980]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,638][INFO ][tcp-disco-sock-reader-#1414%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:45980, rmtPort=45980]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,640][INFO ][disco-notifier-worker-#19455%binary.BinaryMetadataUpdatesFlowTest0%][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, crdVer=1539133558282, topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]], crdNode=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,642][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], mvccCrd=MvccCoordinator [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, crdVer=1539133558282, topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]], mvccCrdChange=true, crd=false, evt=NODE_JOINED, evtNode=8fb16dc0-3515-4a02-8069-6c11c7b00000, customEvt=null, allowMerge=true]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,643][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][msg] Components activation performed in 0 ms.
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,645][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647, mvcc=false], encryptionEnabled=false]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,648][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Started cache [name=default, id=1544803905, memoryPolicyName=default, mode=REPLICATED, atomicity=ATOMIC, backups=2147483647, mvcc=false], encryptionEnabled=false]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,649][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Starting caches on local join performed in 5 ms.
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,649][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Skipped waiting for partitions release future (local node is joining) [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,651][INFO ][grid-nio-worker-tcp-comm-0-#19352%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45624]
[04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,651][WARN ][grid-nio-worker-tcp-comm-0-#19352%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,853][INFO ][grid-nio-worker-tcp-comm-1-#19353%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45626]
[04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,854][WARN ][grid-nio-worker-tcp-comm-1-#19353%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,055][INFO ][grid-nio-worker-tcp-comm-2-#19354%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45628]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,055][WARN ][grid-nio-worker-tcp-comm-2-#19354%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,257][INFO ][grid-nio-worker-tcp-comm-3-#19355%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45634]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,257][WARN ][grid-nio-worker-tcp-comm-3-#19355%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,458][INFO ][grid-nio-worker-tcp-comm-4-#19356%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45642]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,459][WARN ][grid-nio-worker-tcp-comm-4-#19356%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
[04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,461][ERROR][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=GridCacheMessage [msgId=207323, depInfo=null, err=null, skipPrepare=false]GridDhtPartitionsAbstractMessage [exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133727156, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], topVer=98, nodeId8=8fb16dc0, msg=null, type=NODE_JOINED, tstamp=1539133726640], nodeId=8fb16dc0, evt=NODE_JOINED], lastVer=GridCacheVersion [topVer=0, order=1539133725566, nodeOrder=0], super=]GridDhtPartitionsSingleMessage [parts=HashMap {1544803905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=1, size=0], -2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=1, size=0]}, partCntrs=HashMap {1544803905=CachePartitionPartialCountersMap {}, -2100569601=CachePartitionPartialCountersMap {}}, partsSizes=null, partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null, activeQryTrackers=GridLongList [idx=0, arr=[]], super=]]]
[04:08:47]W:	[org.apache.ignite:ignite-core] class org.apache.ignite.IgniteCheckedException: Failed to connect to node (is node still alive?). Make sure that each ComputeTask and cache Transaction has a timeout set in order to prevent parties from waiting forever in case of network issues [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=[/127.0.0.1:45312]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3459)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2987)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2870)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2713)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2672)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1656)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:1731)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1170)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendLocalPartitions(GridDhtPartitionsExchangeFuture.java:1662)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1793)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1316)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:781)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2666)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2538)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
[04:08:47]W:	[org.apache.ignite:ignite-core] at java.lang.Thread.run(Thread.java:748)
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
[04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
[04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,478][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Pinging node: 0a7ffe6b-4f53-4e4b-a316-600ab6900002
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,479][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36227]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,480][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36227]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,481][INFO ][tcp-disco-sock-reader-#1416%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36227, rmtPort=36227]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,483][INFO ][tcp-disco-sock-reader-#1416%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36227, rmtPort=36227
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,684][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=40821]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,685][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=40821]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,686][INFO ][tcp-disco-sock-reader-#1417%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:40821, rmtPort=40821]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,687][INFO ][tcp-disco-sock-reader-#1417%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:40821, rmtPort=40821
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,888][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=59890]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,888][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=59890]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,889][INFO ][tcp-disco-sock-reader-#1418%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:59890, rmtPort=59890]
[04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,890][INFO ][tcp-disco-sock-reader-#1418%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:59890, rmtPort=59890
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,091][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=55784]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,092][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=55784]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,093][INFO ][tcp-disco-sock-reader-#1419%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:55784, rmtPort=55784]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,094][INFO ][tcp-disco-sock-reader-#1419%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:55784, rmtPort=55784
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,295][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=60102]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,295][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=60102]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,296][INFO ][tcp-disco-sock-reader-#1420%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:60102, rmtPort=60102]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,297][INFO ][tcp-disco-sock-reader-#1420%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:60102, rmtPort=60102
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,498][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49142]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,498][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49142]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,499][INFO ][tcp-disco-sock-reader-#1421%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49142, rmtPort=49142]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,500][INFO ][tcp-disco-sock-reader-#1421%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49142, rmtPort=49142
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,700][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36918]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,701][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36918]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,701][INFO ][tcp-disco-sock-reader-#1422%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36918, rmtPort=36918]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,702][INFO ][tcp-disco-sock-reader-#1422%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36918, rmtPort=36918
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,903][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=43219]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,904][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=43219]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,904][INFO ][tcp-disco-sock-reader-#1423%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:43219, rmtPort=43219]
[04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,905][INFO ][tcp-disco-sock-reader-#1423%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:43219, rmtPort=43219
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,110][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=41921]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,110][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=41921]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,112][INFO ][tcp-disco-sock-reader-#1424%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:41921, rmtPort=41921]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,113][INFO ][tcp-disco-sock-reader-#1424%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:41921, rmtPort=41921
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,314][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36591]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,314][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36591]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,315][INFO ][tcp-disco-sock-reader-#1425%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36591, rmtPort=36591]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,316][INFO ][tcp-disco-sock-reader-#1425%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36591, rmtPort=36591
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,517][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=44022]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,517][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=44022]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,518][INFO ][tcp-disco-sock-reader-#1426%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:44022, rmtPort=44022]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,518][INFO ][tcp-disco-sock-reader-#1426%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:44022, rmtPort=44022
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,719][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=52890]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,719][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=52890]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,720][INFO ][tcp-disco-sock-reader-#1427%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:52890, rmtPort=52890]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,720][INFO ][tcp-disco-sock-reader-#1427%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:52890, rmtPort=52890
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,921][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49179]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,921][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49179]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,922][INFO ][tcp-disco-sock-reader-#1428%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49179, rmtPort=49179]
[04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,922][INFO ][tcp-disco-sock-reader-#1428%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49179, rmtPort=49179
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,118][INFO ][node-resurrection-thread][TestTcpDiscoverySpi] No verification for local node leave has been received from coordinator (will stop node anyway).
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,121][INFO ][tcp-disco-sock-reader-#1405%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:50382, rmtPort=50382
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,121][INFO ][tcp-disco-sock-reader-#1414%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:45980, rmtPort=45980
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,122][INFO ][node-resurrection-thread][MvccProcessorImpl] Attempting to stop inactive vacuum.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,123][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Finished node ping [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, res=false, time=2654ms]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,124][INFO ][node-resurrection-thread][BinaryMetadataUpdatesFlowTest2] 
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,124][WARN ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Failed to ping node (status check will be initiated): 0a7ffe6b-4f53-4e4b-a316-600ab6900002
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] >>> +------------------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> Ignite ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b82387a971e282fe52a5ef86edc92e09d stopped OK
[04:08:50] :	[Step 4/5] >>> +------------------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> Ignite instance name: binary.BinaryMetadataUpdatesFlowTest2
[04:08:50] :	[Step 4/5] >>> Grid uptime: 00:00:05.075
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,124][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Sending Single Message performed in 3474 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,125][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], crd=false]
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,130][WARN ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Failed to send message to next node [msg=TcpDiscoveryStatusCheckMessage [creatorNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], failedNodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, status=0, super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=ffb929b5661-8fb16dc0-3515-4a02-8069-6c11c7b00000, verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], errMsg=Failed to send message to next node [msg=TcpDiscoveryStatusCheckMessage [creatorNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], failedNodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, status=0, super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=ffb929b5661-8fb16dc0-3515-4a02-8069-6c11c7b00000, verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=ClusterNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, order=93, addr=[127.0.0.1], daemon=false]]]
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,133][WARN ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Local node has detected failed nodes and started cluster-wide procedure. To speed up failure detection please see 'Failure Detection' section under javadoc for 'TcpDiscoverySpi'
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,134][INFO ][disco-notifier-worker-#19455%binary.BinaryMetadataUpdatesFlowTest0%][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [nodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000, crdVer=1539133558287, topVer=AffinityTopologyVersion [topVer=99, minorTopVer=0]], crdNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,135][WARN ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Node FAILED: TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,136][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Topology snapshot [ver=99, locNode=8fb16dc0, servers=1, clients=0, state=ACTIVE, CPUs=24, offheap=19.0GB, heap=2.0GB]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,136][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Coordinator changed [prev=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], cur=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,139][INFO ][sys-#19459%binary.BinaryMetadataUpdatesFlowTest0%][ExchangeLatchManager] Become new coordinator 8fb16dc0-3515-4a02-8069-6c11c7b00000
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,139][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Coordinator failed, node is new coordinator [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0], prev=0a7ffe6b-4f53-4e4b-a316-600ab6900002]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,140][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Init new coordinator, node left [node=0a7ffe6b-4f53-4e4b-a316-600ab6900002]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,149][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Init new coordinator future will skip remote node: TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,149][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Try restore exchange result [awaited=[], joined=[], nodes=[], discoAllNodes=[0a7ffe6b-4f53-4e4b-a316-600ab6900002, 8fb16dc0-3515-4a02-8069-6c11c7b00000]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,150][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] New coordinator restore state finished [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,150][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Coordinator received all messages, try merge [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,151][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridCachePartitionExchangeManager] Merge exchange future [curFut=AffinityTopologyVersion [topVer=98, minorTopVer=0], mergedFut=AffinityTopologyVersion [topVer=99, minorTopVer=0], evt=NODE_FAILED, evtNode=0a7ffe6b-4f53-4e4b-a316-600ab6900002, evtNodeClient=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,151][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Exchanges merging performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,152][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=99, minorTopVer=0]]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,152][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][CacheAffinitySharedManager] Affinity recalculation (on server left) performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,153][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Affinity changes (coordinator) applied in 1 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Partitions validation performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Partitions assignment performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Detecting lost partitions performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Preparing Full Message performed in 2 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Sending Full Message to all nodes performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=99, minorTopVer=0], err=null]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,158][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Detecting lost partitions performed in 0 ms.
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,158][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=8fb16dc0-3515-4a02-8069-6c11c7b00000, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=99, minorTopVer=0], durationFromInit=3515]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,159][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=99, minorTopVer=0], force=false, evt=NODE_JOINED, node=8fb16dc0-3515-4a02-8069-6c11c7b00000]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,162][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat}
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,162][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Data Regions Configured:
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,163][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] ^-- default [initSize=256.0 MiB, maxSize=18.9 GiB, persistence=false]
[04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,163][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 
[04:08:50] :	[Step 4/5] 
[04:08:50] :	[Step 4/5] >>> +-------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> Ignite ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b82387a971e282fe52a5ef86edc92e09d
[04:08:50] :	[Step 4/5] >>> +-------------------------------------------------------------------------------+
[04:08:50] :	[Step 4/5] >>> OS name: Linux 4.4.0-134-generic amd64
[04:08:50] :	[Step 4/5] >>> CPU(s): 24
[04:08:50] :	[Step 4/5] >>> Heap: 2.0GB
[04:08:50] :	[Step 4/5] >>> VM name: 3032@6bca1cd484ee
[04:08:50] :	[Step 4/5] >>> Ignite instance name: binary.BinaryMetadataUpdatesFlowTest0
[04:08:50] :	[Step 4/5] >>> Local node [ID=8FB16DC0-3515-4A02-8069-6C11C7B00000, order=98, clientMode=false]
[04:08:50] :	[Step 4/5] >>> Local node addresses: [127.0.0.1]
[04:08:50] :	[Step 4/5] >>> Local ports: TCP:10800 TCP:45310 TCP:47500{noformat}


> Test BinaryMetadataUpdatesFlowTest.testConcurrentMetadataUpdates is flaky in master.
> ------------------------------------------------------------------------------------
>
>                 Key: IGNITE-9837
>                 URL: https://issues.apache.org/jira/browse/IGNITE-9837
>             Project: Ignite
>          Issue Type: Bug
>            Reporter: Amelchev Nikita
>            Assignee: Amelchev Nikita
>            Priority: Major
>              Labels: MakeTeamcityGreenAgain
>
> The test _BinaryMetadataUpdatesFlowTest.testConcurrentMetadataUpdates_ is flaky in master. Sometimes it fails by timeout (5min). [Example of fail.|https://ci.ignite.apache.org/viewLog.html?buildId=2042133&tab=buildResultsDiv&buildTypeId=IgniteTests24Java8_BinaryObjects#testNameId4314129944736732856] 
> UPDATE:
> When the test is starting node from the previous test wasn't stopped. Previous tests have threads to start and stop nodes. After tests, it only interrupts this threads but doesn't wait for threads cancellation and stopping all nodes.
> Here is the full log:
> (Node with name BinaryMetadataUpdatesFlowTest2 is from the previous test and doesn't correctly stopped)
> {noformat}
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,523][INFO ][main][root] >>> Starting test: BinaryMetadataUpdatesFlowTest#testConcurrentMetadataUpdates <<<
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,538][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 
> [04:08:45] :	[Step 4/5] 
> [04:08:45] :	[Step 4/5] >>> __________ ________________ 
> [04:08:45] :	[Step 4/5] >>> / _/ ___/ |/ / _/_ __/ __/ 
> [04:08:45] :	[Step 4/5] >>> _/ // (7 7 // / / / / _/ 
> [04:08:45] :	[Step 4/5] >>> /___/\___/_/|_/___/ /_/ /___/ 
> [04:08:45] :	[Step 4/5] >>> 
> [04:08:45] :	[Step 4/5] >>> ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b
> [04:08:45] :	[Step 4/5] >>> 2018 Copyright(C) Apache Software Foundation
> [04:08:45] :	[Step 4/5] >>> 
> [04:08:45] :	[Step 4/5] >>> Ignite documentation: http://ignite.apache.org
> [04:08:45] :	[Step 4/5] 
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,539][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Config URL: n/a
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,540][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] IgniteConfiguration [igniteInstanceName=binary.BinaryMetadataUpdatesFlowTest0, pubPoolSize=24, svcPoolSize=24, callbackPoolSize=24, stripedPoolSize=24, sysPoolSize=24, mgmtPoolSize=4, igfsPoolSize=24, dataStreamerPoolSize=24, utilityCachePoolSize=24, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=24, igniteHome=/data/teamcity/work/9198da4c51c3e112, igniteWorkDir=/data/teamcity/work/9198da4c51c3e112/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@1640190a, nodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000, marsh=BinaryMarshaller [], marshLocJobs=false, daemon=false, p2pEnabled=false, 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=org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$FirstConnectionPolicy@46b8261, enableForcibleNodeKill=false, enableTroubleshootingLog=false, locAddr=null, locHost=null, locPort=45310, 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, boundTcpPort=-1, boundTcpShmemPort=-1, selectorsCnt=12, selectorSpins=0, addrRslvr=null, ctxInitLatch=java.util.concurrent.CountDownLatch@33179221[Count = 1], stopping=false], evtSpi=MemoryEventStorageSpi [expireAgeMs=9223372036854775807, expireCnt=10000, filter=null], colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@76582a, addrRslvr=null, encryptionSpi=org.apache.ignite.spi.encryption.noop.NoopEncryptionSpi@e66ca60, clientMode=false, rebalanceThreadPoolSize=1, txCfg=TransactionConfiguration [txSerEnabled=false, dfltIsolation=REPEATABLE_READ, dfltConcurrency=PESSIMISTIC, dfltTxTimeout=0, txTimeoutOnPartitionMapExchange=0, pessimisticTxLogSize=0, pessimisticTxLogLinger=10000, tmLookupClsName=null, txManagerFactory=null, useJtaSync=false], 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=BinaryConfiguration [idMapper=null, nameMapper=BinaryBaseNameMapper [isSimpleName=true], serializer=null, compactFooter=true], memCfg=null, pstCfg=null, dsCfg=DataStorageConfiguration [sysRegionInitSize=41943040, sysRegionMaxSize=104857600, pageSize=0, concLvl=0, dfltDataRegConf=DataRegionConfiguration [name=default, maxSize=20274432409, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=false, checkpointPageBufSize=0], dataRegions=null, storagePath=null, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, maxWalArchiveSize=1073741824, 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@d82f038, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false, walCompactionLevel=1], 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=24, idleTimeout=0, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=false, useIgniteSslCtxFactory=true, sslClientAuth=false, sslCtxFactory=null], mvccVacuumThreadCnt=2, mvccVacuumFreq=5000, authEnabled=false, failureHnd=AbstractFailureHandler [ignoredFailureTypes=EmptySet []]NoOpFailureHandler [super=], commFailureRslvr=null]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,549][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Daemon mode: off
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,549][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] OS: Linux 4.4.0-134-generic amd64
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] OS user: teamcity
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] PID: 3032
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,550][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Language runtime: Java Platform API Specification ver. 1.8
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM information: Java(TM) SE Runtime Environment 1.8.0_181-b13 Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 25.181-b13
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM total memory: 1.8GB
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Remote Management [restart: off, REST: off, JMX (remote: off)]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,551][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Logger: GridTestLog4jLogger [quiet=false, config=null]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,552][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] IGNITE_HOME=/data/teamcity/work/9198da4c51c3e112
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,552][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] VM arguments: [-DIGNITE_DUMP_THREADS_ON_FAILURE=false, -DMono=/usr/bin/mono-sgen, -DMono4.0_x64=/usr/lib/mono/4.0, -DMono4.5_x64=/usr/lib/mono/4.5, -DMonoVersion=5.4.1.6, -Dagent.home.dir=/home/teamcity/agent, -Dagent.name=publicagent07_9096, -Dagent.ownPort=9096, -Dagent.work.dir=/data/teamcity/work, -Dbuild.number=3986, -Dbuild.vcs.number=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dbuild.vcs.number.1=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dbuild.vcs.number.GitHubApacheIgnite=eadae30b82387a971e282fe52a5ef86edc92e09d, -Dclassworlds.conf=/data/teamcity/temp/buildTmp/teamcity.m2.conf, -Dcom.jetbrains.maven.watcher.report.file=/data/teamcity/temp/buildTmp/maven-build-info.xml, -Djava.io.tmpdir=/data/teamcity/temp/buildTmp, -Dmaven.home=/home/teamcity/agent/tools/maven.3.5.3, -Dmaven.multiModuleProjectDirectory=/data/teamcity/work/9198da4c51c3e112, -Dmaven.repo.local=/home/teamcity/.m2/repository, -Dteamcity.agent.cpuBenchmark=459, -Dteamcity.agent.dotnet.agent_url=http://localhost:9096/RPC2, -Dteamcity.agent.dotnet.build_id=2046426, -Dteamcity.auth.password=*******, -Dteamcity.auth.userId=TeamCityBuildId=2046426, -Dteamcity.build.changedFiles.file=/data/teamcity/temp/buildTmp/changedFiles6946597736255042765.txt, -Dteamcity.build.checkoutDir=/data/teamcity/work/9198da4c51c3e112, -Dteamcity.build.id=2046426, -Dteamcity.build.properties.file=/data/teamcity/temp/buildTmp/teamcity.build4716211550817389630.properties, -Dteamcity.build.tempDir=/data/teamcity/temp/buildTmp, -Dteamcity.build.workingDir=/data/teamcity/work/9198da4c51c3e112, -Dteamcity.buildConfName=Binary Objects, -Dteamcity.buildType.id=IgniteTests24Java8_BinaryObjects, -Dteamcity.configuration.properties.file=/data/teamcity/temp/buildTmp/teamcity.config817725141007444616.properties, -Dteamcity.maven.watcher.home=/home/teamcity/agent/plugins/mavenPlugin/maven-watcher-jdk16, -Dteamcity.projectName=Ignite Tests 2.4+ (Java 8/9/10/11), -Dteamcity.runner.properties.file=/data/teamcity/temp/buildTmp/teamcity.runner8345643043879360132.properties, -Dteamcity.tests.recentlyFailedTests.file=/data/teamcity/temp/buildTmp/testsToRunFirst6462377036881887019.txt, -Dteamcity.version=2017.2.3 (build 51047), -ea, -Xms2g, -Xmx2g, -XX:+HeapDumpOnOutOfMemoryError, -XX:+AggressiveOpts, -DIGNITE_TEST_HOME="/data/teamcity/work/9198da4c51c3e112", -DIGNITE_UPDATE_NOTIFIER=false, -DIGNITE_NO_DISCO_ORDER=true, -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true, -DIGNITE_QUIET=false, -Djava.net.preferIPv4Stack=true]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,557][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemRegionInitialSize property to change the setting.
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,557][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache'], in 'default' dataRegion: ['default']]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,559][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 3-rd party licenses can be found at: /data/teamcity/work/9198da4c51c3e112/libs/licenses
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,563][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] Configured plugins:
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,563][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- TestReconnectPlugin 1.0
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- 
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- StanByClusterTestProvider 1.0
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,564][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- null
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- PageMemory tracker plugin 1.0
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] ^-- 
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,565][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgnitePluginProcessor] 
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,566][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][FailureProcessor] Configured failure handler: [hnd=NoOpFailureHandler [super=AbstractFailureHandler [ignoredFailureTypes=EmptySet []]]]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,568][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=45310, locHost=/127.0.0.1, selectorsCnt=12, selectorSpins=0, pairedConn=false]
> [04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,568][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][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.
> [04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,572][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival).
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,572][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Security status [authentication=off, tls/ssl=off]
> [04:08:45]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:45,575][WARN ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][IgniteCacheDatabaseSharedManager] DataRegionConfiguration.maxWalArchiveSize instead DataRegionConfiguration.walHistorySize would be used for removing old archive wal files
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,575][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][PartitionsEvictManager] Evict partition permits=6
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,578][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][ClientListenerProcessor] Client connector processor has started on TCP port 10800
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,579][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Non-loopback local IPs: 172.17.0.7
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,579][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Enabled local MACs: 0242AC110007
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,580][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TestTcpDiscoverySpi] Connection check threshold is calculated: 10000
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,581][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][TestTcpDiscoverySpi] Successfully bound to TCP port [port=47500, localHost=/127.0.0.1, locNodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,583][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49708]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,583][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49708]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,584][INFO ][tcp-disco-sock-reader-#1412%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49708, rmtPort=49708]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,586][INFO ][tcp-disco-sock-reader-#1412%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49708, rmtPort=49708
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,589][INFO ][tcp-disco-msg-worker-#1400%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=0, intOrder=50, lastExchangeTime=1539133725576, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,590][INFO ][tcp-disco-srvr-#1411%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=32807]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,590][INFO ][tcp-disco-srvr-#1411%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=32807]
> [04:08:45] :	[Step 4/5] [2018-10-10 01:08:45,591][INFO ][tcp-disco-sock-reader-#1413%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:32807, rmtPort=32807]
> [04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,549][WARN ][jvm-pause-detector-worker][BinaryMetadataUpdatesFlowTest0] Possible too long JVM pause: 911 milliseconds.
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,550][INFO ][tcp-disco-sock-reader-#1407%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:58389, rmtPort=58389
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,550][INFO ][tcp-disco-sock-reader-#1403%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:45328, rmtPort=45328
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,636][INFO ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,637][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=45980]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,637][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=45980]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,638][INFO ][tcp-disco-sock-reader-#1414%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:45980, rmtPort=45980]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,640][INFO ][disco-notifier-worker-#19455%binary.BinaryMetadataUpdatesFlowTest0%][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, crdVer=1539133558282, topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]], crdNode=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,642][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], mvccCrd=MvccCoordinator [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, crdVer=1539133558282, topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]], mvccCrdChange=true, crd=false, evt=NODE_JOINED, evtNode=8fb16dc0-3515-4a02-8069-6c11c7b00000, customEvt=null, allowMerge=true]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,643][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][msg] Components activation performed in 0 ms.
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,645][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647, mvcc=false], encryptionEnabled=false]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,648][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Started cache [name=default, id=1544803905, memoryPolicyName=default, mode=REPLICATED, atomicity=ATOMIC, backups=2147483647, mvcc=false], encryptionEnabled=false]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,649][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCacheProcessor] Starting caches on local join performed in 5 ms.
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,649][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Skipped waiting for partitions release future (local node is joining) [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,651][INFO ][grid-nio-worker-tcp-comm-0-#19352%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45624]
> [04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,651][WARN ][grid-nio-worker-tcp-comm-0-#19352%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
> [04:08:46] :	[Step 4/5] [2018-10-10 01:08:46,853][INFO ][grid-nio-worker-tcp-comm-1-#19353%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45626]
> [04:08:46]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:46,854][WARN ][grid-nio-worker-tcp-comm-1-#19353%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,055][INFO ][grid-nio-worker-tcp-comm-2-#19354%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45628]
> [04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,055][WARN ][grid-nio-worker-tcp-comm-2-#19354%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,257][INFO ][grid-nio-worker-tcp-comm-3-#19355%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45634]
> [04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,257][WARN ][grid-nio-worker-tcp-comm-3-#19355%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,458][INFO ][grid-nio-worker-tcp-comm-4-#19356%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:45312, rmtAddr=/127.0.0.1:45642]
> [04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,459][WARN ][grid-nio-worker-tcp-comm-4-#19356%binary.BinaryMetadataUpdatesFlowTest2%][TcpCommunicationSpi] Local node is not started or fully initialized [isStopping=true]
> [04:08:47]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:47,461][ERROR][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=GridCacheMessage [msgId=207323, depInfo=null, err=null, skipPrepare=false]GridDhtPartitionsAbstractMessage [exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133727156, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], topVer=98, nodeId8=8fb16dc0, msg=null, type=NODE_JOINED, tstamp=1539133726640], nodeId=8fb16dc0, evt=NODE_JOINED], lastVer=GridCacheVersion [topVer=0, order=1539133725566, nodeOrder=0], super=]GridDhtPartitionsSingleMessage [parts=HashMap {1544803905=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=1, size=0], -2100569601=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=1, size=0]}, partCntrs=HashMap {1544803905=CachePartitionPartialCountersMap {}, -2100569601=CachePartitionPartialCountersMap {}}, partsSizes=null, partHistCntrs=null, err=null, client=false, compress=true, finishMsg=null, activeQryTrackers=GridLongList [idx=0, arr=[]], super=]]]
> [04:08:47]W:	[org.apache.ignite:ignite-core] class org.apache.ignite.IgniteCheckedException: Failed to connect to node (is node still alive?). Make sure that each ComputeTask and cache Transaction has a timeout set in order to prevent parties from waiting forever in case of network issues [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=[/127.0.0.1:45312]]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3459)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2987)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2870)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2713)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:2672)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1656)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:1731)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1170)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendLocalPartitions(GridDhtPartitionsExchangeFuture.java:1662)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.sendPartitions(GridDhtPartitionsExchangeFuture.java:1793)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.distributedExchange(GridDhtPartitionsExchangeFuture.java:1316)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:781)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body0(GridCachePartitionExchangeManager.java:2666)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:2538)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at java.lang.Thread.run(Thread.java:748)
> [04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to connect to address [addr=/127.0.0.1:45312, err=Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3462)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47]W:	[org.apache.ignite:ignite-core] Caused by: class org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$HandshakeException: Remote node ID is not as expected [expected=0a7ffe6b-4f53-4e4b-a316-600ab6900002, rcvd=null]
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeTcpHandshake(TcpCommunicationSpi.java:3678)
> [04:08:47]W:	[org.apache.ignite:ignite-core] at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:3313)
> [04:08:47]W:	[org.apache.ignite:ignite-core] ... 15 more
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,478][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Pinging node: 0a7ffe6b-4f53-4e4b-a316-600ab6900002
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,479][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36227]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,480][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36227]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,481][INFO ][tcp-disco-sock-reader-#1416%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36227, rmtPort=36227]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,483][INFO ][tcp-disco-sock-reader-#1416%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36227, rmtPort=36227
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,684][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=40821]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,685][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=40821]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,686][INFO ][tcp-disco-sock-reader-#1417%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:40821, rmtPort=40821]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,687][INFO ][tcp-disco-sock-reader-#1417%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:40821, rmtPort=40821
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,888][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=59890]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,888][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=59890]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,889][INFO ][tcp-disco-sock-reader-#1418%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:59890, rmtPort=59890]
> [04:08:47] :	[Step 4/5] [2018-10-10 01:08:47,890][INFO ][tcp-disco-sock-reader-#1418%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:59890, rmtPort=59890
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,091][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=55784]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,092][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=55784]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,093][INFO ][tcp-disco-sock-reader-#1419%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:55784, rmtPort=55784]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,094][INFO ][tcp-disco-sock-reader-#1419%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:55784, rmtPort=55784
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,295][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=60102]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,295][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=60102]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,296][INFO ][tcp-disco-sock-reader-#1420%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:60102, rmtPort=60102]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,297][INFO ][tcp-disco-sock-reader-#1420%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:60102, rmtPort=60102
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,498][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49142]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,498][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49142]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,499][INFO ][tcp-disco-sock-reader-#1421%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49142, rmtPort=49142]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,500][INFO ][tcp-disco-sock-reader-#1421%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49142, rmtPort=49142
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,700][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36918]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,701][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36918]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,701][INFO ][tcp-disco-sock-reader-#1422%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36918, rmtPort=36918]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,702][INFO ][tcp-disco-sock-reader-#1422%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36918, rmtPort=36918
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,903][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=43219]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,904][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=43219]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,904][INFO ][tcp-disco-sock-reader-#1423%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:43219, rmtPort=43219]
> [04:08:48] :	[Step 4/5] [2018-10-10 01:08:48,905][INFO ][tcp-disco-sock-reader-#1423%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:43219, rmtPort=43219
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,110][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=41921]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,110][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=41921]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,112][INFO ][tcp-disco-sock-reader-#1424%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:41921, rmtPort=41921]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,113][INFO ][tcp-disco-sock-reader-#1424%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:41921, rmtPort=41921
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,314][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=36591]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,314][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=36591]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,315][INFO ][tcp-disco-sock-reader-#1425%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:36591, rmtPort=36591]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,316][INFO ][tcp-disco-sock-reader-#1425%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:36591, rmtPort=36591
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,517][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=44022]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,517][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=44022]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,518][INFO ][tcp-disco-sock-reader-#1426%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:44022, rmtPort=44022]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,518][INFO ][tcp-disco-sock-reader-#1426%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:44022, rmtPort=44022
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,719][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=52890]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,719][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=52890]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,720][INFO ][tcp-disco-sock-reader-#1427%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:52890, rmtPort=52890]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,720][INFO ][tcp-disco-sock-reader-#1427%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:52890, rmtPort=52890
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,921][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/127.0.0.1, rmtPort=49179]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,921][INFO ][tcp-disco-srvr-#1401%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/127.0.0.1, rmtPort=49179]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,922][INFO ][tcp-disco-sock-reader-#1428%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Started serving remote node connection [rmtAddr=/127.0.0.1:49179, rmtPort=49179]
> [04:08:49] :	[Step 4/5] [2018-10-10 01:08:49,922][INFO ][tcp-disco-sock-reader-#1428%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:49179, rmtPort=49179
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,118][INFO ][node-resurrection-thread][TestTcpDiscoverySpi] No verification for local node leave has been received from coordinator (will stop node anyway).
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,121][INFO ][tcp-disco-sock-reader-#1405%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:50382, rmtPort=50382
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,121][INFO ][tcp-disco-sock-reader-#1414%binary.BinaryMetadataUpdatesFlowTest2%][TestTcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/127.0.0.1:45980, rmtPort=45980
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,122][INFO ][node-resurrection-thread][MvccProcessorImpl] Attempting to stop inactive vacuum.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,123][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Finished node ping [nodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, res=false, time=2654ms]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,124][INFO ][node-resurrection-thread][BinaryMetadataUpdatesFlowTest2] 
> [04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,124][WARN ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Failed to ping node (status check will be initiated): 0a7ffe6b-4f53-4e4b-a316-600ab6900002
> [04:08:50] :	[Step 4/5] 
> [04:08:50] :	[Step 4/5] >>> +------------------------------------------------------------------------------------------+
> [04:08:50] :	[Step 4/5] >>> Ignite ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b82387a971e282fe52a5ef86edc92e09d stopped OK
> [04:08:50] :	[Step 4/5] >>> +------------------------------------------------------------------------------------------+
> [04:08:50] :	[Step 4/5] >>> Ignite instance name: binary.BinaryMetadataUpdatesFlowTest2
> [04:08:50] :	[Step 4/5] >>> Grid uptime: 00:00:05.075
> [04:08:50] :	[Step 4/5] 
> [04:08:50] :	[Step 4/5] 
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,124][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Sending Single Message performed in 3474 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,125][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], crd=false]
> [04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,130][WARN ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Failed to send message to next node [msg=TcpDiscoveryStatusCheckMessage [creatorNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], failedNodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, status=0, super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=ffb929b5661-8fb16dc0-3515-4a02-8069-6c11c7b00000, verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], errMsg=Failed to send message to next node [msg=TcpDiscoveryStatusCheckMessage [creatorNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], failedNodeId=0a7ffe6b-4f53-4e4b-a316-600ab6900002, status=0, super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=ffb929b5661-8fb16dc0-3515-4a02-8069-6c11c7b00000, verifierNodeId=null, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=ClusterNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, order=93, addr=[127.0.0.1], daemon=false]]]
> [04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,133][WARN ][tcp-disco-msg-worker-#1410%binary.BinaryMetadataUpdatesFlowTest0%][TestTcpDiscoverySpi] Local node has detected failed nodes and started cluster-wide procedure. To speed up failure detection please see 'Failure Detection' section under javadoc for 'TcpDiscoverySpi'
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,134][INFO ][disco-notifier-worker-#19455%binary.BinaryMetadataUpdatesFlowTest0%][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [nodeId=8fb16dc0-3515-4a02-8069-6c11c7b00000, crdVer=1539133558287, topVer=AffinityTopologyVersion [topVer=99, minorTopVer=0]], crdNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
> [04:08:50]W:	[org.apache.ignite:ignite-core] [2018-10-10 01:08:50,135][WARN ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Node FAILED: TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,136][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Topology snapshot [ver=99, locNode=8fb16dc0, servers=1, clients=0, state=ACTIVE, CPUs=24, offheap=19.0GB, heap=2.0GB]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,136][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDiscoveryManager] Coordinator changed [prev=TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], cur=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,139][INFO ][sys-#19459%binary.BinaryMetadataUpdatesFlowTest0%][ExchangeLatchManager] Become new coordinator 8fb16dc0-3515-4a02-8069-6c11c7b00000
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,139][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Coordinator failed, node is new coordinator [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0], prev=0a7ffe6b-4f53-4e4b-a316-600ab6900002]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,140][INFO ][disco-event-worker-#19456%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Init new coordinator, node left [node=0a7ffe6b-4f53-4e4b-a316-600ab6900002]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,149][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Init new coordinator future will skip remote node: TcpDiscoveryNode [id=0a7ffe6b-4f53-4e4b-a316-600ab6900002, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47502], discPort=47502, order=93, intOrder=49, lastExchangeTime=1539133726620, loc=false, ver=2.7.0#20181009-sha1:eadae30b, isClient=false]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,149][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][InitNewCoordinatorFuture] Try restore exchange result [awaited=[], joined=[], nodes=[], discoAllNodes=[0a7ffe6b-4f53-4e4b-a316-600ab6900002, 8fb16dc0-3515-4a02-8069-6c11c7b00000]]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,150][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] New coordinator restore state finished [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,150][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Coordinator received all messages, try merge [ver=AffinityTopologyVersion [topVer=98, minorTopVer=0]]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,151][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridCachePartitionExchangeManager] Merge exchange future [curFut=AffinityTopologyVersion [topVer=98, minorTopVer=0], mergedFut=AffinityTopologyVersion [topVer=99, minorTopVer=0], evt=NODE_FAILED, evtNode=0a7ffe6b-4f53-4e4b-a316-600ab6900002, evtNodeClient=false]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,151][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Exchanges merging performed in 0 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,152][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=99, minorTopVer=0]]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,152][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][CacheAffinitySharedManager] Affinity recalculation (on server left) performed in 0 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,153][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Affinity changes (coordinator) applied in 1 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Partitions validation performed in 0 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Partitions assignment performed in 0 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,154][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Detecting lost partitions performed in 0 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Preparing Full Message performed in 2 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Sending Full Message to all nodes performed in 0 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,157][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=99, minorTopVer=0], err=null]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,158][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Detecting lost partitions performed in 0 ms.
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,158][INFO ][sys-#19460%binary.BinaryMetadataUpdatesFlowTest0%][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=8fb16dc0-3515-4a02-8069-6c11c7b00000, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=98, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=8fb16dc0-3515-4a02-8069-6c11c7b00000, addrs=ArrayList [127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=98, intOrder=50, lastExchangeTime=1539133729680, loc=true, ver=2.7.0#20181009-sha1:eadae30b, isClient=false], done=true], topVer=AffinityTopologyVersion [topVer=99, minorTopVer=0], durationFromInit=3515]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,159][INFO ][exchange-worker-#19457%binary.BinaryMetadataUpdatesFlowTest0%][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=99, minorTopVer=0], force=false, evt=NODE_JOINED, node=8fb16dc0-3515-4a02-8069-6c11c7b00000]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,162][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat}
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,162][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] Data Regions Configured:
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,163][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] ^-- default [initSize=256.0 MiB, maxSize=18.9 GiB, persistence=false]
> [04:08:50] :	[Step 4/5] [2018-10-10 01:08:50,163][INFO ][test-runner-#19379%binary.BinaryMetadataUpdatesFlowTest%][BinaryMetadataUpdatesFlowTest0] 
> [04:08:50] :	[Step 4/5] 
> [04:08:50] :	[Step 4/5] >>> +-------------------------------------------------------------------------------+
> [04:08:50] :	[Step 4/5] >>> Ignite ver. 2.7.0-SNAPSHOT#20181009-sha1:eadae30b82387a971e282fe52a5ef86edc92e09d
> [04:08:50] :	[Step 4/5] >>> +-------------------------------------------------------------------------------+
> [04:08:50] :	[Step 4/5] >>> OS name: Linux 4.4.0-134-generic amd64
> [04:08:50] :	[Step 4/5] >>> CPU(s): 24
> [04:08:50] :	[Step 4/5] >>> Heap: 2.0GB
> [04:08:50] :	[Step 4/5] >>> VM name: 3032@6bca1cd484ee
> [04:08:50] :	[Step 4/5] >>> Ignite instance name: binary.BinaryMetadataUpdatesFlowTest0
> [04:08:50] :	[Step 4/5] >>> Local node [ID=8FB16DC0-3515-4A02-8069-6C11C7B00000, order=98, clientMode=false]
> [04:08:50] :	[Step 4/5] >>> Local node addresses: [127.0.0.1]
> [04:08:50] :	[Step 4/5] >>> Local ports: TCP:10800 TCP:45310 TCP:47500{noformat}



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)


Mime
View raw message