Activation: slow and: Ignite node crashed in the middle of checkpoint.

classic Classic list List threaded Threaded
7 messages Options
Roger Fischer (CW) Roger Fischer (CW)
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

 

afedotov afedotov
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

 




To start a new topic under Apache Ignite Users, email [hidden email]
To unsubscribe from Apache Ignite Users, click here.
NAML

Roger Fischer (CW) Roger Fischer (CW)
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

RE: Activation: slow and: Ignite node crashed in the middle of checkpoint.

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:[hidden email]]
Sent: Monday, August 14, 2017 11:05 AM
To: [hidden email]
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

 

 


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.

Alexey Kukushkin Alexey Kukushkin
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: RE: Activation: slow and: Ignite node crashed in the middle of checkpoint.

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) <[hidden email]> wrote:


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:[hidden email]]
Sent: Monday, August 14, 2017 11:05 AM
To: [hidden email]
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

 

 


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.

dkarachentsev dkarachentsev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

RE: Activation: slow and: Ignite node crashed in the middle of checkpoint.

In reply to this post by Roger Fischer (CW)
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.
Roger Fischer (CW) Roger Fischer (CW)
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

RE: Activation: slow and: Ignite node crashed in the middle of checkpoint.

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:[hidden email]]
Sent: Tuesday, August 15, 2017 2:05 AM
To: [hidden email]
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.

Nikolai Tikhonov-2 Nikolai Tikhonov-2
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Activation: slow and: Ignite node crashed in the middle of checkpoint.

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) <[hidden email]> 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:[hidden email]]
Sent: Tuesday, August 15, 2017 2:05 AM
To: [hidden email]
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.


Loading...