You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ignite.apache.org by "Roger Fischer (CW)" <rf...@Brocade.com> on 2017/08/11 21:38:43 UTC
Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Hello,
I am wondering if the following behavior is typical, or if it represents a concern.
I have a 3 node cluster with native persistence. Each node as 4 CPU and 16 GB of RAM.
Each node has ~45 GB used in work/db. Total across the 3 nodes is about 36.5 M objects.
I am using SQL queries, and there are 3 indexes.
The servers start up normally and join the cluster, as expected.
When I start the client, which calls active(), all 3 servers report the following:
[12:41:28] Topology snapshot [ver=5, servers=3, clients=1, CPUs=16, heap=4.8GB]
[12:41:29] Default checkpoint page buffer size is too small, setting to an adjusted value: 2.0 GiB
[12:41:29] Ignite node crashed in the middle of checkpoint. Will restore memory state and enforce checkpoint on node start.
1) Should I worry about the "crashed" log?
The activation takes more than 30 minutes (until active() returns).
2) Is that normal for activate to take that long?
ver. 2.1.0#20170720-sha1:a6ca5c8a
OS: Linux 3.10.0-514.el7.x86_64 amd64
Thanks...
Roger
Re: RE: Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Posted by Alexey Kukushkin <al...@yahoo.com>.
I just saw this "Ignite node crashed in the middle of checkpoint" on my development machine with the latest Ignite 2.1.4 - it appeared when activating a single node cluster with persistence enabled but no data to preload at all. I will also look into it after I complete my current tasks.
Best regards, Alexey
On Tuesday, August 15, 2017, 3:39:57 AM GMT+3, Roger Fischer (CW) <rf...@Brocade.com> wrote:
#yiv8195883399 #yiv8195883399 -- _filtered #yiv8195883399 {panose-1:2 4 5 3 5 4 6 3 2 4;} _filtered #yiv8195883399 {font-family:Calibri;panose-1:2 15 5 2 2 2 4 3 2 4;} _filtered #yiv8195883399 {font-family:Tahoma;panose-1:2 11 6 4 3 5 4 4 2 4;}#yiv8195883399 #yiv8195883399 p.yiv8195883399MsoNormal, #yiv8195883399 li.yiv8195883399MsoNormal, #yiv8195883399 div.yiv8195883399MsoNormal {margin:0in;margin-bottom:.0001pt;font-size:12.0pt;}#yiv8195883399 a:link, #yiv8195883399 span.yiv8195883399MsoHyperlink {color:blue;text-decoration:underline;}#yiv8195883399 a:visited, #yiv8195883399 span.yiv8195883399MsoHyperlinkFollowed {color:purple;text-decoration:underline;}#yiv8195883399 span.yiv8195883399EmailStyle17 {color:#1F497D;}#yiv8195883399 .yiv8195883399MsoChpDefault {} _filtered #yiv8195883399 {margin:1.0in 1.0in 1.0in 1.0in;}#yiv8195883399 div.yiv8195883399WordSection1 {}#yiv8195883399
Hi Alex,
there were no other relevant logs than what I already listed in the first email.
<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="
http://www.springframework.org/schema/beans
http://www.springframework.org/schema/beans/spring-beans.xsd">
<bean id="grid.cfg" class="org.apache.ignite.configuration.IgniteConfiguration"> <property name="discoverySpi">
<bean class="org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi">
<property name="ipFinder">
<bean class="org.apache.ignite.spi.discovery.tcp.ipfinder.vm.TcpDiscoveryVmIpFinder">
<property name="addresses">
<list>
<value>10.24.51.190</value>
<value>10.24.51.187</value>
<value>10.24.51.150</value>
</list>
</property>
</bean>
</property>
</bean>
</property>
<property name="persistentStoreConfiguration">
<bean class="org.apache.ignite.configuration.PersistentStoreConfiguration"/>
</property>
<property name="cacheConfiguration">
<list>
<bean class="org.apache.ignite.configuration.CacheConfiguration">
<property name="name" value="FcPortStatsCache"/>
<property name="cacheMode" value="PARTITIONED"/>
<property name="backups" value="1"/>
<property name="queryEntities">
<list>
<bean class="org.apache.ignite.cache.QueryEntity">
<property name="keyType" value="com.abc.poc.inppoc.model.FcPortStatsKey"/>
<property name="valueType" value="com.abc.poc.inppoc.model.FcPortStats"/>
<property name="fields">
<map>
<entry key="dateTime" value="java.util.Date"/>
<entry key="portId" value="java.util.UUID"/>
<entry key="portType" value="java.lang.Integer"/>
<entry key="switchId" value="java.util.UUID"/>
<entry key="fabricId" value="java.util.UUID"/>
<entry key="rxUtil" value="java.lang.Float"/>
<entry key="txUtil" value="java.lang.Float"/>
<entry key="higherUtil" value="java.lang.Float"/>
<entry key="lowerUtil" value="java.lang.Float"/>
<entry key="rxRate" value="java.lang.Float"/>
<entry key="txRate" value="java.lang.Float"/>
<entry key="higherRate" value="java.lang.Float"/>
<entry key="lowerRate" value="java.lang.Float"/>
<entry key="c3Discards" value="java.lang.Float"/>
<entry key="crcErrors" value="java.lang.Float"/>
</map>
</property>
<property name="indexes">
<list>
<bean class="org.apache.ignite.cache.QueryIndex">
<constructor-arg>
<list>
<value>dateTime</value>
<value>portId</value>
</list>
</constructor-arg>
<constructor-arg value="SORTED"/>
</bean>
<bean class="org.apache.ignite.cache.QueryIndex">
<constructor-arg>
<list>
<value>portId</value>
<value>dateTime</value>
</list>
</constructor-arg>
<constructor-arg value="SORTED"/>
</bean>
<bean class="org.apache.ignite.cache.QueryIndex">
<constructor-arg>
<list>
<value>switchId</value>
<value>dateTime</value>
</list>
</constructor-arg>
<constructor-arg value="SORTED"/>
</bean>
</list>
</property>
</bean>
</list>
</property>
</bean>
</list>
</property>
</bean>
</beans>
All 3 servers (and the client) are on VMs on the same host. No network hop latency. But all 3 VMs use the same physical disk (on the host).
Servers have 16 GB of RAM. Data on disk (work/db) was about 35 GB per mode. About 36M objects.
Please also notehttp://apache-ignite-users.70518.x6.nabble.com/Strange-problems-with-Ignite-native-Persistence-when-Data-exceeds-Memory-td16187.html.
There were some odd problems at time that may have affected the activation.
Roger
From: afedotov [mailto:alexander.fedotoff@gmail.com]
Sent: Monday, August 14, 2017 11:05 AM
To: user@ignite.apache.org
Subject: Re: Activation: slow and: Ignite node crashed in the middle of checkpoint.
Hi,
Could you please share the logs and configuration?
Actually, the activation time depends on the amount of data, network connectivity and other variables.
Kind regards,
Alex.
On Sat, Aug 12, 2017 at 12:39 AM, Roger Fischer (CW) [via Apache Ignite Users] <[hidden email]> wrote:
Hello,
I am wondering if the following behavior is typical, or if it represents a concern.
I have a 3 node cluster with native persistence. Each node as 4 CPU and 16 GB of RAM.
Each node has ~45 GB used in work/db. Total across the 3 nodes is about 36.5 M objects.
I am using SQL queries, and there are 3 indexes.
The servers start up normally and join the cluster, as expected.
When I start the client, which calls active(), all 3 servers report the following:
[12:41:28] Topology snapshot [ver=5, servers=3, clients=1, CPUs=16, heap=4.8GB]
[12:41:29] Default checkpoint page buffer size is too small, setting to an adjusted value: 2.0 GiB
[12:41:29] Ignite node crashed in the middle of checkpoint. Will restore memory state and enforce checkpoint on node start.
1) Should I worry about the “crashed” log?
The activation takes more than 30 minutes (until active() returns).
2) Is that normal for activate to take that long?
ver. 2.1.0#20170720-sha1:a6ca5c8a
OS: Linux 3.10.0-514.el7.x86_64 amd64
Thanks…
Roger
If you reply to this email, your message will be added to the discussion below:
http://apache-ignite-users.70518.x6.nabble.com/Activation-slow-and-Ignite-node-crashed-in-the-middle-of-checkpoint-tp16144.html
To start a new topic under Apache Ignite Users, email[hidden email]
To unsubscribe from Apache Ignite Users, click here.
NAML
View this message in context: Re: Activation: slow and: Ignite node crashed in the middle of checkpoint.
Sent from the Apache Ignite Users mailing list archive at Nabble.com.
Re: Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Posted by dkarachentsev <dk...@gridgain.com>.
Hi,
Please share full logs and thread dumps, it's hard to understand the root
cause.
Thanks!
-Dmitry.
--
View this message in context: http://apache-ignite-users.70518.x6.nabble.com/Activation-slow-and-Ignite-node-crashed-in-the-middle-of-checkpoint-tp16144p16341.html
Sent from the Apache Ignite Users mailing list archive at Nabble.com.
Re: Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Posted by iostream <si...@gmail.com>.
Hi Roger,
I have experienced a similar issue during cluster activation in my setup as
well. I had shared my logs here -
http://apache-ignite-users.70518.x6.nabble.com/Activating-Cluster-taking-too-long-td16093.html
Eagerly seeking a root cause and resolution for this.
--
View this message in context: http://apache-ignite-users.70518.x6.nabble.com/Activation-slow-and-Ignite-node-crashed-in-the-middle-of-checkpoint-tp16144p16318.html
Sent from the Apache Ignite Users mailing list archive at Nabble.com.
Re: Activation: slow and: Ignite node crashed in the middle of checkpoint.
Posted by Nikolai Tikhonov <nt...@apache.org>.
Hi Roger,
From this logs not clear why you got this behaviour. Could you also take
thread dump from all nodes? Also would be great if you share them as
separate files.
On Wed, Aug 16, 2017 at 2:50 AM, Roger Fischer (CW) <rf...@brocade.com>
wrote:
> Hi Dmitry and Alex,
>
> the cache contains 19.2M objects. The work/db directory is 23, 26 and 22
> GB respectively. The 3 nodes have 8 GB RAM each.
>
> I initiated deactivate at 14:13:39. As of 16:50:00, deactivate has not
> completed. Only server node 2 continues to log warnings.
>
>
>
> The client shows the following logs:
>
> [14:13:39,473][INFO][main][GridClusterStateProcessor] Sending deactivate
> request from node [id=548f4233-67e9-4043-aa3a-086fb541c427,
> topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], client=true,
> daemonfalse]
> [14:13:40,369][INFO][tcp-client-disco-msg-worker-#4%null%][GridClusterStateProcessor]
> Start state transition: false
> [14:13:40,395][INFO][exchange-worker-#96%null%][time] Started exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> crd=false, evt=18, node=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0,
> /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11,
> intOrder=0, lastExchangeTime=1502830168939, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true],
> evtNode=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0,
> /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11,
> intOrder=0, lastExchangeTime=1502830168939, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], customEvt=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false]]
> [14:13:40,396][INFO][exchange-worker-#96%null%][
> GridDhtPartitionsExchangeFuture] Start deactivation process
> [nodeId=548f4233-67e9-4043-aa3a-086fb541c427, client=true,
> topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
> [14:13:40,397][INFO][exchange-worker-#96%null%][
> GridDhtPartitionsExchangeFuture] Successfully deactivated data
> structures, services and caches [nodeId=548f4233-67e9-4043-aa3a-086fb541c427,
> client=true, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
> [14:13:40,398][INFO][exchange-worker-#96%null%][
> GridDhtPartitionsExchangeFuture] Snapshot initialization completed
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], time=0ms]
> [14:13:40,398][INFO][exchange-worker-#96%null%][time] Finished exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> crd=false]
> [14:13:41,173][INFO][tcp-client-disco-msg-worker-#4%null%][GridClusterStateProcessor]
> Received state change finish message: false
> [14:13:45,355][INFO][grid-timeout-worker-#15%null%][IgniteKernal]
> Metrics for local node (to disable set 'metricsLogFrequency' to 0)
> ^-- Node [id=548f4233, name=null, uptime=00:24:07:982]
> ^-- H/N/C [hosts=3, nodes=4, CPUs=12]
> ^-- CPU [cur=0.6%, avg=0.89%, GC=0%]
> ^-- PageMemory [pages=0]
> ^-- Heap [used=248MB, free=86.36%, comm=951MB]
> ^-- Non heap [used=48MB, free=-1%, comm=49MB]
> ^-- Public thread pool [active=0, idle=0, qSize=0]
> ^-- System thread pool [active=0, idle=0, qSize=0]
> ^-- Outbound messages queue [size=0]
> [14:13:50,399][WARNING][exchange-worker-#96%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-086fb541c427].
> Dumping pending objects that might be the cause:
> [14:13:50,400][WARNING][exchange-worker-#96%null%][diagnostic] Ready
> affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
> [14:13:50,624][WARNING][exchange-worker-#96%null%][diagnostic] Last
> exchange future: GridDhtPartitionsExchangeFuture [dummy=false,
> forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent
> [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831381649, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=548f4233, msg=null, type=DISCOVERY_CUSTOM_EVT,
> tstamp=1502831620392]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=1870944589], init=true, lastVer=null, partReleaseFut=null,
> exchActions=ExchangeActions [startCaches=null,
> stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache,
> FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false,
> PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache,
> destroy=false, FabricCache, destroy=false], resetParts=null,
> stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=true,
> clientOnlyExchange=true, initTs=1502831620392, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=false, evtLatch=0,
> remaining=[6ffb9c55-4f23-4920-8134-36a649371cda, bda65979-33d1-4d6f-8a32-45b71255f835,
> 4d8c099c-b04f-48f9-a825-25eba9d794c5], super=GridFutureAdapter
> [ignoreInterrupts=false, state=INIT, res=null, hash=959636403]]
> [14:13:50,624][WARNING][exchange-worker-#96%null%][
> GridCachePartitionExchangeManager] First 10 pending exchange futures
> [total=1]
> [14:13:51,397][WARNING][exchange-worker-#96%null%][diagnostic] Last 10
> exchange futures (total: 3):
> [14:13:51,398][WARNING][exchange-worker-#96%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831381649, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
> [14:13:51,398][WARNING][exchange-worker-#96%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=0], evt=12, evtNode=TcpDiscoveryNode
> [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=10,
> intOrder=7, lastExchangeTime=1502831381649, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,399][WARNING][exchange-worker-#96%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11,
> intOrder=0, lastExchangeTime=1502830168939, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,400][WARNING][exchange-worker-#96%null%][diagnostic] Pending
> transactions:
> [14:13:51,400][WARNING][exchange-worker-#96%null%][diagnostic] Pending
> explicit locks:
> [14:13:51,403][WARNING][exchange-worker-#96%null%][diagnostic] Pending
> cache futures:
> [14:13:51,404][WARNING][exchange-worker-#96%null%][diagnostic] Pending
> atomic cache futures:
> [14:13:51,404][WARNING][exchange-worker-#96%null%][diagnostic] Pending
> data streamer futures:
> [14:13:51,404][WARNING][exchange-worker-#96%null%][diagnostic] Pending
> transaction deadlock detection futures:
> [14:13:51,779][INFO][grid-nio-worker-tcp-comm-3-#20%null%][diagnostic]
> Exchange future waiting for coordinator response
> [crd=bda65979-33d1-4d6f-8a32-45b71255f835, topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1]]
> Remote node information:
> General node info [id=bda65979-33d1-4d6f-8a32-45b71255f835, client=false,
> discoTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> time=14:13:51.525]
> Partitions exchange info [readyVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=0]]
> Last initialized exchange future: GridDhtPartitionsExchangeFuture
> [dummy=false, forcePreload=false, reassign=false,
> discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831630880, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT,
> tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443,
> order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions
> [startCaches=null, stopCaches=[ignite-sys-cache, PortCache,
> FcPortStatsCache, SwitchCache, FabricCache], startGrps=[],
> stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false,
> FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache,
> destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest
> [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT,
> res=null, hash=428221662]]
> Communication SPI statistics [rmtNode=548f4233-67e9-4043-
> aa3a-086fb541c427]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=548f4233-67e9-4043-aa3a-086fb541c427,
> idx=0, connCnt=0], msgsSent=103, msgsAckedByRmt=96, msgsRcvd=106,
> lastAcked=96, reserveCnt=1, descIdHash=2019083035]
> Communication SPI clients:
> [node=548f4233-67e9-4043-aa3a-086fb541c427, client=GridTcpNioCommunicationClient
> [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker
> [super=AbstractNioClientWorker [idx=1, bytesRcvd=569566918,
> bytesSent=3727054, bytesRcvd0=853, bytesSent0=0, select=true,
> super=GridWorker [name=grid-nio-worker-tcp-comm-1,
> igniteInstanceName=null, finished=false, hashCode=1204083040,
> interrupted=false, runner=grid-nio-worker-tcp-comm-1-#18%null%]]],
> writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor
> [acked=96, resendCnt=0, rcvCnt=106, sentCnt=103, reserved=true, lastAck=96,
> nodeLeft=false, node=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0,
> /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /
> 10.24.51.187:0], discPort=0, order=11, intOrder=8, lastExchangeTime=1502831380784,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true],
> connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1,
> pairedConnections=false], outRecovery=GridNioRecoveryDescriptor
> [acked=96, resendCnt=0, rcvCnt=106, sentCnt=103, reserved=true, lastAck=96,
> nodeLeft=false, node=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0,
> /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /
> 10.24.51.187:0], discPort=0, order=11, intOrder=8, lastExchangeTime=1502831380784,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true],
> connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100,
> rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926,
> createTime=1502831383244, closeTime=0, bytesSent=3569974, bytesRcvd=4153,
> bytesSent0=0, bytesRcvd0=853, sndSchedTime=1502831383244,
> lastSndTime=1502831546390, lastRcvTime=1502831631525, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=org.apache.ignite.internal.util.nio.GridDirectParser@33874199,
> directMode=true], GridConnectionBytesVerifyFilter], accepted=true]],
> super=GridAbstractCommunicationClient [lastUsed=1502831383244,
> closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=1, keysCnt=1, bytesRcvd=569566918, bytesRcvd0=853,
> bytesSent=3727054, bytesSent0=0]
> Connection info [in=true, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926,
> locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, msgsSent=103,
> msgsAckedByRmt=96, descIdHash=2019083035, unackedMsgs=[GridQueryNextPageResponse,
> GridQueryNextPageResponse, GridQueryNextPageResponse,
> GridQueryNextPageResponse, GridQueryNextPageResponse], msgsRcvd=106,
> lastAcked=96, descIdHash=2019083035, bytesRcvd=4153, bytesRcvd0=853,
> bytesSent=3569974, bytesSent0=0, opQueueSize=0]
> Exchange future: GridDhtPartitionsExchangeFuture [dummy=false,
> forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent
> [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831631537, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT,
> tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831631537,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443,
> order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions
> [startCaches=null, stopCaches=[ignite-sys-cache, PortCache,
> FcPortStatsCache, SwitchCache, FabricCache], startGrps=[],
> stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false,
> FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache,
> destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest
> [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT,
> res=null, hash=428221662]]
> Local communication statistics:
> Communication SPI statistics [rmtNode=bda65979-33d1-4d6f-
> 8a32-45b71255f835]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> idx=0, connCnt=-1], msgsSent=106, msgsAckedByRmt=96, msgsRcvd=104,
> lastAcked=96, reserveCnt=1, descIdHash=859262134]
> Communication SPI clients:
> [node=bda65979-33d1-4d6f-8a32-45b71255f835, client=GridTcpNioCommunicationClient
> [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker
> [super=AbstractNioClientWorker [idx=3, bytesRcvd=3579228, bytesSent=4129,
> bytesRcvd0=9282, bytesSent0=853, select=true, super=GridWorker
> [name=grid-nio-worker-tcp-comm-3, igniteInstanceName=null,
> finished=false, hashCode=969336725, interrupted=false,
> runner=grid-nio-worker-tcp-comm-3-#20%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0
> lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768
> cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=96, resendCnt=0,
> rcvCnt=104, sentCnt=106, reserved=true, lastAck=96, nodeLeft=false,
> node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=1, queueLimit=4096, reserveCnt=1,
> pairedConnections=false], outRecovery=GridNioRecoveryDescriptor
> [acked=96, resendCnt=0, rcvCnt=104, sentCnt=106, reserved=true, lastAck=96,
> nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=1, queueLimit=4096, reserveCnt=1,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926,
> rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100,
> createTime=1502831383242, closeTime=0, bytesSent=4111, bytesRcvd=3579228,
> bytesSent0=853, bytesRcvd0=9282, sndSchedTime=1502831383242,
> lastSndTime=1502831631530, lastRcvTime=1502831631541, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=org.apache.ignite.internal.util.nio.GridDirectParser@438486ef,
> directMode=true], GridConnectionBytesVerifyFilter], accepted=false]],
> super=GridAbstractCommunicationClient [lastUsed=1502831383242,
> closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=3, keysCnt=1, bytesRcvd=3579228, bytesRcvd0=9282,
> bytesSent=4129, bytesSent0=853]
> Connection info [in=false, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100,
> locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926, msgsSent=106,
> msgsAckedByRmt=96, descIdHash=859262134, unackedMsgs=[GridQueryNextPageRequest,
> GridQueryNextPageRequest, GridQueryNextPageRequest,
> GridQueryNextPageRequest, GridQueryNextPageRequest], msgsRcvd=104,
> lastAcked=96, descIdHash=859262134, bytesRcvd=3579228, bytesRcvd0=9282,
> bytesSent=4111, bytesSent0=853, opQueueSize=0]
>
> Then the logs seem to repeat starting with " Failed to wait for partition
> map exchange ...".
>
> Eventually only logs like this are repeated, seems every 10 seconds.
>
> [16:10:53,425][WARNING][exchange-worker-#96%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
> 086fb541c427]. Dumping pending objects that might be the cause:
> [16:11:03,426][WARNING][exchange-worker-#96%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
> 086fb541c427]. Dumping pending objects that might be the cause:
> [16:11:13,427][WARNING][exchange-worker-#96%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
> 086fb541c427]. Dumping pending objects that might be the cause:
> [16:11:23,428][WARNING][exchange-worker-#96%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
> 086fb541c427]. Dumping pending objects that might be the cause:
> [16:11:33,428][WARNING][exchange-worker-#96%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
> 086fb541c427]. Dumping pending objects that might be the cause:
> [16:11:43,428][WARNING][exchange-worker-#96%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
> 086fb541c427]. Dumping pending objects that might be the cause:
>
>
> Server node 1 logs:
>
> [14:13:40,170][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor]
> Start state transition: false
> [14:13:40,172][INFO][exchange-worker-#34%null%][time] Started exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> crd=true, evt=18, node=T
> cpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockA
> ddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort
> =47500, order=1, intOrder=1, lastExchangeTime=1502831618858, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> evtNode=TcpDiscoveryNode [id=bda65979-
> 33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190,
> 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9
> dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1,
> lastExchangeTime=1502831618858, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a,
> isClient=false], customEvt=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46
> f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d,
> initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false]]
> [14:13:40,172][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Start deactivation process
> [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835, client
> =false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
> [14:13:40,320][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Successfully deactivated data
> structures, services and caches [nodeId=bda65979-
> 33d1-4d6f-8a32-45b71255f835, client=false, topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1]]
> [14:13:40,344][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Finished waiting for partition release
> future [topVer=AffinityTopologyVersion [
> topVer=12, minorTopVer=1], waitTime=0ms]
> [14:13:40,345][INFO][exchange-worker-#34%null%][time] Finished exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=true]
> [14:13:40,612][INFO][grid-nio-worker-tcp-comm-3-#20%null%][TcpCommunicationSpi]
> Accepted incoming communication connection [locAddr=/2620:100:0:fe07:
> f92c:9dbd:9
> b0f:9982:47100, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956]
> [14:13:40,780][INFO][grid-nio-worker-tcp-comm-2-#19%null%][TcpCommunicationSpi]
> Accepted incoming communication connection [locAddr=/2620:100:0:fe07:
> f92c:9dbd:9
> b0f:9982:47100, rmtAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124]
> [14:13:41,153][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor]
> Received state change finish message: false
> [14:13:41,367][INFO][sys-#8331%null%][GridDhtPartitionsExchangeFuture]
> Snapshot initialization completed [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer
> =1], time=0ms]
> [14:13:50,385][WARNING][exchange-worker-#34%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer
> =1], node=bda65979-33d1-4d6f-8a32-45b71255f835]. Dumping pending objects
> that might be the cause:
> [14:13:50,387][WARNING][exchange-worker-#34%null%][diagnostic] Ready
> affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
> [14:13:50,418][WARNING][exchange-worker-#34%null%][diagnostic] Last
> exchange future: GridDhtPartitionsExchangeFuture [dummy=false,
> forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent
> [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831628889, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT,
> tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831628889,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443,
> order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions
> [startCaches=null, stopCaches=[ignite-sys-cache, PortCache,
> FcPortStatsCache, SwitchCache, FabricCache], startGrps=[],
> stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false,
> FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache,
> destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest
> [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT,
> res=null, hash=428221662]]
> [14:13:50,419][WARNING][exchange-worker-#34%null%][
> GridCachePartitionExchangeManager] First 10 pending exchange futures
> [total=0]
> [14:13:50,419][WARNING][exchange-worker-#34%null%][diagnostic] Last 10
> exchange futures (total: 12):
> [14:13:50,419][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831628889, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
> [14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=0], evt=12, evtNode=TcpDiscoveryNode
> [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=10, intOrder=7, lastExchangeTime=1502830171605,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=11, intOrder=8, lastExchangeTime=1502831380784,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=10, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=10, intOrder=7, lastExchangeTime=1502830171605,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=9, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=3d162ac0-049f-4aa8-a4aa-3cc1667d7c70, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=4, intOrder=4, lastExchangeTime=1502751454121,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=8, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=7, intOrder=6, lastExchangeTime=1502816032452,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=7, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=7, intOrder=6, lastExchangeTime=1502816032452,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=2], evt=18, evtNode=TcpDiscoveryNode
> [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3],
> sockAddrs=[5e29cfd6.englab.brocade.com/10.24.51.150:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500],
> discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448020,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
> [14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831628889, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
> [14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=b6e50583-4f35-46fc-9f7b-4702abf9bea3, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=5, intOrder=5, lastExchangeTime=1502753203971,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:50,422][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> transactions:
> [14:13:50,436][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> explicit locks:
> [14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> cache futures:
> [14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> atomic cache futures:
> [14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> data streamer futures:
> [14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> transaction deadlock detection futures:
>
> Logs seem to repeat starting with " Failed to wait for partition map
> exchange ...".
>
> Later repetitions only have these logs:
>
> [16:18:35,463][WARNING][exchange-worker-#34%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer
> =1], node=bda65979-33d1-4d6f-8a32-45b71255f835]. Dumping pending objects
> that might be the cause:
> [16:18:45,465][WARNING][exchange-worker-#34%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer
> =1], node=bda65979-33d1-4d6f-8a32-45b71255f835]. Dumping pending objects
> that might be the cause:
> [16:18:52,458][INFO][db-checkpoint-thread-#562%null%][
> GridCacheDatabaseSharedManager] Skipping checkpoint (no pages were
> modified) [checkpointLockWait=0ms, chec
> kpointLockHoldTime=0ms, reason='timeout']
> [16:18:52,738][INFO][exchange-worker-#34%null%][
> GridCachePartitionExchangeManager] Skipping rebalancing (nothing
> scheduled) [top=AffinityTopologyVersion [topVer
> =12, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT,
> node=bda65979-33d1-4d6f-8a32-45b71255f835]
>
>
> Server node 2 logs:
>
> [14:13:40,299][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor]
> Start state transition: false
> [14:13:40,302][INFO][exchange-worker-#34%null%][time] Started exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> crd=false, evt=18, node=TcpDiscoveryNode [id=6ffb9c55-4f23-4920-8134-36a649371cda,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/2620:100:0:fe07:
> ed4c:b7b8:f80c:9bef%enp0s3:47500, /0:0:0:0:0:0:0:1%lo:47500, /
> 127.0.0.1:47500, rfische-2.englab.brocade.com/10.24.51.187:47500],
> discPort=47500, order=2, intOrder=2, lastExchangeTime=1502831618860,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> evtNode=TcpDiscoveryNode [id=6ffb9c55-4f23-4920-8134-36a649371cda,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/2620:100:0:fe07:
> ed4c:b7b8:f80c:9bef%enp0s3:47500, /0:0:0:0:0:0:0:1%lo:47500, /
> 127.0.0.1:47500, rfische-2.englab.brocade.com/10.24.51.187:47500],
> discPort=47500, order=2, intOrder=2, lastExchangeTime=1502831618860,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], customEvt=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false]]
> [14:13:40,302][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Start deactivation process
> [nodeId=6ffb9c55-4f23-4920-8134-36a649371cda, client=false,
> topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
> [14:13:40,314][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Successfully deactivated data
> structures, services and caches [nodeId=6ffb9c55-4f23-4920-8134-36a649371cda,
> client=false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
> [14:13:40,320][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Finished waiting for partition release
> future [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> waitTime=0ms]
> [14:13:40,940][INFO][grid-nio-worker-tcp-comm-2-#19%null%][TcpCommunicationSpi]
> Established outgoing communication connection [locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956,
> rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100]
> [14:13:40,940][INFO][exchange-worker-#34%null%][time] Finished exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> crd=false]
> [14:13:41,169][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor]
> Received state change finish message: false
> [14:13:41,926][INFO][sys-#8323%null%][GridDhtPartitionsExchangeFuture]
> Snapshot initialization completed [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], time=0ms]
> [14:13:50,965][WARNING][exchange-worker-#34%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], node=6ffb9c55-4f23-4920-8134-36a649371cda].
> Dumping pending objects that might be the cause:
> [14:13:50,966][WARNING][exchange-worker-#34%null%][diagnostic] Ready
> affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
> [14:13:51,078][WARNING][exchange-worker-#34%null%][diagnostic] Last
> exchange future: GridDhtPartitionsExchangeFuture [dummy=false,
> forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent
> [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502751442316, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=6ffb9c55, msg=null, type=DISCOVERY_CUSTOM_EVT,
> tstamp=1502831620299]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=1900349389], init=true, lastVer=null, partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions
> [startCaches=null, stopCaches=[ignite-sys-cache, PortCache,
> FcPortStatsCache, SwitchCache, FabricCache], startGrps=[],
> stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false,
> FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache,
> destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest
> [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620299, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[bda65979-33d1-4d6f-8a32-45b71255f835, 4d8c099c-b04f-48f9-a825-25eba9d794c5],
> super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null,
> hash=322499757]]
> [14:13:51,078][WARNING][exchange-worker-#34%null%][
> GridCachePartitionExchangeManager] First 10 pending exchange futures
> [total=0]
> [14:13:51,080][WARNING][exchange-worker-#34%null%][diagnostic] Last 10
> exchange futures (total: 12):
> [14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502751442316, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
> [14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=0], e:
> vt=12, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0,
> /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=10,
> intOrder=7, lastExchangeTime=1502830171994, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11,
> intOrder=8, lastExchangeTime=1502831380904, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=10, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=10,
> intOrder=7, lastExchangeTime=1502830171994, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=9, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=3d162ac0-049f-4aa8-a4aa-3cc1667d7c70, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=4,
> intOrder=4, lastExchangeTime=1502751454165, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=8, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=7,
> intOrder=6, lastExchangeTime=1502816032799, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=7, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=7,
> intOrder=6, lastExchangeTime=1502816032799, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=2], evt=18, evtNode=TcpDiscoveryNode
> [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3],
> sockAddrs=[rfische-3.englab.brocade.com/10.24.51.150:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500],
> discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448052,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
> [14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502751442316, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
> [14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=b6e50583-4f35-46fc-9f7b-4702abf9bea3, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0,
> rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=5,
> intOrder=5, lastExchangeTime=1502753205000, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> transactions:
> [14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> explicit locks:
> [14:13:51,089][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> cache futures:
> [14:13:51,089][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> atomic cache futures:
> [14:13:51,089][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> data streamer futures:
> [14:13:51,090][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> transaction deadlock detection futures:
> [14:13:51,863][INFO][grid-nio-worker-tcp-comm-3-#20%null%][diagnostic]
> Exchange future waiting for coordinator response
> [crd=bda65979-33d1-4d6f-8a32-45b71255f835, topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1]]
> Remote node information:
> General node info [id=bda65979-33d1-4d6f-8a32-45b71255f835, client=false,
> discoTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> time=14:13:51.481]
> Partitions exchange info [readyVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=0]]
> Last initialized exchange future: GridDhtPartitionsExchangeFuture
> [dummy=false, forcePreload=false, reassign=false,
> discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastEx:
> changeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a,
> isClient=false], topVer=12, nodeId8=bda65979, msg=null,
> type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831630880, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443,
> order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions
> [startCaches=null, stopCaches=[ignite-sys-cache, PortCache,
> FcPortStatsCache, SwitchCache, FabricCache], startGrps=[],
> stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false,
> FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache,
> destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest
> [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT,
> res=null, hash=428221662]]
> Communication SPI statistics [rmtNode=6ffb9c55-4f23-4920-
> 8134-36a649371cda]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=6ffb9c55-4f23-4920-8134-36a649371cda,
> idx=0, connCnt=0], msgsSent=6, msgsAckedByRmt=5, msgsRcvd=7, lastAcked=5,
> reserveCnt=3, descIdHash=1831806861]
> Communication SPI clients:
> [node=6ffb9c55-4f23-4920-8134-36a649371cda, client=GridTcpNioCommunicationClient
> [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker
> [super=AbstractNioClientWorker [idx=3, bytesRcvd=778699647,
> bytesSent=188269, bytesRcvd0=853, bytesSent0=0, select=true,
> super=GridWorker [name=grid-nio-worker-tcp-comm-3,
> igniteInstanceName=null, finished=false, hashCode=1677075109,
> interrupted=false, runner=grid-nio-worker-tcp-comm-3-#20%null%]]],
> writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor
> [acked=5, resendCnt=0, rcvCnt=7, sentCnt=6, reserved=true, lastAck=5,
> nodeLeft=false, node=TcpDiscoveryNode [id=6ffb9c55-4f23-4920-8134-36a649371cda,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/2620:100:0:fe07:
> ed4c:b7b8:f80c:9bef%enp0s3:47500, /0:0:0:0:0:0:0:1%lo:47500, /
> 127.0.0.1:47500, /10.24.51.187:47500], discPort=47500, order=2,
> intOrder=2, lastExchangeTime=1502751442204, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true,
> connectCnt=0, queueLimit=4096, reserveCnt=3, pairedConnections=false],
> outRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=7,
> sentCnt=6, reserved=true, lastAck=5, nodeLeft=false, node=TcpDiscoveryNode
> [id=6ffb9c55-4f23-4920-8134-36a649371cda, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /10.24.51.187:47500],
> discPort=47500, order=2, intOrder=2, lastExchangeTime=1502751442204,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=0, queueLimit=4096, reserveCnt=3,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100,
> rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956,
> createTime=1502831620610, closeTime=0, bytesSent=5151, bytesRcvd=11937,
> bytesSent0=0, bytesRcvd0=853, sndSchedTime=1502831620610,
> lastSndTime=1502831621365, lastRcvTime=1502831631409, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=org.apache.ignite.internal.util.nio.GridDirectParser@33874199,
> directMode=true], GridConnectionBytesVerifyFilter], accepted=true]],
> super=GridAbstractCommunicationClient [lastUsed=1502831620713,
> closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=3, keysCnt=1, bytesRcvd=778699647, bytesRcvd0=853,
> bytesSent=188269, bytesSent0=0]
> Connection info [in=true, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956,
> locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, msgsSent=6,
> msgsAckedByRmt=5, descIdHash=1831806861, unackedMsgs=[GridDhtPartitionsFullMessage],
> msgsRcvd=7, lastAcked=5, descIdHash=1831806861, bytesRcvd=11937,
> bytesRcvd0=853, bytesSent=5151, bytesSent0=0, opQueueSize=0]
> Exchange future: GridDhtPartitionsExchangeFuture [dummy=false,
> forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent
> [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831630880, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT,
> tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443,
> order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=nu:
> ll, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache,
> SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache,
> destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false,
> SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null,
> stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT,
> res=null, hash=428221662]]
> Local communication statistics:
> Communication SPI statistics [rmtNode=bda65979-33d1-4d6f-
> 8a32-45b71255f835]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> idx=0, connCnt=-1], msgsSent=7, msgsAckedByRmt=5, msgsRcvd=7, lastAcked=5,
> reserveCnt=3, descIdHash=1699623061]
> Communication SPI clients:
> [node=bda65979-33d1-4d6f-8a32-45b71255f835, client=GridTcpNioCommunicationClient
> [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker
> [super=AbstractNioClientWorker [idx=2, bytesRcvd=1301067310,
> bytesSent=316517, bytesRcvd0=9187, bytesSent0=853, select=true,
> super=GridWorker [name=grid-nio-worker-tcp-comm-2,
> igniteInstanceName=null, finished=false, hashCode=1774276493,
> interrupted=false, runner=grid-nio-worker-tcp-comm-2-#19%null%]]],
> writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor
> [acked=5, resendCnt=0, rcvCnt=7, sentCnt=7, reserved=true, lastAck=5,
> nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=3, queueLimit=4096, reserveCnt=3,
> pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=5,
> resendCnt=0, rcvCnt=7, sentCnt=7, reserved=true, lastAck=5, nodeLeft=false,
> node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=3, queueLimit=4096, reserveCnt=3,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956,
> rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100,
> createTime=1502831620938, closeTime=0, bytesSent=11895, bytesRcvd=14310,
> bytesSent0=853, bytesRcvd0=9187, sndSchedTime=1502831620938,
> lastSndTime=1502831631416, lastRcvTime=1502831631519, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=org.apache.ignite.internal.util.nio.GridDirectParser@58c3122a,
> directMode=true], GridConnectionBytesVerifyFilter], accepted=false]],
> super=GridAbstractCommunicationClient [lastUsed=1502831620938,
> closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=2, keysCnt=1, bytesRcvd=1301067310, bytesRcvd0=9187,
> bytesSent=316517, bytesSent0=853]
> Connection info [in=false, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100,
> locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956, msgsSent=7,
> msgsAckedByRmt=5, descIdHash=1699623061, unackedMsgs=[
> GridDhtPartitionsSingleMessage, IgniteDiagnosticMessage], msgsRcvd=7,
> lastAcked=5, descIdHash=1699623061, bytesRcvd=14310, bytesRcvd0=9187,
> bytesSent=11895, bytesSent0=853, opQueueSize=0]
>
> Again repeating some of the above logs.
>
>
> Server node 3:
>
> [14:13:40,311][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor]
> Start state transition: false
> [14:13:40,314][INFO][exchange-worker-#34%null%][time] Started exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> crd=false, evt=18, node=
> TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1,
> 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sock
> Addrs=[rfische-3.englab.brocade.com/10.24.51.150:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500],
> discPor
> t=47500, order=3, intOrder=3, lastExchangeTime=1502831620309, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> evtNode=TcpDiscoveryNode [id=4d8c099c
> -b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150,
> 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3],
> sockAddrs=[rfische-3.englab.broca
> de.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500,
> /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPort=47500,
> order=3, intOrder=3,
> lastExchangeTime=1502831620309, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a,
> isClient=false], customEvt=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-4
> 6f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d,
> initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false]]
> [14:13:40,314][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Start deactivation process
> [nodeId=4d8c099c-b04f-48f9-a825-25eba9d794c5, client
> =false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
> [14:13:40,334][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Successfully deactivated data
> structures, services and caches [nodeId=4d8c099c-
> b04f-48f9-a825-25eba9d794c5, client=false, topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1]]
> [14:13:40,335][INFO][exchange-worker-#34%null%][
> GridDhtPartitionsExchangeFuture] Finished waiting for partition release
> future [topVer=AffinityTopologyVersion [
> topVer=12, minorTopVer=1], waitTime=0ms]
> [14:13:40,789][INFO][grid-nio-worker-tcp-comm-3-#20%null%][TcpCommunicationSpi]
> Established outgoing communication connection [locAddr=/2620:100:0:fe07:
> 537b:345
> 9:e373:2436:46124, rmtAddr=/2620:100:0:fe07:f92c:
> 9dbd:9b0f:9982%enp0s3:47100]
> [14:13:40,790][INFO][exchange-worker-#34%null%][time] Finished exchange
> init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> crd=false]
> [14:13:41,178][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor]
> Received state change finish message: false
> [14:13:42,151][INFO][sys-#8325%null%][GridDhtPartitionsExchangeFuture]
> Snapshot initialization completed [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer
> =1], time=0ms]
> [14:13:50,908][WARNING][exchange-worker-#34%null%][diagnostic] Failed to
> wait for partition map exchange [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer
> =1], node=4d8c099c-b04f-48f9-a825-25eba9d794c5]. Dumping pending objects
> that might be the cause:
> [14:13:50,909][WARNING][exchange-worker-#34%null%][diagnostic] Ready
> affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
> [14:13:51,141][WARNING][exchange-worker-#34%null%][diagnostic] Last
> exchange future: GridDhtPartitionsExchangeFuture [dummy=false,
> forcePreload=false, reassign=
> false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7
> a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=Discovery
> Event [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:998
> 2%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, orde
> r=1, intOrder=1, lastExchangeTime=1502751448111, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=4d8c099c, msg=null, type=DISCO
> VERY_CUSTOM_EVT, tstamp=1502831620309]], crd=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620
> :100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.
> 1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751448111,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> exchId=GridDhtParti
> tionExchangeId [topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ig
> noreInterrupts=false, state=DONE, res=true, hash=1067966306], init=true,
> lastVer=null, partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1,
> lsnrCalls=4, don
> e=true, cancelled=false, err=null, futs=[true, true, true, true]],
> exchActions=ExchangeActions [startCaches=null,
> stopCaches=[ignite-sys-cache, PortCache, FcPor
> tStatsCache, SwitchCache, FabricCache], startGrps=[],
> stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false,
> FcPortStatsCache, destroy=false, Swit
> chCache, destroy=false, FabricCache, destroy=false], resetParts=null,
> stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246
> ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d,
> initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false],
> topVer=Affin
> ityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null,
> skipPreload=false, clientOnlyExchange=false, initTs=1502831620309,
> centralizedAff=false, cha
> ngeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[6ffb9c55-4f23-4920-8134-36a649371cda, bda65979-33d1-4d6f-8a32-45b71255f835],
> super=Gr
> idFutureAdapter [ignoreInterrupts=false, state=INIT, res=null,
> hash=297725997]]
> [14:13:51,141][WARNING][exchange-worker-#34%null%][
> GridCachePartitionExchangeManager] First 10 pending exchange futures
> [total=0]
> [14:13:51,143][WARNING][exchange-worker-#34%null%][diagnostic] Last 10
> exchange futures (total: 12):
> [14:13:51,143][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=1], e
> vt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:998
> 2%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, orde
> r=1, intOrder=1, lastExchangeTime=1502751448111, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
> [14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=12, minorTopVer=0], e
> vt=12, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1,
> 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0,
> /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /
> 10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502830173974,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=11, intOrder=8, lastExchangeTime=1502831381070,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=10, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=10, intOrder=7, lastExchangeTime=1502830173974,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=9, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=3d162ac0-049f-4aa8-a4aa-3cc1667d7c70, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=4, intOrder=4, lastExchangeTime=1502751454208,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=8, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=7, intOrder=6, lastExchangeTime=1502816033053,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,145][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=7, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode
> [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=7, intOrder=6, lastExchangeTime=1502816033053,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,145][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=2], evt=18, evtNode=TcpDiscoveryNode
> [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3],
> sockAddrs=[rfische-3.englab.brocade.com/10.24.51.150:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500],
> discPort=47500, order=3, intOrder=3, lastExchangeTime=1502831630889,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751448111,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] >>>
> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
> [topVer=6, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode
> [id=b6e50583-4f35-46fc-9f7b-4702abf9bea3, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3],
> sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
> /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0],
> discPort=0, order=5, intOrder=5, lastExchangeTime=1502753205141,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> transactions:
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> explicit locks:
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> cache futures:
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> atomic cache futures:
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> data streamer futures:
> [14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending
> transaction deadlock detection futures:
> [14:13:51,690][INFO][sys-#8327%null%][diagnostic] Exchange future waiting
> for coordinator response [crd=bda65979-33d1-4d6f-8a32-45b71255f835,
> topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
> Remote node information:
> General node info [id=bda65979-33d1-4d6f-8a32-45b71255f835, client=false,
> discoTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> time=14:13:51.525]
> Partitions exchange info [readyVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=0]]
> Last initialized exchange future: GridDhtPartitionsExchangeFuture
> [dummy=false, forcePreload=false, reassign=false,
> discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastEx:
> changeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a,
> isClient=false], topVer=12, nodeId8=bda65979, msg=null,
> type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831630880, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443,
> order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions
> [startCaches=null, stopCaches=[ignite-sys-cache, PortCache,
> FcPortStatsCache, SwitchCache, FabricCache], startGrps=[],
> stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false,
> FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache,
> destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest
> [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT,
> res=null, hash=428221662]]
> Communication SPI statistics [rmtNode=4d8c099c-b04f-48f9-
> a825-25eba9d794c5]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=4d8c099c-b04f-48f9-a825-25eba9d794c5,
> idx=0, connCnt=0], msgsSent=7, msgsAckedByRmt=6, msgsRcvd=7, lastAcked=5,
> reserveCnt=2, descIdHash=839849160]
> Communication SPI clients:
> [node=4d8c099c-b04f-48f9-a825-25eba9d794c5, client=GridTcpNioCommunicationClient
> [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker
> [super=AbstractNioClientWorker [idx=2, bytesRcvd=27033, bytesSent=31221,
> bytesRcvd0=853, bytesSent0=0, select=true, super=GridWorker
> [name=grid-nio-worker-tcp-comm-2, igniteInstanceName=null,
> finished=false, hashCode=916303930, interrupted=false,
> runner=grid-nio-worker-tcp-comm-2-#19%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0
> lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768
> cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=6, resendCnt=0,
> rcvCnt=7, sentCnt=7, reserved=true, lastAck=5, nodeLeft=false,
> node=TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1,
> 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[5e29cfd6.englab.
> brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /
> 127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500],
> discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448020,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=0, queueLimit=4096, reserveCnt=2,
> pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=6,
> resendCnt=0, rcvCnt=7, sentCnt=7, reserved=true, lastAck=5, nodeLeft=false,
> node=TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1,
> 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[5e29cfd6.englab.
> brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /
> 127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500],
> discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448020,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=0, queueLimit=4096, reserveCnt=2,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100,
> rmtAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124,
> createTime=1502831620775, closeTime=0, bytesSent=5151, bytesRcvd=12342,
> bytesSent0=0, bytesRcvd0=853, sndSchedTime=1502831620775,
> lastSndTime=1502831621365, lastRcvTime=1502831631275, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=org.apache.ignite.internal.util.nio.GridDirectParser@33874199,
> directMode=true], GridConnectionBytesVerifyFilter], accepted=true]],
> super=GridAbstractCommunicationClient [lastUsed=1502831620775,
> closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=2, keysCnt=1, bytesRcvd=27033, bytesRcvd0=853,
> bytesSent=31221, bytesSent0=0]
> Connection info [in=true, rmtAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124,
> locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, msgsSent=7,
> msgsAckedByRmt=6, descIdHash=839849160, unackedMsgs=[GridDhtPartitionsFullMessage],
> msgsRcvd=7, lastAcked=5, descIdHash=839849160, bytesRcvd=12342,
> bytesRcvd0=853, bytesSent=5151, bytesSent0=0, opQueueSize=0]
> Exchange future: GridDhtPartitionsExchangeFuture [dummy=false,
> forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent
> [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], affTopVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500,
> rfische-1.englab.brocade.com/10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502831630880, loc=true,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12,
> nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT,
> tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880,
> loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId
> [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1],
> nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true,
> initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true,
> hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443,
> order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture
> [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null,
> futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=nu
> ll, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache,
> SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache,
> destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false,
> SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null,
> stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage
> [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a,
> reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> activate=false], topVer=AffinityTopologyVersion [topVer=12,
> minorTopVer=1]]], affChangeMsg=null, skipPreload=false,
> clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false,
> changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0,
> remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT,
> res=null, hash=428221662]]
> Local communication statistics:
> Communication SPI statistics [rmtNode=bda65979-33d1-4d6f-
> 8a32-45b71255f835]
> Communication SPI recovery descriptors:
> [key=ConnectionKey [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835,
> idx=0, connCnt=-1], msgsSent=7, msgsAckedByRmt=5, msgsRcvd=8, lastAcked=6,
> reserveCnt=2, descIdHash=1344296970]
> Communication SPI clients:
> [node=bda65979-33d1-4d6f-8a32-45b71255f835, client=GridTcpNioCommunicationClient
> [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker
> [super=AbstractNioClientWorker [idx=3, bytesRcvd=148911614,
> bytesSent=52025, bytesRcvd0=9227, bytesSent0=853, select=true,
> super=GridWorker [name=grid-nio-worker-tcp-comm-3,
> igniteInstanceName=null, finished=false, hashCode=9014207,
> interrupted=false, runner=grid-nio-worker-tcp-comm-3-#20%null%]]],
> writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor
> [acked=5, resendCnt=0, rcvCnt=8, sentCnt=7, reserved=true, lastAck=6,
> nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835,
> addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1,
> 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:
> f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500,
> /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1,
> intOrder=1, lastExchangeTime=1502751448111, loc=false,
> ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true,
> connectCnt=2, queueLimit=4096, reserveCnt=2, pairedConnections=false],
> outRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=8,
> sentCnt=7, reserved=true, lastAck=6, nodeLeft=false, node=TcpDiscoveryNode
> [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo,
> 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3],
> sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /
> 10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751448111,
> loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false],
> connected=true, connectCnt=2, queueLimit=4096, reserveCnt=2,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124,
> rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100,
> createTime=1502831620779, closeTime=0, bytesSent=12300, bytesRcvd=14350,
> bytesSent0=853, bytesRcvd0=9227, sndSchedTime=1502831620779,
> lastSndTime=1502831631275, lastRcvTime=1502831631532, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=org.apache.ignite.internal.util.nio.GridDirectParser@14439bfb,
> directMode=true], GridConnectionBytesVerifyFilter], accepted=false]],
> super=GridAbstractCommunicationClient [lastUsed=1502831620790,
> closed=false, connIdx=0]]]
> NIO sessions statistics:
> >> Selector info [idx=3, keysCnt=1, bytesRcvd=148911614, bytesRcvd0=9227,
> bytesSent=52025, bytesSent0=853]
> Connection info [in=false, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100,
> locAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124, msgsSent=7,
> msgsAckedByRmt=5, descIdHash=1344296970, unackedMsgs=[
> GridDhtPartitionsSingleMessage, IgniteDiagnosticMessage], msgsRcvd=8,
> lastAcked=6, descIdHash=1344296970, bytesRcvd=14350, bytesRcvd0=9227,
> bytesSent=12300, bytesSent0=853, opQueueSize=0]
>
> Similar repetition as on the other nodes.
>
>
>
>
> Roger
>
> -----Original Message-----
> From: dkarachentsev [mailto:dkarachentsev@gridgain.com]
> Sent: Tuesday, August 15, 2017 2:05 AM
> To: user@ignite.apache.org
> Subject: RE: Activation: slow and: Ignite node crashed in the middle of
> checkpoint.
>
> Hi Roger,
>
> The recovery message in logs is normal case when node was forced to stop.
> This only means that data are restoring from WAL on start.
>
> Slow activation doesn't look OK, it shouldn't take so long. Could you
> please restart grid with -DIGNITE_QUIET=false JVM flag and share logs?
>
> Thanks!
> -Dmitry.
>
>
>
> --
> View this message in context: https://urldefense.proofpoint.
> com/v2/url?u=http-3A__apache-2Dignite-2Dusers.70518.x6.
> nabble.com_Activation-2Dslow-2Dand-2DIgnite-2Dnode-
> 2Dcrashed-2Din-2Dthe-2Dmiddle-2Dof-2Dcheckpoint-
> 2Dtp16144p16197.html&d=DwICAg&c=IL_XqQWOjubgfqINi2jTzg&r=
> 1esZO0r0bYS90lcsaLA6N4AFxuNo6lzauhETGwdJQoQ&m=JnQpalzeJE6hfAmoGt1Tq-
> Zwzjfs9siZ3AYjV5hHHy4&s=ub_f0AESPKsYlIHTcAoQVTKPwMZzvov4U6MNrYQVBmg&e=
> Sent from the Apache Ignite Users mailing list archive at Nabble.com.
>
>
RE: Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Posted by "Roger Fischer (CW)" <rf...@Brocade.com>.
Hi Dmitry and Alex,
the cache contains 19.2M objects. The work/db directory is 23, 26 and 22 GB respectively. The 3 nodes have 8 GB RAM each.
I initiated deactivate at 14:13:39. As of 16:50:00, deactivate has not completed. Only server node 2 continues to log warnings.
The client shows the following logs:
[14:13:39,473][INFO][main][GridClusterStateProcessor] Sending deactivate request from node [id=548f4233-67e9-4043-aa3a-086fb541c427, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], client=true, daemonfalse]
[14:13:40,369][INFO][tcp-client-disco-msg-worker-#4%null%][GridClusterStateProcessor] Start state transition: false
[14:13:40,395][INFO][exchange-worker-#96%null%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=false, evt=18, node=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11, intOrder=0, lastExchangeTime=1502830168939, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], evtNode=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11, intOrder=0, lastExchangeTime=1502830168939, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], customEvt=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false]]
[14:13:40,396][INFO][exchange-worker-#96%null%][GridDhtPartitionsExchangeFuture] Start deactivation process [nodeId=548f4233-67e9-4043-aa3a-086fb541c427, client=true, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,397][INFO][exchange-worker-#96%null%][GridDhtPartitionsExchangeFuture] Successfully deactivated data structures, services and caches [nodeId=548f4233-67e9-4043-aa3a-086fb541c427, client=true, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,398][INFO][exchange-worker-#96%null%][GridDhtPartitionsExchangeFuture] Snapshot initialization completed [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], time=0ms]
[14:13:40,398][INFO][exchange-worker-#96%null%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=false]
[14:13:41,173][INFO][tcp-client-disco-msg-worker-#4%null%][GridClusterStateProcessor] Received state change finish message: false
[14:13:45,355][INFO][grid-timeout-worker-#15%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=548f4233, name=null, uptime=00:24:07:982]
^-- H/N/C [hosts=3, nodes=4, CPUs=12]
^-- CPU [cur=0.6%, avg=0.89%, GC=0%]
^-- PageMemory [pages=0]
^-- Heap [used=248MB, free=86.36%, comm=951MB]
^-- Non heap [used=48MB, free=-1%, comm=49MB]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=0, qSize=0]
^-- Outbound messages queue [size=0]
[14:13:50,399][WARNING][exchange-worker-#96%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-086fb541c427]. Dumping pending objects that might be the cause:
[14:13:50,400][WARNING][exchange-worker-#96%null%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
[14:13:50,624][WARNING][exchange-worker-#96%null%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=548f4233, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620392]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=1870944589], init=true, lastVer=null, partReleaseFut=null, exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=true, clientOnlyExchange=true, initTs=1502831620392, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=false, evtLatch=0, remaining=[6ffb9c55-4f23-4920-8134-36a649371cda, bda65979-33d1-4d6f-8a32-45b71255f835, 4d8c099c-b04f-48f9-a825-25eba9d794c5], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=959636403]]
[14:13:50,624][WARNING][exchange-worker-#96%null%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=1]
[14:13:51,397][WARNING][exchange-worker-#96%null%][diagnostic] Last 10 exchange futures (total: 3):
[14:13:51,398][WARNING][exchange-worker-#96%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
[14:13:51,398][WARNING][exchange-worker-#96%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], evt=12, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502831381649, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,399][WARNING][exchange-worker-#96%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11, intOrder=0, lastExchangeTime=1502830168939, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,400][WARNING][exchange-worker-#96%null%][diagnostic] Pending transactions:
[14:13:51,400][WARNING][exchange-worker-#96%null%][diagnostic] Pending explicit locks:
[14:13:51,403][WARNING][exchange-worker-#96%null%][diagnostic] Pending cache futures:
[14:13:51,404][WARNING][exchange-worker-#96%null%][diagnostic] Pending atomic cache futures:
[14:13:51,404][WARNING][exchange-worker-#96%null%][diagnostic] Pending data streamer futures:
[14:13:51,404][WARNING][exchange-worker-#96%null%][diagnostic] Pending transaction deadlock detection futures:
[14:13:51,779][INFO][grid-nio-worker-tcp-comm-3-#20%null%][diagnostic] Exchange future waiting for coordinator response [crd=bda65979-33d1-4d6f-8a32-45b71255f835, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
Remote node information:
General node info [id=bda65979-33d1-4d6f-8a32-45b71255f835, client=false, discoTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], time=14:13:51.525]
Partitions exchange info [readyVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]
Last initialized exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443, order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=428221662]]
Communication SPI statistics [rmtNode=548f4233-67e9-4043-aa3a-086fb541c427]
Communication SPI recovery descriptors:
[key=ConnectionKey [nodeId=548f4233-67e9-4043-aa3a-086fb541c427, idx=0, connCnt=0], msgsSent=103, msgsAckedByRmt=96, msgsRcvd=106, lastAcked=96, reserveCnt=1, descIdHash=2019083035]
Communication SPI clients:
[node=548f4233-67e9-4043-aa3a-086fb541c427, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=1, bytesRcvd=569566918, bytesSent=3727054, bytesRcvd0=853, bytesSent0=0, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-1, igniteInstanceName=null, finished=false, hashCode=1204083040, interrupted=false, runner=grid-nio-worker-tcp-comm-1-#18%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=96, resendCnt=0, rcvCnt=106, sentCnt=103, reserved=true, lastAck=96, nodeLeft=false, node=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=11, intOrder=8, lastExchangeTime=1502831380784, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=96, resendCnt=0, rcvCnt=106, sentCnt=103, reserved=true, lastAck=96, nodeLeft=false, node=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=11, intOrder=8, lastExchangeTime=1502831380784, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], super=GridNioSessionImpl [locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926, createTime=1502831383244, closeTime=0, bytesSent=3569974, bytesRcvd=4153, bytesSent0=0, bytesRcvd0=853, sndSchedTime=1502831383244, lastSndTime=1502831546390, lastRcvTime=1502831631525, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@33874199, directMode=true], GridConnectionBytesVerifyFilter], accepted=true]], super=GridAbstractCommunicationClient [lastUsed=1502831383244, closed=false, connIdx=0]]]
NIO sessions statistics:
>> Selector info [idx=1, keysCnt=1, bytesRcvd=569566918, bytesRcvd0=853, bytesSent=3727054, bytesSent0=0]
Connection info [in=true, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926, locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, msgsSent=103, msgsAckedByRmt=96, descIdHash=2019083035, unackedMsgs=[GridQueryNextPageResponse, GridQueryNextPageResponse, GridQueryNextPageResponse, GridQueryNextPageResponse, GridQueryNextPageResponse], msgsRcvd=106, lastAcked=96, descIdHash=2019083035, bytesRcvd=4153, bytesRcvd0=853, bytesSent=3569974, bytesSent0=0, opQueueSize=0]
Exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831631537, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831631537, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443, order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=428221662]]
Local communication statistics:
Communication SPI statistics [rmtNode=bda65979-33d1-4d6f-8a32-45b71255f835]
Communication SPI recovery descriptors:
[key=ConnectionKey [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835, idx=0, connCnt=-1], msgsSent=106, msgsAckedByRmt=96, msgsRcvd=104, lastAcked=96, reserveCnt=1, descIdHash=859262134]
Communication SPI clients:
[node=bda65979-33d1-4d6f-8a32-45b71255f835, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=3, bytesRcvd=3579228, bytesSent=4129, bytesRcvd0=9282, bytesSent0=853, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-3, igniteInstanceName=null, finished=false, hashCode=969336725, interrupted=false, runner=grid-nio-worker-tcp-comm-3-#20%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=96, resendCnt=0, rcvCnt=104, sentCnt=106, reserved=true, lastAck=96, nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=1, queueLimit=4096, reserveCnt=1, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=96, resendCnt=0, rcvCnt=104, sentCnt=106, reserved=true, lastAck=96, nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831381649, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=1, queueLimit=4096, reserveCnt=1, pairedConnections=false], super=GridNioSessionImpl [locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100, createTime=1502831383242, closeTime=0, bytesSent=4111, bytesRcvd=3579228, bytesSent0=853, bytesRcvd0=9282, sndSchedTime=1502831383242, lastSndTime=1502831631530, lastRcvTime=1502831631541, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@438486ef, directMode=true], GridConnectionBytesVerifyFilter], accepted=false]], super=GridAbstractCommunicationClient [lastUsed=1502831383242, closed=false, connIdx=0]]]
NIO sessions statistics:
>> Selector info [idx=3, keysCnt=1, bytesRcvd=3579228, bytesRcvd0=9282, bytesSent=4129, bytesSent0=853]
Connection info [in=false, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100, locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39926, msgsSent=106, msgsAckedByRmt=96, descIdHash=859262134, unackedMsgs=[GridQueryNextPageRequest, GridQueryNextPageRequest, GridQueryNextPageRequest, GridQueryNextPageRequest, GridQueryNextPageRequest], msgsRcvd=104, lastAcked=96, descIdHash=859262134, bytesRcvd=3579228, bytesRcvd0=9282, bytesSent=4111, bytesSent0=853, opQueueSize=0]
Then the logs seem to repeat starting with " Failed to wait for partition map exchange ...".
Eventually only logs like this are repeated, seems every 10 seconds.
[16:10:53,425][WARNING][exchange-worker-#96%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
086fb541c427]. Dumping pending objects that might be the cause:
[16:11:03,426][WARNING][exchange-worker-#96%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
086fb541c427]. Dumping pending objects that might be the cause:
[16:11:13,427][WARNING][exchange-worker-#96%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
086fb541c427]. Dumping pending objects that might be the cause:
[16:11:23,428][WARNING][exchange-worker-#96%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
086fb541c427]. Dumping pending objects that might be the cause:
[16:11:33,428][WARNING][exchange-worker-#96%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
086fb541c427]. Dumping pending objects that might be the cause:
[16:11:43,428][WARNING][exchange-worker-#96%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=548f4233-67e9-4043-aa3a-
086fb541c427]. Dumping pending objects that might be the cause:
Server node 1 logs:
[14:13:40,170][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor] Start state transition: false
[14:13:40,172][INFO][exchange-worker-#34%null%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=true, evt=18, node=T
cpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockA
ddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort
=47500, order=1, intOrder=1, lastExchangeTime=1502831618858, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], evtNode=TcpDiscoveryNode [id=bda65979-
33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9
dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1,
lastExchangeTime=1502831618858, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], customEvt=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46
f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false]]
[14:13:40,172][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Start deactivation process [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835, client
=false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,320][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Successfully deactivated data structures, services and caches [nodeId=bda65979-
33d1-4d6f-8a32-45b71255f835, client=false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,344][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [
topVer=12, minorTopVer=1], waitTime=0ms]
[14:13:40,345][INFO][exchange-worker-#34%null%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=true]
[14:13:40,612][INFO][grid-nio-worker-tcp-comm-3-#20%null%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/2620:100:0:fe07:f92c:9dbd:9
b0f:9982:47100, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956]
[14:13:40,780][INFO][grid-nio-worker-tcp-comm-2-#19%null%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/2620:100:0:fe07:f92c:9dbd:9
b0f:9982:47100, rmtAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124]
[14:13:41,153][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor] Received state change finish message: false
[14:13:41,367][INFO][sys-#8331%null%][GridDhtPartitionsExchangeFuture] Snapshot initialization completed [topVer=AffinityTopologyVersion [topVer=12, minorTopVer
=1], time=0ms]
[14:13:50,385][WARNING][exchange-worker-#34%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer
=1], node=bda65979-33d1-4d6f-8a32-45b71255f835]. Dumping pending objects that might be the cause:
[14:13:50,387][WARNING][exchange-worker-#34%null%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
[14:13:50,418][WARNING][exchange-worker-#34%null%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831628889, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831628889, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443, order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=428221662]]
[14:13:50,419][WARNING][exchange-worker-#34%null%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=0]
[14:13:50,419][WARNING][exchange-worker-#34%null%][diagnostic] Last 10 exchange futures (total: 12):
[14:13:50,419][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831628889, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
[14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], evt=12, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502830171605, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=11, intOrder=8, lastExchangeTime=1502831380784, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502830171605, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=3d162ac0-049f-4aa8-a4aa-3cc1667d7c70, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=4, intOrder=4, lastExchangeTime=1502751454121, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:50,420][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=7, intOrder=6, lastExchangeTime=1502816032452, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=7, intOrder=6, lastExchangeTime=1502816032452, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], evt=18, evtNode=TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[5e29cfd6.englab.brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448020, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
[14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831628889, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
[14:13:50,421][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=b6e50583-4f35-46fc-9f7b-4702abf9bea3, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=5, intOrder=5, lastExchangeTime=1502753203971, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:50,422][WARNING][exchange-worker-#34%null%][diagnostic] Pending transactions:
[14:13:50,436][WARNING][exchange-worker-#34%null%][diagnostic] Pending explicit locks:
[14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending cache futures:
[14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending atomic cache futures:
[14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending data streamer futures:
[14:13:50,437][WARNING][exchange-worker-#34%null%][diagnostic] Pending transaction deadlock detection futures:
Logs seem to repeat starting with " Failed to wait for partition map exchange ...".
Later repetitions only have these logs:
[16:18:35,463][WARNING][exchange-worker-#34%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer
=1], node=bda65979-33d1-4d6f-8a32-45b71255f835]. Dumping pending objects that might be the cause:
[16:18:45,465][WARNING][exchange-worker-#34%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer
=1], node=bda65979-33d1-4d6f-8a32-45b71255f835]. Dumping pending objects that might be the cause:
[16:18:52,458][INFO][db-checkpoint-thread-#562%null%][GridCacheDatabaseSharedManager] Skipping checkpoint (no pages were modified) [checkpointLockWait=0ms, chec
kpointLockHoldTime=0ms, reason='timeout']
[16:18:52,738][INFO][exchange-worker-#34%null%][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer
=12, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=bda65979-33d1-4d6f-8a32-45b71255f835]
Server node 2 logs:
[14:13:40,299][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor] Start state transition: false
[14:13:40,302][INFO][exchange-worker-#34%null%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=false, evt=18, node=TcpDiscoveryNode [id=6ffb9c55-4f23-4920-8134-36a649371cda, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, rfische-2.englab.brocade.com/10.24.51.187:47500], discPort=47500, order=2, intOrder=2, lastExchangeTime=1502831618860, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], evtNode=TcpDiscoveryNode [id=6ffb9c55-4f23-4920-8134-36a649371cda, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, rfische-2.englab.brocade.com/10.24.51.187:47500], discPort=47500, order=2, intOrder=2, lastExchangeTime=1502831618860, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], customEvt=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false]]
[14:13:40,302][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Start deactivation process [nodeId=6ffb9c55-4f23-4920-8134-36a649371cda, client=false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,314][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Successfully deactivated data structures, services and caches [nodeId=6ffb9c55-4f23-4920-8134-36a649371cda, client=false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,320][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], waitTime=0ms]
[14:13:40,940][INFO][grid-nio-worker-tcp-comm-2-#19%null%][TcpCommunicationSpi] Established outgoing communication connection [locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100]
[14:13:40,940][INFO][exchange-worker-#34%null%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=false]
[14:13:41,169][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor] Received state change finish message: false
[14:13:41,926][INFO][sys-#8323%null%][GridDhtPartitionsExchangeFuture] Snapshot initialization completed [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], time=0ms]
[14:13:50,965][WARNING][exchange-worker-#34%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], node=6ffb9c55-4f23-4920-8134-36a649371cda]. Dumping pending objects that might be the cause:
[14:13:50,966][WARNING][exchange-worker-#34%null%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
[14:13:51,078][WARNING][exchange-worker-#34%null%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=6ffb9c55, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620299]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=1900349389], init=true, lastVer=null, partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620299, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[bda65979-33d1-4d6f-8a32-45b71255f835, 4d8c099c-b04f-48f9-a825-25eba9d794c5], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=322499757]]
[14:13:51,078][WARNING][exchange-worker-#34%null%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=0]
[14:13:51,080][WARNING][exchange-worker-#34%null%][diagnostic] Last 10 exchange futures (total: 12):
[14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
[14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], e:
vt=12, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502830171994, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=11, intOrder=8, lastExchangeTime=1502831380904, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502830171994, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,081][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=3d162ac0-049f-4aa8-a4aa-3cc1667d7c70, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=4, intOrder=4, lastExchangeTime=1502751454165, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=7, intOrder=6, lastExchangeTime=1502816032799, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=7, intOrder=6, lastExchangeTime=1502816032799, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], evt=18, evtNode=TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[rfische-3.englab.brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448052, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
[14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
[14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=b6e50583-4f35-46fc-9f7b-4702abf9bea3, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, rfische-2.englab.brocade.com/10.24.51.187:0], discPort=0, order=5, intOrder=5, lastExchangeTime=1502753205000, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] Pending transactions:
[14:13:51,082][WARNING][exchange-worker-#34%null%][diagnostic] Pending explicit locks:
[14:13:51,089][WARNING][exchange-worker-#34%null%][diagnostic] Pending cache futures:
[14:13:51,089][WARNING][exchange-worker-#34%null%][diagnostic] Pending atomic cache futures:
[14:13:51,089][WARNING][exchange-worker-#34%null%][diagnostic] Pending data streamer futures:
[14:13:51,090][WARNING][exchange-worker-#34%null%][diagnostic] Pending transaction deadlock detection futures:
[14:13:51,863][INFO][grid-nio-worker-tcp-comm-3-#20%null%][diagnostic] Exchange future waiting for coordinator response [crd=bda65979-33d1-4d6f-8a32-45b71255f835, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
Remote node information:
General node info [id=bda65979-33d1-4d6f-8a32-45b71255f835, client=false, discoTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], time=14:13:51.481]
Partitions exchange info [readyVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]
Last initialized exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastEx:
changeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443, order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=428221662]]
Communication SPI statistics [rmtNode=6ffb9c55-4f23-4920-8134-36a649371cda]
Communication SPI recovery descriptors:
[key=ConnectionKey [nodeId=6ffb9c55-4f23-4920-8134-36a649371cda, idx=0, connCnt=0], msgsSent=6, msgsAckedByRmt=5, msgsRcvd=7, lastAcked=5, reserveCnt=3, descIdHash=1831806861]
Communication SPI clients:
[node=6ffb9c55-4f23-4920-8134-36a649371cda, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=3, bytesRcvd=778699647, bytesSent=188269, bytesRcvd0=853, bytesSent0=0, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-3, igniteInstanceName=null, finished=false, hashCode=1677075109, interrupted=false, runner=grid-nio-worker-tcp-comm-3-#20%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=7, sentCnt=6, reserved=true, lastAck=5, nodeLeft=false, node=TcpDiscoveryNode [id=6ffb9c55-4f23-4920-8134-36a649371cda, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /10.24.51.187:47500], discPort=47500, order=2, intOrder=2, lastExchangeTime=1502751442204, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=3, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=7, sentCnt=6, reserved=true, lastAck=5, nodeLeft=false, node=TcpDiscoveryNode [id=6ffb9c55-4f23-4920-8134-36a649371cda, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /10.24.51.187:47500], discPort=47500, order=2, intOrder=2, lastExchangeTime=1502751442204, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=3, pairedConnections=false], super=GridNioSessionImpl [locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956, createTime=1502831620610, closeTime=0, bytesSent=5151, bytesRcvd=11937, bytesSent0=0, bytesRcvd0=853, sndSchedTime=1502831620610, lastSndTime=1502831621365, lastRcvTime=1502831631409, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@33874199, directMode=true], GridConnectionBytesVerifyFilter], accepted=true]], super=GridAbstractCommunicationClient [lastUsed=1502831620713, closed=false, connIdx=0]]]
NIO sessions statistics:
>> Selector info [idx=3, keysCnt=1, bytesRcvd=778699647, bytesRcvd0=853, bytesSent=188269, bytesSent0=0]
Connection info [in=true, rmtAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956, locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, msgsSent=6, msgsAckedByRmt=5, descIdHash=1831806861, unackedMsgs=[GridDhtPartitionsFullMessage], msgsRcvd=7, lastAcked=5, descIdHash=1831806861, bytesRcvd=11937, bytesRcvd0=853, bytesSent=5151, bytesSent0=0, opQueueSize=0]
Exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443, order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=nu:
ll, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=428221662]]
Local communication statistics:
Communication SPI statistics [rmtNode=bda65979-33d1-4d6f-8a32-45b71255f835]
Communication SPI recovery descriptors:
[key=ConnectionKey [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835, idx=0, connCnt=-1], msgsSent=7, msgsAckedByRmt=5, msgsRcvd=7, lastAcked=5, reserveCnt=3, descIdHash=1699623061]
Communication SPI clients:
[node=bda65979-33d1-4d6f-8a32-45b71255f835, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=2, bytesRcvd=1301067310, bytesSent=316517, bytesRcvd0=9187, bytesSent0=853, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-2, igniteInstanceName=null, finished=false, hashCode=1774276493, interrupted=false, runner=grid-nio-worker-tcp-comm-2-#19%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=7, sentCnt=7, reserved=true, lastAck=5, nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=3, queueLimit=4096, reserveCnt=3, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=7, sentCnt=7, reserved=true, lastAck=5, nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751442316, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=3, queueLimit=4096, reserveCnt=3, pairedConnections=false], super=GridNioSessionImpl [locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100, createTime=1502831620938, closeTime=0, bytesSent=11895, bytesRcvd=14310, bytesSent0=853, bytesRcvd0=9187, sndSchedTime=1502831620938, lastSndTime=1502831631416, lastRcvTime=1502831631519, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@58c3122a, directMode=true], GridConnectionBytesVerifyFilter], accepted=false]], super=GridAbstractCommunicationClient [lastUsed=1502831620938, closed=false, connIdx=0]]]
NIO sessions statistics:
>> Selector info [idx=2, keysCnt=1, bytesRcvd=1301067310, bytesRcvd0=9187, bytesSent=316517, bytesSent0=853]
Connection info [in=false, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100, locAddr=/2620:100:0:fe07:ed4c:b7b8:f80c:9bef:39956, msgsSent=7, msgsAckedByRmt=5, descIdHash=1699623061, unackedMsgs=[GridDhtPartitionsSingleMessage, IgniteDiagnosticMessage], msgsRcvd=7, lastAcked=5, descIdHash=1699623061, bytesRcvd=14310, bytesRcvd0=9187, bytesSent=11895, bytesSent0=853, opQueueSize=0]
Again repeating some of the above logs.
Server node 3:
[14:13:40,311][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor] Start state transition: false
[14:13:40,314][INFO][exchange-worker-#34%null%][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=false, evt=18, node=
TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sock
Addrs=[rfische-3.englab.brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPor
t=47500, order=3, intOrder=3, lastExchangeTime=1502831620309, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], evtNode=TcpDiscoveryNode [id=4d8c099c
-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[rfische-3.englab.broca
de.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPort=47500, order=3, intOrder=3,
lastExchangeTime=1502831620309, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], customEvt=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-4
6f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false]]
[14:13:40,314][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Start deactivation process [nodeId=4d8c099c-b04f-48f9-a825-25eba9d794c5, client
=false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,334][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Successfully deactivated data structures, services and caches [nodeId=4d8c099c-
b04f-48f9-a825-25eba9d794c5, client=false, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
[14:13:40,335][INFO][exchange-worker-#34%null%][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [
topVer=12, minorTopVer=1], waitTime=0ms]
[14:13:40,789][INFO][grid-nio-worker-tcp-comm-3-#20%null%][TcpCommunicationSpi] Established outgoing communication connection [locAddr=/2620:100:0:fe07:537b:345
9:e373:2436:46124, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100]
[14:13:40,790][INFO][exchange-worker-#34%null%][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], crd=false]
[14:13:41,178][INFO][tcp-disco-msg-worker-#3%null%][GridClusterStateProcessor] Received state change finish message: false
[14:13:42,151][INFO][sys-#8325%null%][GridDhtPartitionsExchangeFuture] Snapshot initialization completed [topVer=AffinityTopologyVersion [topVer=12, minorTopVer
=1], time=0ms]
[14:13:50,908][WARNING][exchange-worker-#34%null%][diagnostic] Failed to wait for partition map exchange [topVer=AffinityTopologyVersion [topVer=12, minorTopVer
=1], node=4d8c099c-b04f-48f9-a825-25eba9d794c5]. Dumping pending objects that might be the cause:
[14:13:50,909][WARNING][exchange-worker-#34%null%][diagnostic] Ready affinity version: AffinityTopologyVersion [topVer=12, minorTopVer=0]
[14:13:51,141][WARNING][exchange-worker-#34%null%][diagnostic] Last exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=
false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7
a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=Discovery
Event [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:998
2%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, orde
r=1, intOrder=1, lastExchangeTime=1502751448111, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=4d8c099c, msg=null, type=DISCO
VERY_CUSTOM_EVT, tstamp=1502831620309]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620
:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.
1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751448111, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtParti
tionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ig
noreInterrupts=false, state=DONE, res=true, hash=1067966306], init=true, lastVer=null, partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, don
e=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPor
tStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, Swit
chCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246
ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=Affin
ityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620309, centralizedAff=false, cha
ngeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[6ffb9c55-4f23-4920-8134-36a649371cda, bda65979-33d1-4d6f-8a32-45b71255f835], super=Gr
idFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=297725997]]
[14:13:51,141][WARNING][exchange-worker-#34%null%][GridCachePartitionExchangeManager] First 10 pending exchange futures [total=0]
[14:13:51,143][WARNING][exchange-worker-#34%null%][diagnostic] Last 10 exchange futures (total: 12):
[14:13:51,143][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], e
vt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:998
2%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, orde
r=1, intOrder=1, lastExchangeTime=1502751448111, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=false]
[14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], e
vt=12, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502830173974, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=548f4233-67e9-4043-aa3a-086fb541c427, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=11, intOrder=8, lastExchangeTime=1502831381070, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=d8c9f516-433d-4914-aed0-d07fb78aa960, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=10, intOrder=7, lastExchangeTime=1502830173974, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=3d162ac0-049f-4aa8-a4aa-3cc1667d7c70, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=4, intOrder=4, lastExchangeTime=1502751454208, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,144][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=7, intOrder=6, lastExchangeTime=1502816033053, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,145][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], evt=10, evtNode=TcpDiscoveryNode [id=8b933c1c-bf0c-4fb8-ba2e-fc188248099c, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=7, intOrder=6, lastExchangeTime=1502816033053, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,145][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=2], evt=18, evtNode=TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[rfische-3.englab.brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPort=47500, order=3, intOrder=3, lastExchangeTime=1502831630889, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=1], evt=18, evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751448111, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], done=true]
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] >>> GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], evt=11, evtNode=TcpDiscoveryNode [id=b6e50583-4f35-46fc-9f7b-4702abf9bea3, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.187, 127.0.0.1, 2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /2620:100:0:fe07:ed4c:b7b8:f80c:9bef%enp0s3:0, /10.24.51.187:0], discPort=0, order=5, intOrder=5, lastExchangeTime=1502753205141, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], done=true]
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending transactions:
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending explicit locks:
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending cache futures:
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending atomic cache futures:
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending data streamer futures:
[14:13:51,146][WARNING][exchange-worker-#34%null%][diagnostic] Pending transaction deadlock detection futures:
[14:13:51,690][INFO][sys-#8327%null%][diagnostic] Exchange future waiting for coordinator response [crd=bda65979-33d1-4d6f-8a32-45b71255f835, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]
Remote node information:
General node info [id=bda65979-33d1-4d6f-8a32-45b71255f835, client=false, discoTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], time=14:13:51.525]
Partitions exchange info [readyVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]
Last initialized exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastEx:
changeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443, order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=null, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=428221662]]
Communication SPI statistics [rmtNode=4d8c099c-b04f-48f9-a825-25eba9d794c5]
Communication SPI recovery descriptors:
[key=ConnectionKey [nodeId=4d8c099c-b04f-48f9-a825-25eba9d794c5, idx=0, connCnt=0], msgsSent=7, msgsAckedByRmt=6, msgsRcvd=7, lastAcked=5, reserveCnt=2, descIdHash=839849160]
Communication SPI clients:
[node=4d8c099c-b04f-48f9-a825-25eba9d794c5, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=2, bytesRcvd=27033, bytesSent=31221, bytesRcvd0=853, bytesSent0=0, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-2, igniteInstanceName=null, finished=false, hashCode=916303930, interrupted=false, runner=grid-nio-worker-tcp-comm-2-#19%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=6, resendCnt=0, rcvCnt=7, sentCnt=7, reserved=true, lastAck=5, nodeLeft=false, node=TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[5e29cfd6.englab.brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448020, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=2, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=6, resendCnt=0, rcvCnt=7, sentCnt=7, reserved=true, lastAck=5, nodeLeft=false, node=TcpDiscoveryNode [id=4d8c099c-b04f-48f9-a825-25eba9d794c5, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.150, 127.0.0.1, 2620:100:0:fe07:537b:3459:e373:2436%enp0s3], sockAddrs=[5e29cfd6.englab.brocade.com/10.24.51.150:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /2620:100:0:fe07:537b:3459:e373:2436%enp0s3:47500], discPort=47500, order=3, intOrder=3, lastExchangeTime=1502751448020, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=2, pairedConnections=false], super=GridNioSessionImpl [locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, rmtAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124, createTime=1502831620775, closeTime=0, bytesSent=5151, bytesRcvd=12342, bytesSent0=0, bytesRcvd0=853, sndSchedTime=1502831620775, lastSndTime=1502831621365, lastRcvTime=1502831631275, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@33874199, directMode=true], GridConnectionBytesVerifyFilter], accepted=true]], super=GridAbstractCommunicationClient [lastUsed=1502831620775, closed=false, connIdx=0]]]
NIO sessions statistics:
>> Selector info [idx=2, keysCnt=1, bytesRcvd=27033, bytesRcvd0=853, bytesSent=31221, bytesSent0=0]
Connection info [in=true, rmtAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124, locAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982:47100, msgsSent=7, msgsAckedByRmt=6, descIdHash=839849160, unackedMsgs=[GridDhtPartitionsFullMessage], msgsRcvd=7, lastAcked=5, descIdHash=839849160, bytesRcvd=12342, bytesRcvd0=853, bytesSent=5151, bytesSent0=0, opQueueSize=0]
Exchange future: GridDhtPartitionsExchangeFuture [dummy=false, forcePreload=false, reassign=false, discoEvt=DiscoveryCustomEvent [customMsg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], affTopVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], super=DiscoveryEvent [evtNode=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], topVer=12, nodeId8=bda65979, msg=null, type=DISCOVERY_CUSTOM_EVT, tstamp=1502831620166]], crd=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, rfische-1.englab.brocade.com/10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502831630880, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1], nodeId=bda65979, evt=DISCOVERY_CUSTOM_EVT], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=DONE, res=true, hash=360559332], init=true, lastVer=GridCacheVersion [topVer=114231443, order=1502764777482, nodeOrder=3], partReleaseFut=GridCompoundFuture [rdc=null, initFlag=1, lsnrCalls=4, done=true, cancelled=false, err=null, futs=[true, true, true, true]], exchActions=ExchangeActions [startCaches=nu
ll, stopCaches=[ignite-sys-cache, PortCache, FcPortStatsCache, SwitchCache, FabricCache], startGrps=[], stopGrps=[ignite-sys-cache, destroy=false, PortCache, destroy=false, FcPortStatsCache, destroy=false, SwitchCache, destroy=false, FabricCache, destroy=false], resetParts=null, stateChangeRequest=StateChangeRequest [msg=ChangeGlobalStateMessage [id=c90edf2ed51-d51246ce-e4d1-46f7-b156-f1ceac90bb7a, reqId=5505420d-5d31-4d2c-b0ae-fa7a77629d2d, initiatingNodeId=bda65979-33d1-4d6f-8a32-45b71255f835, activate=false], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=1]]], affChangeMsg=null, skipPreload=false, clientOnlyExchange=false, initTs=1502831620166, centralizedAff=false, changeGlobalStateE=null, forcedRebFut=null, done=true, evtLatch=0, remaining=[], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=428221662]]
Local communication statistics:
Communication SPI statistics [rmtNode=bda65979-33d1-4d6f-8a32-45b71255f835]
Communication SPI recovery descriptors:
[key=ConnectionKey [nodeId=bda65979-33d1-4d6f-8a32-45b71255f835, idx=0, connCnt=-1], msgsSent=7, msgsAckedByRmt=5, msgsRcvd=8, lastAcked=6, reserveCnt=2, descIdHash=1344296970]
Communication SPI clients:
[node=bda65979-33d1-4d6f-8a32-45b71255f835, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=3, bytesRcvd=148911614, bytesSent=52025, bytesRcvd0=9227, bytesSent0=853, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-3, igniteInstanceName=null, finished=false, hashCode=9014207, interrupted=false, runner=grid-nio-worker-tcp-comm-3-#20%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=8, sentCnt=7, reserved=true, lastAck=6, nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751448111, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=2, queueLimit=4096, reserveCnt=2, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=5, resendCnt=0, rcvCnt=8, sentCnt=7, reserved=true, lastAck=6, nodeLeft=false, node=TcpDiscoveryNode [id=bda65979-33d1-4d6f-8a32-45b71255f835, addrs=[0:0:0:0:0:0:0:1%lo, 10.24.51.190, 127.0.0.1, 2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3], sockAddrs=[/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47500, /10.24.51.190:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1502751448111, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=false], connected=true, connectCnt=2, queueLimit=4096, reserveCnt=2, pairedConnections=false], super=GridNioSessionImpl [locAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100, createTime=1502831620779, closeTime=0, bytesSent=12300, bytesRcvd=14350, bytesSent0=853, bytesRcvd0=9227, sndSchedTime=1502831620779, lastSndTime=1502831631275, lastRcvTime=1502831631532, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@14439bfb, directMode=true], GridConnectionBytesVerifyFilter], accepted=false]], super=GridAbstractCommunicationClient [lastUsed=1502831620790, closed=false, connIdx=0]]]
NIO sessions statistics:
>> Selector info [idx=3, keysCnt=1, bytesRcvd=148911614, bytesRcvd0=9227, bytesSent=52025, bytesSent0=853]
Connection info [in=false, rmtAddr=/2620:100:0:fe07:f92c:9dbd:9b0f:9982%enp0s3:47100, locAddr=/2620:100:0:fe07:537b:3459:e373:2436:46124, msgsSent=7, msgsAckedByRmt=5, descIdHash=1344296970, unackedMsgs=[GridDhtPartitionsSingleMessage, IgniteDiagnosticMessage], msgsRcvd=8, lastAcked=6, descIdHash=1344296970, bytesRcvd=14350, bytesRcvd0=9227, bytesSent=12300, bytesSent0=853, opQueueSize=0]
Similar repetition as on the other nodes.
Roger
-----Original Message-----
From: dkarachentsev [mailto:dkarachentsev@gridgain.com]
Sent: Tuesday, August 15, 2017 2:05 AM
To: user@ignite.apache.org
Subject: RE: Activation: slow and: Ignite node crashed in the middle of checkpoint.
Hi Roger,
The recovery message in logs is normal case when node was forced to stop.
This only means that data are restoring from WAL on start.
Slow activation doesn't look OK, it shouldn't take so long. Could you please restart grid with -DIGNITE_QUIET=false JVM flag and share logs?
Thanks!
-Dmitry.
--
View this message in context: https://urldefense.proofpoint.com/v2/url?u=http-3A__apache-2Dignite-2Dusers.70518.x6.nabble.com_Activation-2Dslow-2Dand-2DIgnite-2Dnode-2Dcrashed-2Din-2Dthe-2Dmiddle-2Dof-2Dcheckpoint-2Dtp16144p16197.html&d=DwICAg&c=IL_XqQWOjubgfqINi2jTzg&r=1esZO0r0bYS90lcsaLA6N4AFxuNo6lzauhETGwdJQoQ&m=JnQpalzeJE6hfAmoGt1Tq-Zwzjfs9siZ3AYjV5hHHy4&s=ub_f0AESPKsYlIHTcAoQVTKPwMZzvov4U6MNrYQVBmg&e=
Sent from the Apache Ignite Users mailing list archive at Nabble.com.
RE: Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Posted by dkarachentsev <dk...@gridgain.com>.
Hi Roger,
The recovery message in logs is normal case when node was forced to stop.
This only means that data are restoring from WAL on start.
Slow activation doesn't look OK, it shouldn't take so long. Could you please
restart grid with -DIGNITE_QUIET=false JVM flag and share logs?
Thanks!
-Dmitry.
--
View this message in context: http://apache-ignite-users.70518.x6.nabble.com/Activation-slow-and-Ignite-node-crashed-in-the-middle-of-checkpoint-tp16144p16197.html
Sent from the Apache Ignite Users mailing list archive at Nabble.com.
RE: Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Posted by "Roger Fischer (CW)" <rf...@Brocade.com>.
Hi Alex,
there were no other relevant logs than what I already listed in the first email.
<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="
http://www.springframework.org/schema/beans
http://www.springframework.org/schema/beans/spring-beans.xsd">
<bean id="grid.cfg" class="org.apache.ignite.configuration.IgniteConfiguration"> <property name="discoverySpi">
<bean class="org.apache.ignite.spi.discovery.tcp.TcpDiscoverySpi">
<property name="ipFinder">
<bean class="org.apache.ignite.spi.discovery.tcp.ipfinder.vm.TcpDiscoveryVmIpFinder">
<property name="addresses">
<list>
<value>10.24.51.190</value>
<value>10.24.51.187</value>
<value>10.24.51.150</value>
</list>
</property>
</bean>
</property>
</bean>
</property>
<property name="persistentStoreConfiguration">
<bean class="org.apache.ignite.configuration.PersistentStoreConfiguration"/>
</property>
<property name="cacheConfiguration">
<list>
<bean class="org.apache.ignite.configuration.CacheConfiguration">
<property name="name" value="FcPortStatsCache"/>
<property name="cacheMode" value="PARTITIONED"/>
<property name="backups" value="1"/>
<property name="queryEntities">
<list>
<bean class="org.apache.ignite.cache.QueryEntity">
<property name="keyType" value="com.abc.poc.inppoc.model.FcPortStatsKey"/>
<property name="valueType" value="com.abc.poc.inppoc.model.FcPortStats"/>
<property name="fields">
<map>
<entry key="dateTime" value="java.util.Date"/>
<entry key="portId" value="java.util.UUID"/>
<entry key="portType" value="java.lang.Integer"/>
<entry key="switchId" value="java.util.UUID"/>
<entry key="fabricId" value="java.util.UUID"/>
<entry key="rxUtil" value="java.lang.Float"/>
<entry key="txUtil" value="java.lang.Float"/>
<entry key="higherUtil" value="java.lang.Float"/>
<entry key="lowerUtil" value="java.lang.Float"/>
<entry key="rxRate" value="java.lang.Float"/>
<entry key="txRate" value="java.lang.Float"/>
<entry key="higherRate" value="java.lang.Float"/>
<entry key="lowerRate" value="java.lang.Float"/>
<entry key="c3Discards" value="java.lang.Float"/>
<entry key="crcErrors" value="java.lang.Float"/>
</map>
</property>
<property name="indexes">
<list>
<bean class="org.apache.ignite.cache.QueryIndex">
<constructor-arg>
<list>
<value>dateTime</value>
<value>portId</value>
</list>
</constructor-arg>
<constructor-arg value="SORTED"/>
</bean>
<bean class="org.apache.ignite.cache.QueryIndex">
<constructor-arg>
<list>
<value>portId</value>
<value>dateTime</value>
</list>
</constructor-arg>
<constructor-arg value="SORTED"/>
</bean>
<bean class="org.apache.ignite.cache.QueryIndex">
<constructor-arg>
<list>
<value>switchId</value>
<value>dateTime</value>
</list>
</constructor-arg>
<constructor-arg value="SORTED"/>
</bean>
</list>
</property>
</bean>
</list>
</property>
</bean>
</list>
</property>
</bean>
</beans>
All 3 servers (and the client) are on VMs on the same host. No network hop latency. But all 3 VMs use the same physical disk (on the host).
Servers have 16 GB of RAM. Data on disk (work/db) was about 35 GB per mode. About 36M objects.
Please also note http://apache-ignite-users.70518.x6.nabble.com/Strange-problems-with-Ignite-native-Persistence-when-Data-exceeds-Memory-td16187.html.
There were some odd problems at time that may have affected the activation.
Roger
From: afedotov [mailto:alexander.fedotoff@gmail.com]
Sent: Monday, August 14, 2017 11:05 AM
To: user@ignite.apache.org
Subject: Re: Activation: slow and: Ignite node crashed in the middle of checkpoint.
Hi,
Could you please share the logs and configuration?
Actually, the activation time depends on the amount of data, network connectivity and other variables.
Kind regards,
Alex.
On Sat, Aug 12, 2017 at 12:39 AM, Roger Fischer (CW) [via Apache Ignite Users] <[hidden email]</user/SendEmail.jtp?type=node&node=16176&i=0>> wrote:
Hello,
I am wondering if the following behavior is typical, or if it represents a concern.
I have a 3 node cluster with native persistence. Each node as 4 CPU and 16 GB of RAM.
Each node has ~45 GB used in work/db. Total across the 3 nodes is about 36.5 M objects.
I am using SQL queries, and there are 3 indexes.
The servers start up normally and join the cluster, as expected.
When I start the client, which calls active(), all 3 servers report the following:
[12:41:28] Topology snapshot [ver=5, servers=3, clients=1, CPUs=16, heap=4.8GB]
[12:41:29] Default checkpoint page buffer size is too small, setting to an adjusted value: 2.0 GiB
[12:41:29] Ignite node crashed in the middle of checkpoint. Will restore memory state and enforce checkpoint on node start.
1) Should I worry about the “crashed” log?
The activation takes more than 30 minutes (until active() returns).
2) Is that normal for activate to take that long?
ver. 2.1.0#20170720-sha1:a6ca5c8a
OS: Linux 3.10.0-514.el7.x86_64 amd64
Thanks…
Roger
________________________________
If you reply to this email, your message will be added to the discussion below:
http://apache-ignite-users.70518.x6.nabble.com/Activation-slow-and-Ignite-node-crashed-in-the-middle-of-checkpoint-tp16144.html<https://urldefense.proofpoint.com/v2/url?u=http-3A__apache-2Dignite-2Dusers.70518.x6.nabble.com_Activation-2Dslow-2Dand-2DIgnite-2Dnode-2Dcrashed-2Din-2Dthe-2Dmiddle-2Dof-2Dcheckpoint-2Dtp16144.html&d=DwMFaQ&c=IL_XqQWOjubgfqINi2jTzg&r=1esZO0r0bYS90lcsaLA6N4AFxuNo6lzauhETGwdJQoQ&m=qsKTpUnWgB48OZA1huxDdJW-LyQpHaNdTlxMrCCW-Xk&s=DO1_9o_iSHBJutWMps2XTrpB04xC7ifpFgWgH-GCQKI&e=>
To start a new topic under Apache Ignite Users, email [hidden email]</user/SendEmail.jtp?type=node&node=16176&i=1>
To unsubscribe from Apache Ignite Users, click here.
NAML<https://urldefense.proofpoint.com/v2/url?u=http-3A__apache-2Dignite-2Dusers.70518.x6.nabble.com_template_NamlServlet.jtp-3Fmacro-3Dmacro-5Fviewer-26id-3Dinstant-5Fhtml-2521nabble-253Aemail.naml-26base-3Dnabble.naml.namespaces.BasicNamespace-2Dnabble.view.web.template.NabbleNamespace-2Dnabble.view.web.template.NodeNamespace-26breadcrumbs-3Dnotify-5Fsubscribers-2521nabble-253Aemail.naml-2Dinstant-5Femails-2521nabble-253Aemail.naml-2Dsend-5Finstant-5Femail-2521nabble-253Aemail.naml&d=DwMFaQ&c=IL_XqQWOjubgfqINi2jTzg&r=1esZO0r0bYS90lcsaLA6N4AFxuNo6lzauhETGwdJQoQ&m=qsKTpUnWgB48OZA1huxDdJW-LyQpHaNdTlxMrCCW-Xk&s=UnxulBBZr8p2NytrAfQlV_zN5CuQMKdMmEzmwxTWre4&e=>
________________________________
View this message in context: Re: Activation: slow and: Ignite node crashed in the middle of checkpoint.<https://urldefense.proofpoint.com/v2/url?u=http-3A__apache-2Dignite-2Dusers.70518.x6.nabble.com_Activation-2Dslow-2Dand-2DIgnite-2Dnode-2Dcrashed-2Din-2Dthe-2Dmiddle-2Dof-2Dcheckpoint-2Dtp16144p16176.html&d=DwMFaQ&c=IL_XqQWOjubgfqINi2jTzg&r=1esZO0r0bYS90lcsaLA6N4AFxuNo6lzauhETGwdJQoQ&m=qsKTpUnWgB48OZA1huxDdJW-LyQpHaNdTlxMrCCW-Xk&s=EniF7rtveceC33Z8NsqSuKuTjP6oxO1SLh9wC4S4S1o&e=>
Sent from the Apache Ignite Users mailing list archive<https://urldefense.proofpoint.com/v2/url?u=http-3A__apache-2Dignite-2Dusers.70518.x6.nabble.com_&d=DwMFaQ&c=IL_XqQWOjubgfqINi2jTzg&r=1esZO0r0bYS90lcsaLA6N4AFxuNo6lzauhETGwdJQoQ&m=qsKTpUnWgB48OZA1huxDdJW-LyQpHaNdTlxMrCCW-Xk&s=YZ5IcVzR9jK6NBv3sOl_ifmo1gC14Pa01R0HCHWBLPY&e=> at Nabble.com.
Re: Activation: slow and: Ignite node crashed in the middle of
checkpoint.
Posted by afedotov <al...@gmail.com>.
Hi,
Could you please share the logs and configuration?
Actually, the activation time depends on the amount of data, network
connectivity and other variables.
Kind regards,
Alex.
On Sat, Aug 12, 2017 at 12:39 AM, Roger Fischer (CW) [via Apache Ignite
Users] <ml...@n6.nabble.com> wrote:
> Hello,
>
>
>
> I am wondering if the following behavior is typical, or if it represents a
> concern.
>
>
>
> I have a 3 node cluster with native persistence. Each node as 4 CPU and 16
> GB of RAM.
>
> Each node has ~45 GB used in work/db. Total across the 3 nodes is about
> 36.5 M objects.
>
> I am using SQL queries, and there are 3 indexes.
>
>
>
> The servers start up normally and join the cluster, as expected.
>
>
>
> When I start the client, which calls active(), all 3 servers report the
> following:
>
>
>
> [12:41:28] Topology snapshot [ver=5, servers=3, clients=1, CPUs=16,
> heap=4.8GB]
>
> [12:41:29] Default checkpoint page buffer size is too small, setting to an
> adjusted value: 2.0 GiB
>
> [12:41:29] Ignite node crashed in the middle of checkpoint. Will restore
> memory state and enforce checkpoint on node start.
>
>
>
> 1) Should I worry about the “crashed” log?
>
>
>
> The activation takes more than 30 minutes (until active() returns).
>
>
>
> 2) Is that normal for activate to take that long?
>
>
>
> ver. 2.1.0#20170720-sha1:a6ca5c8a
>
> OS: Linux 3.10.0-514.el7.x86_64 amd64
>
>
>
> Thanks…
>
>
>
> Roger
>
>
>
>
> ------------------------------
> If you reply to this email, your message will be added to the discussion
> below:
> http://apache-ignite-users.70518.x6.nabble.com/Activation-slow-and-Ignite-
> node-crashed-in-the-middle-of-checkpoint-tp16144.html
> To start a new topic under Apache Ignite Users, email
> ml+s70518n1h65@n6.nabble.com
> To unsubscribe from Apache Ignite Users, click here
> <http://apache-ignite-users.70518.x6.nabble.com/template/NamlServlet.jtp?macro=unsubscribe_by_code&node=1&code=YWxleGFuZGVyLmZlZG90b2ZmQGdtYWlsLmNvbXwxfC0xMzYxNTU0NTg=>
> .
> NAML
> <http://apache-ignite-users.70518.x6.nabble.com/template/NamlServlet.jtp?macro=macro_viewer&id=instant_html%21nabble%3Aemail.naml&base=nabble.naml.namespaces.BasicNamespace-nabble.view.web.template.NabbleNamespace-nabble.view.web.template.NodeNamespace&breadcrumbs=notify_subscribers%21nabble%3Aemail.naml-instant_emails%21nabble%3Aemail.naml-send_instant_email%21nabble%3Aemail.naml>
>
--
View this message in context: http://apache-ignite-users.70518.x6.nabble.com/Activation-slow-and-Ignite-node-crashed-in-the-middle-of-checkpoint-tp16144p16176.html
Sent from the Apache Ignite Users mailing list archive at Nabble.com.