[
https://issues.apache.org/jira/browse/IGNITE-4213?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ksenia Rybakova updated IGNITE-4213:
------------------------------------
Description:
Load configuration
- Benchmark: CacheRandomOperation
- Operations: put, put_all, get, get_all, invoke, invoke_all, remove,
remove_all, put_if_absent, replace
- Heap: 8Gb for servers, 4Gb for clients
- 5 clients, 20 servers
- Number of caches: 12
- Types of caches (atomicity mode): different (atomic, transactional)
- Types of caches (tiered storage mode): different (onheap without eviction,
onheap with eviction, offheap_tired, offheap_values)
- Types of caches (indexing): different (with and without indexes)
- Types of caches (cache mode): different (partitioned, replicated)
- Backups count: 1
- Failover: 1 server are being restarted every 15 minutes
- Duration: 12h
- TLSv1.2 enabled
After one of the servers was restarted (killed and started again) on purpose
another one failed unexpectedly with the following errors:
{noformat}
[23:12:24,599][ERROR][tcp-disco-sock-reader-#72%null%][TcpDiscoverySpi] Failed
to initialize connection (this can happen due to short time network problems
and can be ignored if does not affect node discovery)
[sock=20a09999[SSL_NULL_WIT
H_NULL_NULL: Socket[addr=/172.25.1.35,port=34762,localport=47500]]]
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
at sun.security.ssl.InputRecord.read(InputRecord.java:480)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
at
sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1332)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:889)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at
org.apache.ignite.spi.discovery.tcp.ServerImpl$SocketReader.body(ServerImpl.java:5260)
at org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
[23:12:25,340][WARN ][grid-nio-worker-1-#10%null%][TcpCommunicationSpi] Failed
to process selector key (will close): GridSelectorNioSessionImpl
[selectorIdx=1, queueSize=5, writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32530
cap=32768], r
eadBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
recovery=GridNioRecoveryDescriptor [acked=1508080, resendCnt=0, rcvCnt=1812199,
sentCnt=1508107, reserved=true, lastAck=1812192, nodeLeft=false,
node=TcpDiscoveryNode [id=2f7d3
673-2ca6-4d68-8b73-0c6a209df16f, addrs=[127.0.0.1, 172.25.1.36],
sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500], discPort=47500, order=7,
intOrder=7, lastExchangeTime=1478801828352, loc=false,
ver=1.8.0#20161110-sha1:baa75266, isClient
=false], connected=true, connectCnt=1, queueLimit=5120, reserveCnt=1],
super=GridNioSessionImpl [locAddr=/172.25.1.31:39392,
rmtAddr=/172.25.1.36:47100, createTime=1478801829611, closeTime=0,
bytesSent=2559699127, bytesRcvd=2820406363, s
ndSchedTime=1478808745318, lastSndTime=1478808745334,
lastRcvTime=1478808745334, readsPaused=false,
filterChain=FilterChain[filters=[GridNioCodecFilter
[parser=o.a.i.i.util.nio.GridDirectParser@61d3d493, directMode=true],
GridConnectionB
ytesVerifyFilter, SSL filter], accepted=false]]
[23:12:25,341][WARN ][grid-nio-worker-1-#10%null%][TcpCommunicationSpi] Closing
NIO session because of unhandled exception [cls=class
o.a.i.i.util.nio.GridNioException, msg=Connection reset by peer]
[23:12:26,331][WARN ][tcp-disco-msg-worker-#2%null%][TcpDiscoverySpi] Node is
out of topology (probably, due to short-time network problems).
[23:12:26,332][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Local
node SEGMENTED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[/127.0.0.1:47500,
testagent01.gridgain.
local/172.25.1.31:47500], discPort=47500, order=1, intOrder=1,
lastExchangeTime=1478808746325, loc=true, ver=1.8.0#20161110-sha1:baa75266,
isClient=false]
[23:12:26,393][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
Stopping local node according to configured segmentation policy.
[23:12:26,393][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=6413da0d-fa60-42d1-8f44-dcbd88055cc6,
addrs=[127.0.0.1, 172.25.1.32], sockAddrs=[172.25.1.32/172.25.1.32:47500,
/127.0.0.1:47500]
, discPort=47500, order=2, intOrder=2, lastExchangeTime=1478801825834,
loc=false, ver=1.8.0#20161110-sha1:baa75266, isClient=false]
[23:12:26,394][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=18, clients=5, CPUs=128, heap=160.0GB]
[23:12:26,396][INFO ][Thread-4][GridTcpRestProtocol] Command protocol
successfully stopped: TCP binary
[23:12:26,405][ERROR][sys-#188%null%][GridDhtAtomicCache]
<atomic-offheap-values> Failed to send deferred DHT update response to remote
node [futIds=[GridCacheVersion [topVer=90281865, time=1478808744658,
order=1479020599817, nodeOrder=7
], GridCacheVersion [topVer=90281865, time=1478808744672, order=1479020600087,
nodeOrder=7], GridCacheVersion [topVer=90281865, time=1478808744687,
order=1479020600359, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744759,
order=1479020601713, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744761, order=1479020601746, nodeOrder=7], GridCacheVersion
[topVer=90281865, time=1478808744787, order=1479020602023, nodeOrder=7],
GridCacheVersion [top
Ver=90281865, time=1478808744797, order=1479020602260, nodeOrder=7],
GridCacheVersion [topVer=90281865, time=1478808744911, order=1479020603563,
nodeOrder=7], GridCacheVersion [topVer=90281865, time=1478808744913,
order=1479020603600, no
deOrder=7], GridCacheVersion [topVer=90281865, time=1478808744919,
order=1479020603734, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744923, order=1479020604206, nodeOrder=7], GridCacheVersion
[topVer=90281865, time=14788
08744925, order=1479020604312, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744926, order=1479020604352, nodeOrder=7], GridCacheVersion
[topVer=90281865, time=1478808745205, order=1479020604469, nodeOrder=7],
GridCacheVer
sion [topVer=90281865, time=1478808745208, order=1479020604681, nodeOrder=7]],
node=2f7d3673-2ca6-4d68-8b73-0c6a209df16f]
class org.apache.ignite.IgniteCheckedException: Failed to send message (node
may have left the grid or TCP connection cannot be established due to firewall
issues) [node=TcpDiscoveryNode [id=2f7d3673-2ca6-4d68-8b73-0c6a209df16f,
addrs=[1
27.0.0.1, 172.25.1.36], sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500],
discPort=47500, order=7, intOrder=7, lastExchangeTime=1478801828352, loc=false,
ver=1.8.0#20161110-sha1:baa75266, isClient=false], topic=TOPIC_CACHE,
msg=GridCache
Message [msgId=36713767, depInfo=null, err=null, skipPrepare=false,
cacheId=1489451830, cacheId=1489451830], policy=2]
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1153)
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1217)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:841)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:990)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$3.finish(GridDhtAtomicCache.java:255)
at
org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer.finish0(GridDeferredAckMessageSender.java:214)
at
org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer.access$000(GridDeferredAckMessageSender.java:111)
at
org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer$1.run(GridDeferredAckMessageSender.java:159)
at
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6589)
at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(GridClosureProcessor.java:764)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: class org.apache.ignite.spi.IgniteSpiException: Failed to send
message to remote node: TcpDiscoveryNode
[id=2f7d3673-2ca6-4d68-8b73-0c6a209df16f, addrs=[127.0.0.1, 172.25.1.36],
sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500], discPort=47500, order=7,
intOrder=7, lastExchangeTime=1478801828352, loc=false,
ver=1.8.0#20161110-sha1:baa75266, isClient=false]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2017)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1955)
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1148)
... 13 more
Caused by: 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=2f7d3673-2ca6-4d68-8b73-0c6a209df16f,
addrs=[/172.25.1.36:47100, /127.0.0.1:47100]]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2521)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2161)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2055)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1989)
... 15 more
Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to
connect to address: /172.25.1.36:47100
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2526)
... 18 more
Caused by: class org.apache.ignite.IgniteCheckedException: Failed to
read remote node recovery handshake (connection closed).
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeHandshake(TcpCommunicationSpi.java:2709)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2398)
... 18 more
Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to
connect to address: /127.0.0.1:47100
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2526)
... 18 more
Caused by: class org.apache.ignite.IgniteCheckedException: Remote node
ID is not as expected [expected=2f7d3673-2ca6-4d68-8b73-0c6a209df16f,
rcvd=5fec5215-bbcb-48b3-bcdf-480243950218]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeHandshake(TcpCommunicationSpi.java:2638)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2398)
... 18 more
[23:12:26,406][WARN ][sys-#180%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745219, order=1479020605899, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,406][WARN ][sys-#169%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745218, order=1479020605897, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,406][WARN ][sys-#161%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745209, order=1479020605896, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,406][WARN ][sys-#188%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745231, order=1479020606225, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,409][ERROR][sys-#188%null%][GridCacheIoManager] Failed processing
message [senderId=a5a404d1-d9e8-4a5f-9ab3-cecaa6acde5f,
msg=GridDhtAtomicUpdateRequest [nodeId=null, futVer=GridCacheVersion
[topVer=90281865, time=1478808745326, order=1479020607019, nodeOrder=12],
writeVer=GridCacheVersion [topVer=90281865, time=1478808745326,
order=1479020607018, nodeOrder=12], topVer=AffinityTopologyVersion [topVer=40,
minorTopVer=0], keys=[KeyCacheObjectImpl [val=253965, hasValBytes=true]],
vals=[null], prevVals=null, ttls=null, conflictExpireTimes=null, nearTtls=null,
nearExpireTimes=null, syncMode=PRIMARY_SYNC, nearKeys=null, nearVals=null,
forceTransformBackups=false, subjId=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421,
taskNameHash=0, updateCntrs=GridLongList [idx=1, arr=[11573]], onRes=false,
keepBinary=false, flags=0, super=GridCacheMessage [msgId=37427737,
depInfo=null, err=null, skipPrepare=false, cacheId=-770341200,
cacheId=-770341200]]]
java.lang.IllegalStateException: Failed to remove from index (grid is stopping).
at
org.apache.ignite.internal.processors.query.GridQueryProcessor.remove(GridQueryProcessor.java:1017)
at
org.apache.ignite.internal.processors.cache.query.GridCacheQueryManager.remove(GridCacheQueryManager.java:411)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearIndex(GridCacheMapEntry.java:4042)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.innerUpdate(GridCacheMapEntry.java:2522)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateRequest(GridDhtAtomicCache.java:3157)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$1800(GridDhtAtomicCache.java:125)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:369)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:364)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:758)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:363)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:287)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$000(GridCacheIoManager.java:89)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:232)
at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
at
org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
at
org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
[23:12:26,409][ERROR][sys-#169%null%][GridCacheIoManager] Failed processing
message [senderId=1fa739fb-560f-41d5-8e3b-26e69f993572,
msg=GridDhtAtomicUpdateRequest [nodeId=null, futVer=GridCacheVersion
[topVer=90281865, time=1478808745301, order=1479020606608, nodeOrder=10],
writeVer=GridCacheVersion [topVer=90281865, time=1478808745301,
order=1479020606607, nodeOrder=10], topVer=AffinityTopologyVersion [topVer=40,
minorTopVer=0], keys=[KeyCacheObjectImpl [val=461996, hasValBytes=true]],
vals=[null], prevVals=null, ttls=null, conflictExpireTimes=null, nearTtls=null,
nearExpireTimes=null, syncMode=PRIMARY_SYNC, nearKeys=null, nearVals=null,
forceTransformBackups=false, subjId=07e3d9f2-c151-4b5a-9007-65b52aa983b7,
taskNameHash=0, updateCntrs=GridLongList [idx=1, arr=[11366]], onRes=false,
keepBinary=false, flags=0, super=GridCacheMessage [msgId=39950832,
depInfo=null, err=null, skipPrepare=false, cacheId=-770341200,
cacheId=-770341200]]]
java.lang.IllegalStateException: Failed to remove from index (grid is stopping).
at
org.apache.ignite.internal.processors.query.GridQueryProcessor.remove(GridQueryProcessor.java:1017)
at
org.apache.ignite.internal.processors.cache.query.GridCacheQueryManager.remove(GridCacheQueryManager.java:411)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearIndex(GridCacheMapEntry.java:4042)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.innerUpdate(GridCacheMapEntry.java:2522)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateRequest(GridDhtAtomicCache.java:3157)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$1800(GridDhtAtomicCache.java:125)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:369)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:364)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:758)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:363)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:287)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$000(GridCacheIoManager.java:89)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:232)
at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
at
org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
at
org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
{noformat}
Example log of some other server at this time:
{noformat}
[23:12:20,741][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6413da0d, name=null, uptime=01:54:54:579]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=13.67%, avg=14.89%, GC=0.87%]
^-- Heap [used=3715MB, free=54.65%, comm=8192MB]
^-- Non heap [used=48MB, free=61.72%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:24,933][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:24,951][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:25,068][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
/127.0.0.1:47500]
[23:12:25,069][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:25,154][WARN ][sys-#185%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744922, order=1479020603983, nodeOrder=24],
dhtTxId=null,
[23:12:25,300][WARN ][sys-#158%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,360][WARN ][sys-#188%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744918, order=1479020603580, nodeOrder=25],
dhtTxId=null,
[23:12:25,364][WARN ][sys-#169%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744443, order=1479020595316, nodeOrder=25],
dhtTxId=null,
[23:12:25,678][WARN ][sys-#184%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,701][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744716, order=1479020600668, nodeOrder=23],
dhtTxId=null,
[23:12:25,749][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6413da0d, name=null, uptime=01:54:59:585]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=7.2%, avg=14.88%, GC=0%]
^-- Heap [used=3909MB, free=52.27%, comm=8192MB]
^-- Non heap [used=49MB, free=61.7%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:25,762][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,762][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
dhtTxId=null,
[23:12:25,768][WARN ][sys-#171%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
dhtTxId=null,
[23:12:25,877][WARN ][sys-#180%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:25,917][WARN ][sys-#191%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608336, nodeOrder=25],
dhtTxId=null,
[23:12:25,918][WARN ][sys-#155%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744921, order=1479020603934, nodeOrder=23],
dhtTxId=null,
[23:12:25,918][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744936, order=1479020603682, nodeOrder=25],
dhtTxId=null,
[23:12:26,008][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744781, order=1479020602170, nodeOrder=23],
dhtTxId=null,
[23:12:26,008][WARN ][sys-#183%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808744959, order=1479020604994, nodeOrder=23],
dhtTxId=null,
[23:12:26,028][WARN ][sys-#191%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,067][WARN ][sys-#188%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608335, nodeOrder=25],
dhtTxId=null,
[23:12:26,084][WARN ][sys-#166%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744937, order=1479020604456, nodeOrder=21],
dhtTxId=null,
[23:12:29,932][WARN ][sys-#154%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808743558, order=1479020583258, nodeOrder=21],
dhtTxId=null,
[23:12:30,122][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745236, order=1479020606164, nodeOrder=21],
dhtTxId=null,
[23:12:30,372][WARN ][sys-#167%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745868, order=1479020609299, nodeOrder=21],
dhtTxId=null,
[23:12:30,757][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6413da0d, name=null, uptime=01:55:04:593]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=0.5%, avg=14.88%, GC=0%]
^-- Heap [used=3949MB, free=51.78%, comm=8192MB]
^-- Non heap [used=49MB, free=61.68%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:24,621][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=487de04c, name=null, uptime=01:54:58:326]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=18.77%, avg=21.83%, GC=0.5%]
^-- Heap [used=3713MB, free=54.67%, comm=8192MB]
^-- Non heap [used=49MB, free=61.69%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=3]
[23:12:24,942][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:24,945][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:25,084][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
/127.0.0.1:47500]
[23:12:25,085][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:25,210][WARN ][sys-#189%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744378, order=1479020593863, nodeOrder=23],
dhtTxId=null,
[23:12:25,305][WARN ][sys-#178%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,353][WARN ][sys-#171%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808742992, order=1479020576526, nodeOrder=22],
dhtTxId=null,
[23:12:25,353][WARN ][sys-#184%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744177, order=1479020591329, nodeOrder=22],
dhtTxId=null,
[23:12:25,512][WARN ][sys-#149%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744918, order=1479020603580, nodeOrder=25],
dhtTxId=null,
[23:12:25,572][WARN ][sys-#154%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,710][WARN ][sys-#183%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744984, order=1479020605045, nodeOrder=21],
dhtTxId=null,
[23:12:25,733][WARN ][sys-#173%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744542, order=1479020597396, nodeOrder=25],
dhtTxId=null,
[23:12:25,761][WARN ][sys-#160%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744366, order=1479020593140, nodeOrder=21],
dhtTxId=null,
[23:12:25,763][WARN ][sys-#190%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,773][WARN ][sys-#186%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
dhtTxId=null,
[23:12:25,879][WARN ][sys-#166%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:25,888][WARN ][sys-#158%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744922, order=1479020603994, nodeOrder=24],
dhtTxId=null,
[23:12:25,919][WARN ][sys-#195%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608336, nodeOrder=25],
dhtTxId=null,
[23:12:26,030][WARN ][sys-#190%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,066][WARN ][sys-#161%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745824, order=1479020608940, nodeOrder=21],
dhtTxId=null,
[23:12:26,068][WARN ][sys-#173%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745299, order=1479020606786, nodeOrder=21],
dhtTxId=null,
[23:12:26,088][WARN ][sys-#155%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744937, order=1479020604334, nodeOrder=23],
dhtTxId=null,
[23:12:29,623][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=487de04c, name=null, uptime=01:55:03:327]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=10.1%, avg=21.83%, GC=0%]
^-- Heap [used=3977MB, free=51.44%, comm=8192MB]
^-- Non heap [used=49MB, free=61.68%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:21,602][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=2ca811d9, name=null, uptime=01:54:55:355]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=41.03%, avg=14.42%, GC=0.67%]
^-- Heap [used=3863MB, free=52.84%, comm=8192MB]
^-- Non heap [used=48MB, free=61.92%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:25,197][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:25,200][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:25,251][WARN ][sys-#148%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744743, order=1479020601226, nodeOrder=24],
dhtTxId=null,
[23:12:25,285][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[localhost/127.0.0.1:47500,
testagent01.gridgain.
[23:12:25,286][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:25,300][WARN ][sys-#159%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744442, order=1479020595560, nodeOrder=24],
dhtTxId=null,
[23:12:25,330][WARN ][sys-#182%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,359][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744563, order=1479020597755, nodeOrder=22],
dhtTxId=null,
[23:12:25,361][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808743289, order=1479020579258, nodeOrder=22],
dhtTxId=null,
[23:12:25,902][WARN ][sys-#192%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,902][WARN ][sys-#193%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,909][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744366, order=1479020593140, nodeOrder=21],
dhtTxId=null,
[23:12:25,910][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
dhtTxId=null,
[23:12:25,910][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744861, order=1479020603211, nodeOrder=21],
dhtTxId=null,
[23:12:25,911][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:26,052][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,067][WARN ][sys-#184%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745824, order=1479020608940, nodeOrder=21],
dhtTxId=null,
[23:12:26,607][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=2ca811d9, name=null, uptime=01:55:00:363]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=8.87%, avg=14.41%, GC=0%]
^-- Heap [used=3522MB, free=57%, comm=8192MB]
^-- Non heap [used=48MB, free=61.9%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:24,288][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=a5a404d1, name=null, uptime=01:54:58:134]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=18.17%, avg=21.47%, GC=0.97%]
^-- Heap [used=3821MB, free=53.35%, comm=8192MB]
^-- Non heap [used=48MB, free=61.84%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=5]
[23:12:25,251][WARN ][sys-#161%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744743, order=1479020601226, nodeOrder=24],
dhtTxId=null,
[23:12:25,307][WARN ][sys-#154%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,770][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
dhtTxId=null,
[23:12:25,780][WARN ][sys-#148%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,824][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744631, order=1479020599199, nodeOrder=21],
dhtTxId=null,
[23:12:25,907][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744739, order=1479020601057, nodeOrder=23],
dhtTxId=null,
[23:12:26,079][WARN ][sys-#169%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745299, order=1479020606786, nodeOrder=21],
dhtTxId=null,
[23:12:26,088][WARN ][sys-#182%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744937, order=1479020604334, nodeOrder=23],
dhtTxId=null,
[23:12:27,133][WARN ][tcp-comm-worker-#1%null%][TcpDiscoverySpi] Failed to ping
node (status check will be initiated): 5fec5215-bbcb-48b3-bcdf-480243950218
[23:12:29,291][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=a5a404d1, name=null, uptime=01:55:03:134]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=10.27%, avg=21.47%, GC=0%]
^-- Heap [used=3957MB, free=51.69%, comm=8192MB]
^-- Non heap [used=48MB, free=61.84%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:29,816][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:29,817][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:29,878][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
localhost/127.0.0
[23:12:29,878][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:30,332][WARN ][sys-#181%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744775, order=1479020601955, nodeOrder=23],
dhtTxId=null,
[23:12:30,344][WARN ][sys-#181%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745236, order=1479020606164, nodeOrder=21],
dhtTxId=null,
[23:12:34,296][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=a5a404d1, name=null, uptime=01:55:08:143]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=15.1%, avg=21.46%, GC=0.87%]
^-- Heap [used=3637MB, free=55.6%, comm=8192MB]
^-- Non heap [used=48MB, free=61.83%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:22,546][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=cccd6656, name=null, uptime=01:54:56:334]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=13.33%, avg=14.28%, GC=1.1%]
^-- Heap [used=3649MB, free=55.44%, comm=8192MB]
^-- Non heap [used=48MB, free=62.12%, comm=51MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=12]
[23:12:25,395][WARN ][sys-#163%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744387, order=1479020593606, nodeOrder=25],
dhtTxId=null,
[23:12:25,402][WARN ][sys-#161%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,404][WARN ][sys-#160%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744177, order=1479020591329, nodeOrder=22],
dhtTxId=null,
[23:12:25,570][WARN ][sys-#190%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,736][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744637, order=1479020599301, nodeOrder=22],
dhtTxId=null,
[23:12:25,765][WARN ][sys-#169%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
dhtTxId=null,
[23:12:25,878][WARN ][sys-#157%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:25,992][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744770, order=1479020601853, nodeOrder=23],
dhtTxId=null,
[23:12:26,028][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,067][WARN ][sys-#157%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608335, nodeOrder=25],
dhtTxId=null,
[23:12:27,060][WARN ][tcp-comm-worker-#1%null%][TcpDiscoverySpi] Failed to ping
node (status check will be initiated): 5fec5215-bbcb-48b3-bcdf-480243950218
[23:12:27,550][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=cccd6656, name=null, uptime=01:55:01:338]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=12.47%, avg=14.28%, GC=0.33%]
^-- Heap [used=3562MB, free=56.51%, comm=8192MB]
^-- Non heap [used=48MB, free=62.12%, comm=51MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:29,903][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:29,904][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:29,918][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
localhost/127.0.0
[23:12:29,918][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:32,557][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=cccd6656, name=null, uptime=01:55:06:346]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=1.33%, avg=14.28%, GC=0%]
^-- Heap [used=3786MB, free=53.77%, comm=8192MB]
^-- Non heap [used=48MB, free=62.1%, comm=51MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
was:
Load configuration
- Benchmark: CacheRandomOperation
- Operations: put, put_all, get, get_all, invoke, invoke_all, remove,
remove_all, put_if_absent, replace, scan_query, sql_query, continuous_query
- Heap: 8Gb for servers, 4Gb for clients
- 5 clients, 20 servers
- Number of caches: 12
- Types of caches (atomicity mode): different (atomic, transactional)
- Types of caches (tiered storage mode): different (onheap without eviction,
onheap with eviction, offheap_tired, offheap_values)
- Types of caches (indexing): different (with and without indexes)
- Types of caches (cache mode): different (partitioned, replicated)
- Backups count: 1
- Failover: 1 server are being restarted every 15 minutes
- Duration: 12h
- TLSv1.2 enabled
After one of the servers was restarted (killed and started again) on purpose
another one failed unexpectedly with the following errors:
{noformat}
[23:12:24,599][ERROR][tcp-disco-sock-reader-#72%null%][TcpDiscoverySpi] Failed
to initialize connection (this can happen due to short time network problems
and can be ignored if does not affect node discovery)
[sock=20a09999[SSL_NULL_WIT
H_NULL_NULL: Socket[addr=/172.25.1.35,port=34762,localport=47500]]]
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
at sun.security.ssl.InputRecord.read(InputRecord.java:480)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
at
sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1332)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:889)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at
org.apache.ignite.spi.discovery.tcp.ServerImpl$SocketReader.body(ServerImpl.java:5260)
at org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
[23:12:25,340][WARN ][grid-nio-worker-1-#10%null%][TcpCommunicationSpi] Failed
to process selector key (will close): GridSelectorNioSessionImpl
[selectorIdx=1, queueSize=5, writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32530
cap=32768], r
eadBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
recovery=GridNioRecoveryDescriptor [acked=1508080, resendCnt=0, rcvCnt=1812199,
sentCnt=1508107, reserved=true, lastAck=1812192, nodeLeft=false,
node=TcpDiscoveryNode [id=2f7d3
673-2ca6-4d68-8b73-0c6a209df16f, addrs=[127.0.0.1, 172.25.1.36],
sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500], discPort=47500, order=7,
intOrder=7, lastExchangeTime=1478801828352, loc=false,
ver=1.8.0#20161110-sha1:baa75266, isClient
=false], connected=true, connectCnt=1, queueLimit=5120, reserveCnt=1],
super=GridNioSessionImpl [locAddr=/172.25.1.31:39392,
rmtAddr=/172.25.1.36:47100, createTime=1478801829611, closeTime=0,
bytesSent=2559699127, bytesRcvd=2820406363, s
ndSchedTime=1478808745318, lastSndTime=1478808745334,
lastRcvTime=1478808745334, readsPaused=false,
filterChain=FilterChain[filters=[GridNioCodecFilter
[parser=o.a.i.i.util.nio.GridDirectParser@61d3d493, directMode=true],
GridConnectionB
ytesVerifyFilter, SSL filter], accepted=false]]
[23:12:25,341][WARN ][grid-nio-worker-1-#10%null%][TcpCommunicationSpi] Closing
NIO session because of unhandled exception [cls=class
o.a.i.i.util.nio.GridNioException, msg=Connection reset by peer]
[23:12:26,331][WARN ][tcp-disco-msg-worker-#2%null%][TcpDiscoverySpi] Node is
out of topology (probably, due to short-time network problems).
[23:12:26,332][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Local
node SEGMENTED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[/127.0.0.1:47500,
testagent01.gridgain.
local/172.25.1.31:47500], discPort=47500, order=1, intOrder=1,
lastExchangeTime=1478808746325, loc=true, ver=1.8.0#20161110-sha1:baa75266,
isClient=false]
[23:12:26,393][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
Stopping local node according to configured segmentation policy.
[23:12:26,393][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=6413da0d-fa60-42d1-8f44-dcbd88055cc6,
addrs=[127.0.0.1, 172.25.1.32], sockAddrs=[172.25.1.32/172.25.1.32:47500,
/127.0.0.1:47500]
, discPort=47500, order=2, intOrder=2, lastExchangeTime=1478801825834,
loc=false, ver=1.8.0#20161110-sha1:baa75266, isClient=false]
[23:12:26,394][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=18, clients=5, CPUs=128, heap=160.0GB]
[23:12:26,396][INFO ][Thread-4][GridTcpRestProtocol] Command protocol
successfully stopped: TCP binary
[23:12:26,405][ERROR][sys-#188%null%][GridDhtAtomicCache]
<atomic-offheap-values> Failed to send deferred DHT update response to remote
node [futIds=[GridCacheVersion [topVer=90281865, time=1478808744658,
order=1479020599817, nodeOrder=7
], GridCacheVersion [topVer=90281865, time=1478808744672, order=1479020600087,
nodeOrder=7], GridCacheVersion [topVer=90281865, time=1478808744687,
order=1479020600359, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744759,
order=1479020601713, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744761, order=1479020601746, nodeOrder=7], GridCacheVersion
[topVer=90281865, time=1478808744787, order=1479020602023, nodeOrder=7],
GridCacheVersion [top
Ver=90281865, time=1478808744797, order=1479020602260, nodeOrder=7],
GridCacheVersion [topVer=90281865, time=1478808744911, order=1479020603563,
nodeOrder=7], GridCacheVersion [topVer=90281865, time=1478808744913,
order=1479020603600, no
deOrder=7], GridCacheVersion [topVer=90281865, time=1478808744919,
order=1479020603734, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744923, order=1479020604206, nodeOrder=7], GridCacheVersion
[topVer=90281865, time=14788
08744925, order=1479020604312, nodeOrder=7], GridCacheVersion [topVer=90281865,
time=1478808744926, order=1479020604352, nodeOrder=7], GridCacheVersion
[topVer=90281865, time=1478808745205, order=1479020604469, nodeOrder=7],
GridCacheVer
sion [topVer=90281865, time=1478808745208, order=1479020604681, nodeOrder=7]],
node=2f7d3673-2ca6-4d68-8b73-0c6a209df16f]
class org.apache.ignite.IgniteCheckedException: Failed to send message (node
may have left the grid or TCP connection cannot be established due to firewall
issues) [node=TcpDiscoveryNode [id=2f7d3673-2ca6-4d68-8b73-0c6a209df16f,
addrs=[1
27.0.0.1, 172.25.1.36], sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500],
discPort=47500, order=7, intOrder=7, lastExchangeTime=1478801828352, loc=false,
ver=1.8.0#20161110-sha1:baa75266, isClient=false], topic=TOPIC_CACHE,
msg=GridCache
Message [msgId=36713767, depInfo=null, err=null, skipPrepare=false,
cacheId=1489451830, cacheId=1489451830], policy=2]
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1153)
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1217)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:841)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:990)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$3.finish(GridDhtAtomicCache.java:255)
at
org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer.finish0(GridDeferredAckMessageSender.java:214)
at
org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer.access$000(GridDeferredAckMessageSender.java:111)
at
org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer$1.run(GridDeferredAckMessageSender.java:159)
at
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6589)
at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(GridClosureProcessor.java:764)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: class org.apache.ignite.spi.IgniteSpiException: Failed to send
message to remote node: TcpDiscoveryNode
[id=2f7d3673-2ca6-4d68-8b73-0c6a209df16f, addrs=[127.0.0.1, 172.25.1.36],
sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500], discPort=47500, order=7,
intOrder=7, lastExchangeTime=1478801828352, loc=false,
ver=1.8.0#20161110-sha1:baa75266, isClient=false]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2017)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1955)
at
org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1148)
... 13 more
Caused by: 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=2f7d3673-2ca6-4d68-8b73-0c6a209df16f,
addrs=[/172.25.1.36:47100, /127.0.0.1:47100]]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2521)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2161)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2055)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1989)
... 15 more
Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to
connect to address: /172.25.1.36:47100
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2526)
... 18 more
Caused by: class org.apache.ignite.IgniteCheckedException: Failed to
read remote node recovery handshake (connection closed).
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeHandshake(TcpCommunicationSpi.java:2709)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2398)
... 18 more
Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to
connect to address: /127.0.0.1:47100
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2526)
... 18 more
Caused by: class org.apache.ignite.IgniteCheckedException: Remote node
ID is not as expected [expected=2f7d3673-2ca6-4d68-8b73-0c6a209df16f,
rcvd=5fec5215-bbcb-48b3-bcdf-480243950218]
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeHandshake(TcpCommunicationSpi.java:2638)
at
org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2398)
... 18 more
[23:12:26,406][WARN ][sys-#180%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745219, order=1479020605899, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,406][WARN ][sys-#169%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745218, order=1479020605897, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,406][WARN ][sys-#161%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745209, order=1479020605896, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,406][WARN ][sys-#188%null%][atomic] Skip near update request, node
originated update request left [futId=GridCacheVersion [topVer=90281865,
time=1478808745231, order=1479020606225, nodeOrder=25],
node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
[23:12:26,409][ERROR][sys-#188%null%][GridCacheIoManager] Failed processing
message [senderId=a5a404d1-d9e8-4a5f-9ab3-cecaa6acde5f,
msg=GridDhtAtomicUpdateRequest [nodeId=null, futVer=GridCacheVersion
[topVer=90281865, time=1478808745326, order=1479020607019, nodeOrder=12],
writeVer=GridCacheVersion [topVer=90281865, time=1478808745326,
order=1479020607018, nodeOrder=12], topVer=AffinityTopologyVersion [topVer=40,
minorTopVer=0], keys=[KeyCacheObjectImpl [val=253965, hasValBytes=true]],
vals=[null], prevVals=null, ttls=null, conflictExpireTimes=null, nearTtls=null,
nearExpireTimes=null, syncMode=PRIMARY_SYNC, nearKeys=null, nearVals=null,
forceTransformBackups=false, subjId=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421,
taskNameHash=0, updateCntrs=GridLongList [idx=1, arr=[11573]], onRes=false,
keepBinary=false, flags=0, super=GridCacheMessage [msgId=37427737,
depInfo=null, err=null, skipPrepare=false, cacheId=-770341200,
cacheId=-770341200]]]
java.lang.IllegalStateException: Failed to remove from index (grid is stopping).
at
org.apache.ignite.internal.processors.query.GridQueryProcessor.remove(GridQueryProcessor.java:1017)
at
org.apache.ignite.internal.processors.cache.query.GridCacheQueryManager.remove(GridCacheQueryManager.java:411)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearIndex(GridCacheMapEntry.java:4042)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.innerUpdate(GridCacheMapEntry.java:2522)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateRequest(GridDhtAtomicCache.java:3157)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$1800(GridDhtAtomicCache.java:125)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:369)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:364)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:758)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:363)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:287)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$000(GridCacheIoManager.java:89)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:232)
at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
at
org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
at
org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
[23:12:26,409][ERROR][sys-#169%null%][GridCacheIoManager] Failed processing
message [senderId=1fa739fb-560f-41d5-8e3b-26e69f993572,
msg=GridDhtAtomicUpdateRequest [nodeId=null, futVer=GridCacheVersion
[topVer=90281865, time=1478808745301, order=1479020606608, nodeOrder=10],
writeVer=GridCacheVersion [topVer=90281865, time=1478808745301,
order=1479020606607, nodeOrder=10], topVer=AffinityTopologyVersion [topVer=40,
minorTopVer=0], keys=[KeyCacheObjectImpl [val=461996, hasValBytes=true]],
vals=[null], prevVals=null, ttls=null, conflictExpireTimes=null, nearTtls=null,
nearExpireTimes=null, syncMode=PRIMARY_SYNC, nearKeys=null, nearVals=null,
forceTransformBackups=false, subjId=07e3d9f2-c151-4b5a-9007-65b52aa983b7,
taskNameHash=0, updateCntrs=GridLongList [idx=1, arr=[11366]], onRes=false,
keepBinary=false, flags=0, super=GridCacheMessage [msgId=39950832,
depInfo=null, err=null, skipPrepare=false, cacheId=-770341200,
cacheId=-770341200]]]
java.lang.IllegalStateException: Failed to remove from index (grid is stopping).
at
org.apache.ignite.internal.processors.query.GridQueryProcessor.remove(GridQueryProcessor.java:1017)
at
org.apache.ignite.internal.processors.cache.query.GridCacheQueryManager.remove(GridCacheQueryManager.java:411)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearIndex(GridCacheMapEntry.java:4042)
at
org.apache.ignite.internal.processors.cache.GridCacheMapEntry.innerUpdate(GridCacheMapEntry.java:2522)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateRequest(GridDhtAtomicCache.java:3157)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$1800(GridDhtAtomicCache.java:125)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:369)
at
org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:364)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:758)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:363)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:287)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$000(GridCacheIoManager.java:89)
at
org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:232)
at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
at
org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
at
org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
{noformat}
Example log of some other server at this time:
{noformat}
[23:12:20,741][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6413da0d, name=null, uptime=01:54:54:579]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=13.67%, avg=14.89%, GC=0.87%]
^-- Heap [used=3715MB, free=54.65%, comm=8192MB]
^-- Non heap [used=48MB, free=61.72%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:24,933][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:24,951][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:25,068][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
/127.0.0.1:47500]
[23:12:25,069][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:25,154][WARN ][sys-#185%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744922, order=1479020603983, nodeOrder=24],
dhtTxId=null,
[23:12:25,300][WARN ][sys-#158%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,360][WARN ][sys-#188%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744918, order=1479020603580, nodeOrder=25],
dhtTxId=null,
[23:12:25,364][WARN ][sys-#169%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744443, order=1479020595316, nodeOrder=25],
dhtTxId=null,
[23:12:25,678][WARN ][sys-#184%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,701][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744716, order=1479020600668, nodeOrder=23],
dhtTxId=null,
[23:12:25,749][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6413da0d, name=null, uptime=01:54:59:585]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=7.2%, avg=14.88%, GC=0%]
^-- Heap [used=3909MB, free=52.27%, comm=8192MB]
^-- Non heap [used=49MB, free=61.7%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:25,762][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,762][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
dhtTxId=null,
[23:12:25,768][WARN ][sys-#171%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
dhtTxId=null,
[23:12:25,877][WARN ][sys-#180%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:25,917][WARN ][sys-#191%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608336, nodeOrder=25],
dhtTxId=null,
[23:12:25,918][WARN ][sys-#155%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744921, order=1479020603934, nodeOrder=23],
dhtTxId=null,
[23:12:25,918][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744936, order=1479020603682, nodeOrder=25],
dhtTxId=null,
[23:12:26,008][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744781, order=1479020602170, nodeOrder=23],
dhtTxId=null,
[23:12:26,008][WARN ][sys-#183%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808744959, order=1479020604994, nodeOrder=23],
dhtTxId=null,
[23:12:26,028][WARN ][sys-#191%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,067][WARN ][sys-#188%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608335, nodeOrder=25],
dhtTxId=null,
[23:12:26,084][WARN ][sys-#166%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744937, order=1479020604456, nodeOrder=21],
dhtTxId=null,
[23:12:29,932][WARN ][sys-#154%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808743558, order=1479020583258, nodeOrder=21],
dhtTxId=null,
[23:12:30,122][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745236, order=1479020606164, nodeOrder=21],
dhtTxId=null,
[23:12:30,372][WARN ][sys-#167%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745868, order=1479020609299, nodeOrder=21],
dhtTxId=null,
[23:12:30,757][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6413da0d, name=null, uptime=01:55:04:593]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=0.5%, avg=14.88%, GC=0%]
^-- Heap [used=3949MB, free=51.78%, comm=8192MB]
^-- Non heap [used=49MB, free=61.68%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:24,621][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=487de04c, name=null, uptime=01:54:58:326]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=18.77%, avg=21.83%, GC=0.5%]
^-- Heap [used=3713MB, free=54.67%, comm=8192MB]
^-- Non heap [used=49MB, free=61.69%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=3]
[23:12:24,942][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:24,945][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:25,084][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
/127.0.0.1:47500]
[23:12:25,085][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:25,210][WARN ][sys-#189%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744378, order=1479020593863, nodeOrder=23],
dhtTxId=null,
[23:12:25,305][WARN ][sys-#178%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,353][WARN ][sys-#171%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808742992, order=1479020576526, nodeOrder=22],
dhtTxId=null,
[23:12:25,353][WARN ][sys-#184%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744177, order=1479020591329, nodeOrder=22],
dhtTxId=null,
[23:12:25,512][WARN ][sys-#149%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744918, order=1479020603580, nodeOrder=25],
dhtTxId=null,
[23:12:25,572][WARN ][sys-#154%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,710][WARN ][sys-#183%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744984, order=1479020605045, nodeOrder=21],
dhtTxId=null,
[23:12:25,733][WARN ][sys-#173%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744542, order=1479020597396, nodeOrder=25],
dhtTxId=null,
[23:12:25,761][WARN ][sys-#160%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744366, order=1479020593140, nodeOrder=21],
dhtTxId=null,
[23:12:25,763][WARN ][sys-#190%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,773][WARN ][sys-#186%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
dhtTxId=null,
[23:12:25,879][WARN ][sys-#166%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:25,888][WARN ][sys-#158%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744922, order=1479020603994, nodeOrder=24],
dhtTxId=null,
[23:12:25,919][WARN ][sys-#195%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608336, nodeOrder=25],
dhtTxId=null,
[23:12:26,030][WARN ][sys-#190%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,066][WARN ][sys-#161%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745824, order=1479020608940, nodeOrder=21],
dhtTxId=null,
[23:12:26,068][WARN ][sys-#173%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745299, order=1479020606786, nodeOrder=21],
dhtTxId=null,
[23:12:26,088][WARN ][sys-#155%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744937, order=1479020604334, nodeOrder=23],
dhtTxId=null,
[23:12:29,623][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=487de04c, name=null, uptime=01:55:03:327]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=10.1%, avg=21.83%, GC=0%]
^-- Heap [used=3977MB, free=51.44%, comm=8192MB]
^-- Non heap [used=49MB, free=61.68%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:21,602][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=2ca811d9, name=null, uptime=01:54:55:355]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=41.03%, avg=14.42%, GC=0.67%]
^-- Heap [used=3863MB, free=52.84%, comm=8192MB]
^-- Non heap [used=48MB, free=61.92%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:25,197][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:25,200][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:25,251][WARN ][sys-#148%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744743, order=1479020601226, nodeOrder=24],
dhtTxId=null,
[23:12:25,285][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[localhost/127.0.0.1:47500,
testagent01.gridgain.
[23:12:25,286][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:25,300][WARN ][sys-#159%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744442, order=1479020595560, nodeOrder=24],
dhtTxId=null,
[23:12:25,330][WARN ][sys-#182%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,359][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744563, order=1479020597755, nodeOrder=22],
dhtTxId=null,
[23:12:25,361][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808743289, order=1479020579258, nodeOrder=22],
dhtTxId=null,
[23:12:25,902][WARN ][sys-#192%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,902][WARN ][sys-#193%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,909][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744366, order=1479020593140, nodeOrder=21],
dhtTxId=null,
[23:12:25,910][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
dhtTxId=null,
[23:12:25,910][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744861, order=1479020603211, nodeOrder=21],
dhtTxId=null,
[23:12:25,911][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:26,052][WARN ][sys-#165%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,067][WARN ][sys-#184%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745824, order=1479020608940, nodeOrder=21],
dhtTxId=null,
[23:12:26,607][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=2ca811d9, name=null, uptime=01:55:00:363]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=8.87%, avg=14.41%, GC=0%]
^-- Heap [used=3522MB, free=57%, comm=8192MB]
^-- Non heap [used=48MB, free=61.9%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:24,288][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=a5a404d1, name=null, uptime=01:54:58:134]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=18.17%, avg=21.47%, GC=0.97%]
^-- Heap [used=3821MB, free=53.35%, comm=8192MB]
^-- Non heap [used=48MB, free=61.84%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=5]
[23:12:25,251][WARN ][sys-#161%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744743, order=1479020601226, nodeOrder=24],
dhtTxId=null,
[23:12:25,307][WARN ][sys-#154%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,770][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
dhtTxId=null,
[23:12:25,780][WARN ][sys-#148%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
dhtTxId=null,
[23:12:25,824][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744631, order=1479020599199, nodeOrder=21],
dhtTxId=null,
[23:12:25,907][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744739, order=1479020601057, nodeOrder=23],
dhtTxId=null,
[23:12:26,079][WARN ][sys-#169%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745299, order=1479020606786, nodeOrder=21],
dhtTxId=null,
[23:12:26,088][WARN ][sys-#182%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744937, order=1479020604334, nodeOrder=23],
dhtTxId=null,
[23:12:27,133][WARN ][tcp-comm-worker-#1%null%][TcpDiscoverySpi] Failed to ping
node (status check will be initiated): 5fec5215-bbcb-48b3-bcdf-480243950218
[23:12:29,291][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=a5a404d1, name=null, uptime=01:55:03:134]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=10.27%, avg=21.47%, GC=0%]
^-- Heap [used=3957MB, free=51.69%, comm=8192MB]
^-- Non heap [used=48MB, free=61.84%, comm=52MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:29,816][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:29,817][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:29,878][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
localhost/127.0.0
[23:12:29,878][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:30,332][WARN ][sys-#181%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744775, order=1479020601955, nodeOrder=23],
dhtTxId=null,
[23:12:30,344][WARN ][sys-#181%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281866, time=1478808745236, order=1479020606164, nodeOrder=21],
dhtTxId=null,
[23:12:34,296][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=a5a404d1, name=null, uptime=01:55:08:143]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=15.1%, avg=21.46%, GC=0.87%]
^-- Heap [used=3637MB, free=55.6%, comm=8192MB]
^-- Non heap [used=48MB, free=61.83%, comm=52MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
{noformat}
[23:12:22,546][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=cccd6656, name=null, uptime=01:54:56:334]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=13.33%, avg=14.28%, GC=1.1%]
^-- Heap [used=3649MB, free=55.44%, comm=8192MB]
^-- Non heap [used=48MB, free=62.12%, comm=51MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=12]
[23:12:25,395][WARN ][sys-#163%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744387, order=1479020593606, nodeOrder=25],
dhtTxId=null,
[23:12:25,402][WARN ][sys-#161%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
dhtTxId=null,
[23:12:25,404][WARN ][sys-#160%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744177, order=1479020591329, nodeOrder=22],
dhtTxId=null,
[23:12:25,570][WARN ][sys-#190%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
dhtTxId=null,
[23:12:25,736][WARN ][sys-#187%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744637, order=1479020599301, nodeOrder=22],
dhtTxId=null,
[23:12:25,765][WARN ][sys-#169%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
dhtTxId=null,
[23:12:25,878][WARN ][sys-#157%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
dhtTxId=null,
[23:12:25,992][WARN ][sys-#176%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281865, time=1478808744770, order=1479020601853, nodeOrder=23],
dhtTxId=null,
[23:12:26,028][WARN ][sys-#170%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
dhtTxId=null,
[23:12:26,067][WARN ][sys-#157%null%][finish] Received finish request for
completed transaction (the message may be too late) [txId=GridCacheVersion
[topVer=90281867, time=1478808745605, order=1479020608335, nodeOrder=25],
dhtTxId=null,
[23:12:27,060][WARN ][tcp-comm-worker-#1%null%][TcpDiscoverySpi] Failed to ping
node (status check will be initiated): 5fec5215-bbcb-48b3-bcdf-480243950218
[23:12:27,550][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=cccd6656, name=null, uptime=01:55:01:338]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=12.47%, avg=14.28%, GC=0.33%]
^-- Heap [used=3562MB, free=56.51%, comm=8192MB]
^-- Non heap [used=48MB, free=62.12%, comm=51MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[23:12:29,903][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager] Added
new node to topology: TcpDiscoveryNode
[id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
[23:12:29,904][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
[23:12:29,918][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager] Node
FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
localhost/127.0.0
[23:12:29,918][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
[23:12:32,557][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=cccd6656, name=null, uptime=01:55:06:346]
^-- H/N/C [hosts=8, nodes=24, CPUs=128]
^-- CPU [cur=1.33%, avg=14.28%, GC=0%]
^-- Heap [used=3786MB, free=53.77%, comm=8192MB]
^-- Non heap [used=48MB, free=62.1%, comm=51MB]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
{noformat}
> One of the node fails unexpectedly during failover test with TLS enabled
> ------------------------------------------------------------------------
>
> Key: IGNITE-4213
> URL: https://issues.apache.org/jira/browse/IGNITE-4213
> Project: Ignite
> Issue Type: Bug
> Affects Versions: 1.7
> Reporter: Ksenia Rybakova
>
> Load configuration
> - Benchmark: CacheRandomOperation
> - Operations: put, put_all, get, get_all, invoke, invoke_all, remove,
> remove_all, put_if_absent, replace
> - Heap: 8Gb for servers, 4Gb for clients
> - 5 clients, 20 servers
> - Number of caches: 12
> - Types of caches (atomicity mode): different (atomic, transactional)
> - Types of caches (tiered storage mode): different (onheap without eviction,
> onheap with eviction, offheap_tired, offheap_values)
> - Types of caches (indexing): different (with and without indexes)
> - Types of caches (cache mode): different (partitioned, replicated)
> - Backups count: 1
> - Failover: 1 server are being restarted every 15 minutes
> - Duration: 12h
> - TLSv1.2 enabled
> After one of the servers was restarted (killed and started again) on purpose
> another one failed unexpectedly with the following errors:
> {noformat}
> [23:12:24,599][ERROR][tcp-disco-sock-reader-#72%null%][TcpDiscoverySpi]
> Failed to initialize connection (this can happen due to short time network
> problems and can be ignored if does not affect node discovery)
> [sock=20a09999[SSL_NULL_WIT
> H_NULL_NULL: Socket[addr=/172.25.1.35,port=34762,localport=47500]]]
> java.net.SocketTimeoutException: Read timed out
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:152)
> at java.net.SocketInputStream.read(SocketInputStream.java:122)
> at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
> at sun.security.ssl.InputRecord.read(InputRecord.java:480)
> at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
> at
> sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1332)
> at
> sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:889)
> at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
> at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
> at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
> at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
> at
> org.apache.ignite.spi.discovery.tcp.ServerImpl$SocketReader.body(ServerImpl.java:5260)
> at org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:62)
> [23:12:25,340][WARN ][grid-nio-worker-1-#10%null%][TcpCommunicationSpi]
> Failed to process selector key (will close): GridSelectorNioSessionImpl
> [selectorIdx=1, queueSize=5, writeBuf=java.nio.DirectByteBuffer[pos=0
> lim=32530 cap=32768], r
> eadBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> recovery=GridNioRecoveryDescriptor [acked=1508080, resendCnt=0,
> rcvCnt=1812199, sentCnt=1508107, reserved=true, lastAck=1812192,
> nodeLeft=false, node=TcpDiscoveryNode [id=2f7d3
> 673-2ca6-4d68-8b73-0c6a209df16f, addrs=[127.0.0.1, 172.25.1.36],
> sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500], discPort=47500, order=7,
> intOrder=7, lastExchangeTime=1478801828352, loc=false,
> ver=1.8.0#20161110-sha1:baa75266, isClient
> =false], connected=true, connectCnt=1, queueLimit=5120, reserveCnt=1],
> super=GridNioSessionImpl [locAddr=/172.25.1.31:39392,
> rmtAddr=/172.25.1.36:47100, createTime=1478801829611, closeTime=0,
> bytesSent=2559699127, bytesRcvd=2820406363, s
> ndSchedTime=1478808745318, lastSndTime=1478808745334,
> lastRcvTime=1478808745334, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=o.a.i.i.util.nio.GridDirectParser@61d3d493, directMode=true],
> GridConnectionB
> ytesVerifyFilter, SSL filter], accepted=false]]
> [23:12:25,341][WARN ][grid-nio-worker-1-#10%null%][TcpCommunicationSpi]
> Closing NIO session because of unhandled exception [cls=class
> o.a.i.i.util.nio.GridNioException, msg=Connection reset by peer]
> [23:12:26,331][WARN ][tcp-disco-msg-worker-#2%null%][TcpDiscoverySpi] Node is
> out of topology (probably, due to short-time network problems).
> [23:12:26,332][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Local node SEGMENTED: TcpDiscoveryNode
> [id=5fec5215-bbcb-48b3-bcdf-480243950218, addrs=[127.0.0.1, 172.25.1.31],
> sockAddrs=[/127.0.0.1:47500, testagent01.gridgain.
> local/172.25.1.31:47500], discPort=47500, order=1, intOrder=1,
> lastExchangeTime=1478808746325, loc=true, ver=1.8.0#20161110-sha1:baa75266,
> isClient=false]
> [23:12:26,393][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Stopping local node according to configured segmentation policy.
> [23:12:26,393][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Node FAILED: TcpDiscoveryNode [id=6413da0d-fa60-42d1-8f44-dcbd88055cc6,
> addrs=[127.0.0.1, 172.25.1.32], sockAddrs=[172.25.1.32/172.25.1.32:47500,
> /127.0.0.1:47500]
> , discPort=47500, order=2, intOrder=2, lastExchangeTime=1478801825834,
> loc=false, ver=1.8.0#20161110-sha1:baa75266, isClient=false]
> [23:12:26,394][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=41, servers=18, clients=5, CPUs=128, heap=160.0GB]
> [23:12:26,396][INFO ][Thread-4][GridTcpRestProtocol] Command protocol
> successfully stopped: TCP binary
> [23:12:26,405][ERROR][sys-#188%null%][GridDhtAtomicCache]
> <atomic-offheap-values> Failed to send deferred DHT update response to remote
> node [futIds=[GridCacheVersion [topVer=90281865, time=1478808744658,
> order=1479020599817, nodeOrder=7
> ], GridCacheVersion [topVer=90281865, time=1478808744672,
> order=1479020600087, nodeOrder=7], GridCacheVersion [topVer=90281865,
> time=1478808744687, order=1479020600359, nodeOrder=7], GridCacheVersion
> [topVer=90281865, time=1478808744759,
> order=1479020601713, nodeOrder=7], GridCacheVersion [topVer=90281865,
> time=1478808744761, order=1479020601746, nodeOrder=7], GridCacheVersion
> [topVer=90281865, time=1478808744787, order=1479020602023, nodeOrder=7],
> GridCacheVersion [top
> Ver=90281865, time=1478808744797, order=1479020602260, nodeOrder=7],
> GridCacheVersion [topVer=90281865, time=1478808744911, order=1479020603563,
> nodeOrder=7], GridCacheVersion [topVer=90281865, time=1478808744913,
> order=1479020603600, no
> deOrder=7], GridCacheVersion [topVer=90281865, time=1478808744919,
> order=1479020603734, nodeOrder=7], GridCacheVersion [topVer=90281865,
> time=1478808744923, order=1479020604206, nodeOrder=7], GridCacheVersion
> [topVer=90281865, time=14788
> 08744925, order=1479020604312, nodeOrder=7], GridCacheVersion
> [topVer=90281865, time=1478808744926, order=1479020604352, nodeOrder=7],
> GridCacheVersion [topVer=90281865, time=1478808745205, order=1479020604469,
> nodeOrder=7], GridCacheVer
> sion [topVer=90281865, time=1478808745208, order=1479020604681,
> nodeOrder=7]], node=2f7d3673-2ca6-4d68-8b73-0c6a209df16f]
> class org.apache.ignite.IgniteCheckedException: Failed to send message (node
> may have left the grid or TCP connection cannot be established due to
> firewall issues) [node=TcpDiscoveryNode
> [id=2f7d3673-2ca6-4d68-8b73-0c6a209df16f, addrs=[1
> 27.0.0.1, 172.25.1.36], sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500],
> discPort=47500, order=7, intOrder=7, lastExchangeTime=1478801828352,
> loc=false, ver=1.8.0#20161110-sha1:baa75266, isClient=false],
> topic=TOPIC_CACHE, msg=GridCache
> Message [msgId=36713767, depInfo=null, err=null, skipPrepare=false,
> cacheId=1489451830, cacheId=1489451830], policy=2]
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1153)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1217)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:841)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:990)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$3.finish(GridDhtAtomicCache.java:255)
> at
> org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer.finish0(GridDeferredAckMessageSender.java:214)
> at
> org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer.access$000(GridDeferredAckMessageSender.java:111)
> at
> org.apache.ignite.internal.processors.cache.GridDeferredAckMessageSender$DeferredAckMessageBuffer$1.run(GridDeferredAckMessageSender.java:159)
> at
> org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6589)
> at
> org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(GridClosureProcessor.java:764)
> at
> org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: class org.apache.ignite.spi.IgniteSpiException: Failed to send
> message to remote node: TcpDiscoveryNode
> [id=2f7d3673-2ca6-4d68-8b73-0c6a209df16f, addrs=[127.0.0.1, 172.25.1.36],
> sockAddrs=[/127.0.0.1:47500, /172.25.1.36:47500], discPort=47500, order=7,
> intOrder=7, lastExchangeTime=1478801828352, loc=false,
> ver=1.8.0#20161110-sha1:baa75266, isClient=false]
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:2017)
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1955)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:1148)
> ... 13 more
> Caused by: 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=2f7d3673-2ca6-4d68-8b73-0c6a209df16f, addrs=[/172.25.1.36:47100,
> /127.0.0.1:47100]]
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2521)
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createNioClient(TcpCommunicationSpi.java:2161)
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.reserveClient(TcpCommunicationSpi.java:2055)
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1989)
> ... 15 more
> Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to
> connect to address: /172.25.1.36:47100
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2526)
> ... 18 more
> Caused by: class org.apache.ignite.IgniteCheckedException: Failed to
> read remote node recovery handshake (connection closed).
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeHandshake(TcpCommunicationSpi.java:2709)
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2398)
> ... 18 more
> Suppressed: class org.apache.ignite.IgniteCheckedException: Failed to
> connect to address: /127.0.0.1:47100
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2526)
> ... 18 more
> Caused by: class org.apache.ignite.IgniteCheckedException: Remote
> node ID is not as expected [expected=2f7d3673-2ca6-4d68-8b73-0c6a209df16f,
> rcvd=5fec5215-bbcb-48b3-bcdf-480243950218]
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.safeHandshake(TcpCommunicationSpi.java:2638)
> at
> org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:2398)
> ... 18 more
> [23:12:26,406][WARN ][sys-#180%null%][atomic] Skip near update request, node
> originated update request left [futId=GridCacheVersion [topVer=90281865,
> time=1478808745219, order=1479020605899, nodeOrder=25],
> node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
> [23:12:26,406][WARN ][sys-#169%null%][atomic] Skip near update request, node
> originated update request left [futId=GridCacheVersion [topVer=90281865,
> time=1478808745218, order=1479020605897, nodeOrder=25],
> node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
> [23:12:26,406][WARN ][sys-#161%null%][atomic] Skip near update request, node
> originated update request left [futId=GridCacheVersion [topVer=90281865,
> time=1478808745209, order=1479020605896, nodeOrder=25],
> node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
> [23:12:26,406][WARN ][sys-#188%null%][atomic] Skip near update request, node
> originated update request left [futId=GridCacheVersion [topVer=90281865,
> time=1478808745231, order=1479020606225, nodeOrder=25],
> node=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421]
> [23:12:26,409][ERROR][sys-#188%null%][GridCacheIoManager] Failed processing
> message [senderId=a5a404d1-d9e8-4a5f-9ab3-cecaa6acde5f,
> msg=GridDhtAtomicUpdateRequest [nodeId=null, futVer=GridCacheVersion
> [topVer=90281865, time=1478808745326, order=1479020607019, nodeOrder=12],
> writeVer=GridCacheVersion [topVer=90281865, time=1478808745326,
> order=1479020607018, nodeOrder=12], topVer=AffinityTopologyVersion
> [topVer=40, minorTopVer=0], keys=[KeyCacheObjectImpl [val=253965,
> hasValBytes=true]], vals=[null], prevVals=null, ttls=null,
> conflictExpireTimes=null, nearTtls=null, nearExpireTimes=null,
> syncMode=PRIMARY_SYNC, nearKeys=null, nearVals=null,
> forceTransformBackups=false, subjId=a028c2c3-7eb5-4cfa-88e5-6f2e1fcce421,
> taskNameHash=0, updateCntrs=GridLongList [idx=1, arr=[11573]], onRes=false,
> keepBinary=false, flags=0, super=GridCacheMessage [msgId=37427737,
> depInfo=null, err=null, skipPrepare=false, cacheId=-770341200,
> cacheId=-770341200]]]
> java.lang.IllegalStateException: Failed to remove from index (grid is
> stopping).
> at
> org.apache.ignite.internal.processors.query.GridQueryProcessor.remove(GridQueryProcessor.java:1017)
> at
> org.apache.ignite.internal.processors.cache.query.GridCacheQueryManager.remove(GridCacheQueryManager.java:411)
> at
> org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearIndex(GridCacheMapEntry.java:4042)
> at
> org.apache.ignite.internal.processors.cache.GridCacheMapEntry.innerUpdate(GridCacheMapEntry.java:2522)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateRequest(GridDhtAtomicCache.java:3157)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$1800(GridDhtAtomicCache.java:125)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:369)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:364)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:758)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:363)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:287)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$000(GridCacheIoManager.java:89)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:232)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> [23:12:26,409][ERROR][sys-#169%null%][GridCacheIoManager] Failed processing
> message [senderId=1fa739fb-560f-41d5-8e3b-26e69f993572,
> msg=GridDhtAtomicUpdateRequest [nodeId=null, futVer=GridCacheVersion
> [topVer=90281865, time=1478808745301, order=1479020606608, nodeOrder=10],
> writeVer=GridCacheVersion [topVer=90281865, time=1478808745301,
> order=1479020606607, nodeOrder=10], topVer=AffinityTopologyVersion
> [topVer=40, minorTopVer=0], keys=[KeyCacheObjectImpl [val=461996,
> hasValBytes=true]], vals=[null], prevVals=null, ttls=null,
> conflictExpireTimes=null, nearTtls=null, nearExpireTimes=null,
> syncMode=PRIMARY_SYNC, nearKeys=null, nearVals=null,
> forceTransformBackups=false, subjId=07e3d9f2-c151-4b5a-9007-65b52aa983b7,
> taskNameHash=0, updateCntrs=GridLongList [idx=1, arr=[11366]], onRes=false,
> keepBinary=false, flags=0, super=GridCacheMessage [msgId=39950832,
> depInfo=null, err=null, skipPrepare=false, cacheId=-770341200,
> cacheId=-770341200]]]
> java.lang.IllegalStateException: Failed to remove from index (grid is
> stopping).
> at
> org.apache.ignite.internal.processors.query.GridQueryProcessor.remove(GridQueryProcessor.java:1017)
> at
> org.apache.ignite.internal.processors.cache.query.GridCacheQueryManager.remove(GridCacheQueryManager.java:411)
> at
> org.apache.ignite.internal.processors.cache.GridCacheMapEntry.clearIndex(GridCacheMapEntry.java:4042)
> at
> org.apache.ignite.internal.processors.cache.GridCacheMapEntry.innerUpdate(GridCacheMapEntry.java:2522)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateRequest(GridDhtAtomicCache.java:3157)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$1800(GridDhtAtomicCache.java:125)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:369)
> at
> org.apache.ignite.internal.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:364)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:758)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:363)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:287)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$000(GridCacheIoManager.java:89)
> at
> org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:232)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
> at
> org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> Example log of some other server at this time:
> {noformat}
> [23:12:20,741][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=6413da0d, name=null, uptime=01:54:54:579]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=13.67%, avg=14.89%, GC=0.87%]
> ^-- Heap [used=3715MB, free=54.65%, comm=8192MB]
> ^-- Non heap [used=48MB, free=61.72%, comm=52MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> [23:12:24,933][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Added new node to topology: TcpDiscoveryNode
> [id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
> sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
> [23:12:24,951][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
> [23:12:25,068][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Node FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
> addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
> /127.0.0.1:47500]
> [23:12:25,069][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
> [23:12:25,154][WARN ][sys-#185%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744922, order=1479020603983, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,300][WARN ][sys-#158%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,360][WARN ][sys-#188%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744918, order=1479020603580, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,364][WARN ][sys-#169%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744443, order=1479020595316, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,678][WARN ][sys-#184%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,701][WARN ][sys-#176%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744716, order=1479020600668, nodeOrder=23],
> dhtTxId=null,
> [23:12:25,749][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=6413da0d, name=null, uptime=01:54:59:585]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=7.2%, avg=14.88%, GC=0%]
> ^-- Heap [used=3909MB, free=52.27%, comm=8192MB]
> ^-- Non heap [used=49MB, free=61.7%, comm=52MB]
> ^-- Public thread pool [active=0, idle=2, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> [23:12:25,762][WARN ][sys-#176%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,762][WARN ][sys-#176%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,768][WARN ][sys-#171%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,877][WARN ][sys-#180%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,917][WARN ][sys-#191%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745605, order=1479020608336, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,918][WARN ][sys-#155%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744921, order=1479020603934, nodeOrder=23],
> dhtTxId=null,
> [23:12:25,918][WARN ][sys-#187%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744936, order=1479020603682, nodeOrder=25],
> dhtTxId=null,
> [23:12:26,008][WARN ][sys-#187%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744781, order=1479020602170, nodeOrder=23],
> dhtTxId=null,
> [23:12:26,008][WARN ][sys-#183%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281866, time=1478808744959, order=1479020604994, nodeOrder=23],
> dhtTxId=null,
> [23:12:26,028][WARN ][sys-#191%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,067][WARN ][sys-#188%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745605, order=1479020608335, nodeOrder=25],
> dhtTxId=null,
> [23:12:26,084][WARN ][sys-#166%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744937, order=1479020604456, nodeOrder=21],
> dhtTxId=null,
> [23:12:29,932][WARN ][sys-#154%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808743558, order=1479020583258, nodeOrder=21],
> dhtTxId=null,
> [23:12:30,122][WARN ][sys-#187%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281866, time=1478808745236, order=1479020606164, nodeOrder=21],
> dhtTxId=null,
> [23:12:30,372][WARN ][sys-#167%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745868, order=1479020609299, nodeOrder=21],
> dhtTxId=null,
> [23:12:30,757][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=6413da0d, name=null, uptime=01:55:04:593]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=0.5%, avg=14.88%, GC=0%]
> ^-- Heap [used=3949MB, free=51.78%, comm=8192MB]
> ^-- Non heap [used=49MB, free=61.68%, comm=52MB]
> ^-- Public thread pool [active=0, idle=2, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> {noformat}
> {noformat}
> [23:12:24,621][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=487de04c, name=null, uptime=01:54:58:326]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=18.77%, avg=21.83%, GC=0.5%]
> ^-- Heap [used=3713MB, free=54.67%, comm=8192MB]
> ^-- Non heap [used=49MB, free=61.69%, comm=52MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=3]
> [23:12:24,942][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Added new node to topology: TcpDiscoveryNode
> [id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
> sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
> [23:12:24,945][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
> [23:12:25,084][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Node FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
> addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
> /127.0.0.1:47500]
> [23:12:25,085][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
> [23:12:25,210][WARN ][sys-#189%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744378, order=1479020593863, nodeOrder=23],
> dhtTxId=null,
> [23:12:25,305][WARN ][sys-#178%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,353][WARN ][sys-#171%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808742992, order=1479020576526, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,353][WARN ][sys-#184%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744177, order=1479020591329, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,512][WARN ][sys-#149%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744918, order=1479020603580, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,572][WARN ][sys-#154%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,710][WARN ][sys-#183%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744984, order=1479020605045, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,733][WARN ][sys-#173%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744542, order=1479020597396, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,761][WARN ][sys-#160%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744366, order=1479020593140, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,763][WARN ][sys-#190%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,773][WARN ][sys-#186%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,879][WARN ][sys-#166%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,888][WARN ][sys-#158%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744922, order=1479020603994, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,919][WARN ][sys-#195%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745605, order=1479020608336, nodeOrder=25],
> dhtTxId=null,
> [23:12:26,030][WARN ][sys-#190%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,066][WARN ][sys-#161%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745824, order=1479020608940, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,068][WARN ][sys-#173%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745299, order=1479020606786, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,088][WARN ][sys-#155%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744937, order=1479020604334, nodeOrder=23],
> dhtTxId=null,
> [23:12:29,623][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=487de04c, name=null, uptime=01:55:03:327]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=10.1%, avg=21.83%, GC=0%]
> ^-- Heap [used=3977MB, free=51.44%, comm=8192MB]
> ^-- Non heap [used=49MB, free=61.68%, comm=52MB]
> ^-- Public thread pool [active=0, idle=2, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> {noformat}
> {noformat}
> [23:12:21,602][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=2ca811d9, name=null, uptime=01:54:55:355]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=41.03%, avg=14.42%, GC=0.67%]
> ^-- Heap [used=3863MB, free=52.84%, comm=8192MB]
> ^-- Non heap [used=48MB, free=61.92%, comm=52MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> [23:12:25,197][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Added new node to topology: TcpDiscoveryNode
> [id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
> sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
> [23:12:25,200][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
> [23:12:25,251][WARN ][sys-#148%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744743, order=1479020601226, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,285][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Node FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
> addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[localhost/127.0.0.1:47500,
> testagent01.gridgain.
> [23:12:25,286][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
> [23:12:25,300][WARN ][sys-#159%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744442, order=1479020595560, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,330][WARN ][sys-#182%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,359][WARN ][sys-#170%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744563, order=1479020597755, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,361][WARN ][sys-#170%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808743289, order=1479020579258, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,902][WARN ][sys-#192%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,902][WARN ][sys-#193%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,909][WARN ][sys-#165%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744366, order=1479020593140, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,910][WARN ][sys-#165%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,910][WARN ][sys-#165%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744861, order=1479020603211, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,911][WARN ][sys-#165%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,052][WARN ][sys-#165%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,067][WARN ][sys-#184%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745824, order=1479020608940, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,607][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=2ca811d9, name=null, uptime=01:55:00:363]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=8.87%, avg=14.41%, GC=0%]
> ^-- Heap [used=3522MB, free=57%, comm=8192MB]
> ^-- Non heap [used=48MB, free=61.9%, comm=52MB]
> ^-- Public thread pool [active=0, idle=2, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> {noformat}
> {noformat}
> [23:12:24,288][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=a5a404d1, name=null, uptime=01:54:58:134]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=18.17%, avg=21.47%, GC=0.97%]
> ^-- Heap [used=3821MB, free=53.35%, comm=8192MB]
> ^-- Non heap [used=48MB, free=61.84%, comm=52MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=5]
> [23:12:25,251][WARN ][sys-#161%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744743, order=1479020601226, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,307][WARN ][sys-#154%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,770][WARN ][sys-#170%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744742, order=1479020601124, nodeOrder=24],
> dhtTxId=null,
> [23:12:25,780][WARN ][sys-#148%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281866, time=1478808745208, order=1479020605895, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,824][WARN ][sys-#187%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744631, order=1479020599199, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,907][WARN ][sys-#187%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744739, order=1479020601057, nodeOrder=23],
> dhtTxId=null,
> [23:12:26,079][WARN ][sys-#169%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745299, order=1479020606786, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,088][WARN ][sys-#182%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744937, order=1479020604334, nodeOrder=23],
> dhtTxId=null,
> [23:12:27,133][WARN ][tcp-comm-worker-#1%null%][TcpDiscoverySpi] Failed to
> ping node (status check will be initiated):
> 5fec5215-bbcb-48b3-bcdf-480243950218
> [23:12:29,291][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=a5a404d1, name=null, uptime=01:55:03:134]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=10.27%, avg=21.47%, GC=0%]
> ^-- Heap [used=3957MB, free=51.69%, comm=8192MB]
> ^-- Non heap [used=48MB, free=61.84%, comm=52MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> [23:12:29,816][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Added new node to topology: TcpDiscoveryNode
> [id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
> sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
> [23:12:29,817][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
> [23:12:29,878][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Node FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
> addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
> localhost/127.0.0
> [23:12:29,878][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
> [23:12:30,332][WARN ][sys-#181%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744775, order=1479020601955, nodeOrder=23],
> dhtTxId=null,
> [23:12:30,344][WARN ][sys-#181%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281866, time=1478808745236, order=1479020606164, nodeOrder=21],
> dhtTxId=null,
> [23:12:34,296][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=a5a404d1, name=null, uptime=01:55:08:143]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=15.1%, avg=21.46%, GC=0.87%]
> ^-- Heap [used=3637MB, free=55.6%, comm=8192MB]
> ^-- Non heap [used=48MB, free=61.83%, comm=52MB]
> ^-- Public thread pool [active=0, idle=2, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> {noformat}
> {noformat}
> [23:12:22,546][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=cccd6656, name=null, uptime=01:54:56:334]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=13.33%, avg=14.28%, GC=1.1%]
> ^-- Heap [used=3649MB, free=55.44%, comm=8192MB]
> ^-- Non heap [used=48MB, free=62.12%, comm=51MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=12]
> [23:12:25,395][WARN ][sys-#163%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744387, order=1479020593606, nodeOrder=25],
> dhtTxId=null,
> [23:12:25,402][WARN ][sys-#161%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744930, order=1479020604353, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,404][WARN ][sys-#160%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744177, order=1479020591329, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,570][WARN ][sys-#190%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745556, order=1479020608286, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,736][WARN ][sys-#187%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744637, order=1479020599301, nodeOrder=22],
> dhtTxId=null,
> [23:12:25,765][WARN ][sys-#169%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744489, order=1479020596448, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,878][WARN ][sys-#157%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745840, order=1479020609141, nodeOrder=21],
> dhtTxId=null,
> [23:12:25,992][WARN ][sys-#176%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281865, time=1478808744770, order=1479020601853, nodeOrder=23],
> dhtTxId=null,
> [23:12:26,028][WARN ][sys-#170%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745906, order=1479020610007, nodeOrder=21],
> dhtTxId=null,
> [23:12:26,067][WARN ][sys-#157%null%][finish] Received finish request for
> completed transaction (the message may be too late) [txId=GridCacheVersion
> [topVer=90281867, time=1478808745605, order=1479020608335, nodeOrder=25],
> dhtTxId=null,
> [23:12:27,060][WARN ][tcp-comm-worker-#1%null%][TcpDiscoverySpi] Failed to
> ping node (status check will be initiated):
> 5fec5215-bbcb-48b3-bcdf-480243950218
> [23:12:27,550][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=cccd6656, name=null, uptime=01:55:01:338]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=12.47%, avg=14.28%, GC=0.33%]
> ^-- Heap [used=3562MB, free=56.51%, comm=8192MB]
> ^-- Non heap [used=48MB, free=62.12%, comm=51MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> [23:12:29,903][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Added new node to topology: TcpDiscoveryNode
> [id=83eb2036-3726-4c83-8e30-e826f6f33f43, addrs=[127.0.0.1, 172.25.1.35],
> sockAddrs=[/172.25.1.35:47500, /127.0.0.1:47
> [23:12:29,904][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=41, servers=20, clients=5, CPUs=128, heap=180.0GB]
> [23:12:29,918][WARN ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Node FAILED: TcpDiscoveryNode [id=5fec5215-bbcb-48b3-bcdf-480243950218,
> addrs=[127.0.0.1, 172.25.1.31], sockAddrs=[172.25.1.31/172.25.1.31:47500,
> localhost/127.0.0
> [23:12:29,918][INFO ][disco-event-worker-#20%null%][GridDiscoveryManager]
> Topology snapshot [ver=42, servers=19, clients=5, CPUs=128, heap=170.0GB]
> [23:12:32,557][INFO ][grid-timeout-worker-#7%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=cccd6656, name=null, uptime=01:55:06:346]
> ^-- H/N/C [hosts=8, nodes=24, CPUs=128]
> ^-- CPU [cur=1.33%, avg=14.28%, GC=0%]
> ^-- Heap [used=3786MB, free=53.77%, comm=8192MB]
> ^-- Non heap [used=48MB, free=62.1%, comm=51MB]
> ^-- Public thread pool [active=0, idle=2, qSize=0]
> ^-- System thread pool [active=0, idle=32, qSize=0]
> ^-- Outbound messages queue [size=0]
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
