Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 5C585200BBE for ; Fri, 11 Nov 2016 11:48:01 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 5B1F3160B01; Fri, 11 Nov 2016 10:48:01 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 852AA160AF5 for ; Fri, 11 Nov 2016 11:47:59 +0100 (CET) Received: (qmail 32659 invoked by uid 500); 11 Nov 2016 10:47:58 -0000 Mailing-List: contact dev-help@ignite.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@ignite.apache.org Delivered-To: mailing list dev@ignite.apache.org Received: (qmail 32625 invoked by uid 99); 11 Nov 2016 10:47:58 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 11 Nov 2016 10:47:58 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id 66D652C0276 for ; Fri, 11 Nov 2016 10:47:58 +0000 (UTC) Date: Fri, 11 Nov 2016 10:47:58 +0000 (UTC) From: "Ksenia Rybakova (JIRA)" To: dev@ignite.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Created] (IGNITE-4213) One of the node fails unexpectedly during failover test with TLS enabled MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Fri, 11 Nov 2016 10:48:01 -0000 Ksenia Rybakova created IGNITE-4213: --------------------------------------- Summary: 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, 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] 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)