[
https://issues.apache.org/jira/browse/IGNITE-9837?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16659286#comment-16659286
]
ASF GitHub Bot commented on IGNITE-9837:
----------------------------------------
Github user asfgit closed the pull request at:
https://github.com/apache/ignite/pull/4969
> 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
> Fix For: 2.8
>
>
> 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)
