[IGNITE-10383] Partition Full message finished info printed out in logs after full message sent info

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 2.5
• Fix Version/s: 2.5
• Ignite Flags: Docs Required
• Assignee: Unassigned
• Reporter: Max Shonichev
• Created: 22/Nov/18 17:25
• Updated: 22/Nov/18 17:26

Description

see excerpt from logs:

==[crd]==
2018-11-19 18:57:55.845 [INFO ][sys-#3636%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=282, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=282, minorTopVer=0], err=null]
2018-11-19 18:57:55.845 [INFO ][sys-#3636%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture] Sending Full Message performed in 3 ms.
2018-11-19 18:57:55.845 [INFO ][sys-#3636%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture] Sending Full Message to all nodes performed in 5 ms.

2018-11-19 18:59:01.289 [INFO ][sys-#3610%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.GridCachePartitionExchangeManager] Finished full message creation [msgTopVer=AffinityTopologyVersion [topVer=282, minorTopVer=0], groups=[CacheGroupContext [grp=CACHEGROUP_PARTICLE_union-module_com.sbt.cdm.model.uss27.d
2018-11-19 18:59:01.898 [INFO ][sys-#3610%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.GridCachePartitionExchangeManager] Finished sending full message [msgTopVer=AffinityTopologyVersion [topVer=282, minorTopVer=0], groups=[CacheGroupContext [grp=CACHEGROUP_PARTICLE_union-module_com.sbt.cdm.model.uss27.di

==[non-crd]==
2018-11-19 18:57:56.693 [INFO ][sys-#8210%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=5f56aea6-3ecf-4a55-b2e1-cdafdb534e32, resVer=AffinityTopologyVersion [topVer=282, minorTopVer=0]]
2018-11-19 18:57:57.466 [INFO ][sys-#8210%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.CacheAffinitySharedManager] Affinity recalculation (on server join) performed in 773 ms.
2018-11-19 18:57:58.077 [INFO ][sys-#8210%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture] Affinity changes applied in 1384 ms.
2018-11-19 18:57:58.210 [INFO ][sys-#8210%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=282, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=282, minorTopVer=0], err=null]

'Finished sending full message' is printed out way too after message was sent and seemingly received by other node.
That confuses PME analyse, please fix it