[
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 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}
was:
The test _BinaryMetadataUpdatesFlowTest.testConcurrentMetadataUpdates_ is flaky
in master. Sometimes it fails by timeout (5min). [Example of fail.
U|https://ci.ignite.apache.org/viewLog.html?buildId=2042133&tab=buildResultsDiv&buildTypeId=IgniteTests24Java8_BinaryObjects#testNameId4314129944736732856]PDATE:
When test started node from previous test wasnt stopped.
> 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 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}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
