We are talking about:

* PlayerEvent.StartTracking

* EntityJoinWorldEvent

 

Some part of my mod are pretty old (but well written), and they are working for months now.

About month (I think) ago I upped to 1.8.9 and everything also seemed (I wasn't coding much, maybe I missed bug there) fine.

 

Anyway, I soon decided to go to 1.9. Currently I am on latest (while ago 1812 -> 1816 now) build and I am getting unexpected errors (as in - they are concerning my very old code).

 

Okay, so problem:

Till now system worked like this:

1. Construction attaches props.

2. Maps are constructed and filled with "holders" for attributes.

3. EntityJoinWorldEvent calls props.maps.load() - this is done because entity can be constructed, but not be in world, so I decided to load attributes to map after they join. Also - world (and coords/weather/etc) affects loaded attributes so that is pretty much design requirement.

4. PlayerEvent.StartTracking catches every entity player starts tracking, iterates over all holders in entity's props.maps and send them to client.

 

Till now - this all happened smooth. As of (I think) 1.9 update it seems that expected order of events is not longer kept.

 

BIG NOTE! While tracking is called on server only - joinWorld is called on both. I just need to say - this and anything with threads is not my problem, we are right now talking about server only side.

 

In past when player logged in, all entities near his pos were:

constructed -> loaded -> tracked

Note: server (even without players) sometimes constructs entities without making them join world.

 

As of now: As expected those things happen in this order but only after 10-20 entities load.

[05:01:37] common.entity.player.ExtendedPlayer:deserializeNBT:183]: LOADING: {C:[]}
[05:01:37] server.event.ServerForgeEvents:onEntityJoinWorld:116]: EntityPlayerMP['Ernio'/236, l='world', x=-84,50, y=71,00, z=241,50] JOIN
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/35, l='world', x=-146,50, y=69,00, z=259,50] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/35, l='world', x=-146,50, y=69,00, z=259,50]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/37, l='world', x=-158,49, y=67,00, z=272,70] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/37, l='world', x=-158,49, y=67,00, z=272,70]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/42, l='world', x=-133,76, y=73,00, z=245,57] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/42, l='world', x=-133,76, y=73,00, z=245,57]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/36, l='world', x=-143,80, y=74,00, z=264,45] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/36, l='world', x=-143,80, y=74,00, z=264,45]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/44, l='world', x=-113,48, y=84,00, z=182,78] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/44, l='world', x=-113,48, y=84,00, z=182,78]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/45, l='world', x=-115,46, y=76,00, z=205,75] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/45, l='world', x=-115,46, y=76,00, z=205,75]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/46, l='world', x=-120,18, y=85,00, z=194,48] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/46, l='world', x=-120,18, y=85,00, z=194,48]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/65, l='world', x=-64,80, y=70,00, z=246,40] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/65, l='world', x=-64,80, y=70,00, z=246,40]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/66, l='world', x=-65,81, y=70,00, z=249,17] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/66, l='world', x=-65,81, y=70,00, z=249,17]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/67, l='world', x=-69,50, y=70,00, z=240,50] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/67, l='world', x=-69,50, y=70,00, z=240,50]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/68, l='world', x=-64,27, y=70,00, z=264,49] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/68, l='world', x=-64,27, y=70,00, z=264,49]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/75, l='world', x=-63,76, y=70,00, z=232,81] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/75, l='world', x=-63,76, y=70,00, z=232,81]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/76, l='world', x=-52,50, y=68,00, z=270,50] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/76, l='world', x=-52,50, y=68,00, z=270,50]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/77, l='world', x=-55,50, y=70,00, z=266,50] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/77, l='world', x=-55,50, y=70,00, z=266,50]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityItem['item.tile.mushroom'/74, l='world', x=-48,75, y=32,00, z=222,82] TRACK // item are not synced, only living ents are
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySheep['Sheep'/84, l='world', x=-41,95, y=69,00, z=265,52] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySheep['Sheep'/84, l='world', x=-41,95, y=69,00, z=265,52]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityItem['item.tile.mushroom'/83, l='world', x=-44,97, y=34,00, z=223,78] TRACK
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/97, l='world', x=-32,55, y=66,75, z=218,51] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/97, l='world', x=-32,55, y=66,75, z=218,51]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/64, l='world', x=-67,04, y=66,00, z=180,35] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/64, l='world', x=-67,04, y=66,00, z=180,35]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/57, l='world', x=-110,55, y=81,00, z=182,58] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/57, l='world', x=-110,55, y=81,00, z=182,58]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/72, l='world', x=-50,54, y=66,00, z=185,72] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/72, l='world', x=-50,54, y=66,00, z=185,72]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/73, l='world', x=-54,51, y=64,00, z=176,23] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/73, l='world', x=-54,51, y=64,00, z=176,23]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/98, l='world', x=-18,22, y=64,00, z=221,49] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/98, l='world', x=-18,22, y=64,00, z=221,49]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/99, l='world', x=-19,60, y=64,00, z=215,53] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/99, l='world', x=-19,60, y=64,00, z=215,53]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/96, l='world', x=-19,59, y=64,00, z=207,81] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/96, l='world', x=-19,59, y=64,00, z=207,81]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/56, l='world', x=-110,50, y=80,00, z=164,20] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/56, l='world', x=-110,50, y=80,00, z=164,20]  null
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityCow['Cow'/71, l='world', x=-54,95, y=63,00, z=173,29] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityCow['Cow'/71, l='world', x=-54,95, y=63,00, z=173,29]  null
[05:01:37] server.event.ServerForgeEvents:onEntityJoinWorld:116]: EntityBat['Bat'/276, l='world', x=-39,50, y=54,00, z=241,50] JOIN // FINALLY 1st JOIN
[05:01:37] common.entity.BaseStats:load:195]: EntityBat['Bat'/276, l='world', x=-39,50, y=54,00, z=241,50] LOAD // and his LOAD (called from JOIN)
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityBat['Bat'/276, l='world', x=-39,50, y=54,00, z=241,50] TRACK // and his corresponding TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityBat['Bat'/276, l='world', x=-39,50, y=54,00, z=241,50]  B10.0 // and STATS are detected
[05:01:37] server.event.ServerForgeEvents:onEntityJoinWorld:116]: EntitySkeleton['Skeleton'/286, l='world', x=-70,50, y=29,00, z=224,50] JOIN
[05:01:37] common.entity.BaseStats:load:195]: EntitySkeleton['Skeleton'/286, l='world', x=-70,50, y=29,00, z=224,50] LOAD
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntitySkeleton['Skeleton'/286, l='world', x=-70,50, y=29,00, z=224,50] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntitySkeleton['Skeleton'/286, l='world', x=-70,50, y=29,00, z=224,50]  B10.0
[05:01:37] server.event.ServerForgeEvents:onEntityJoinWorld:116]: EntityBat['Bat'/302, l='world', x=-74,50, y=33,00, z=273,50] JOIN
[05:01:37] common.entity.BaseStats:load:195]: EntityBat['Bat'/302, l='world', x=-74,50, y=33,00, z=273,50] LOAD
[05:01:37] server.event.ServerForgeEvents:onPlayerStartTracking:71]: EntityBat['Bat'/302, l='world', x=-74,50, y=33,00, z=273,50] TRACK
[05:01:37] common.entity.EntityStats:synchronizeStatsTo:77]: EntityBat['Bat'/302, l='world', x=-74,50, y=33,00, z=273,50]  B10.0
// AND SO ON

 

As you can se - we get:

TRACK -> null at 1st, but then everything is back to normal:

JOIN (LOAD) -> TRACK -> stats sent (this B10.0 thing).

 

Question: Could someone help me find what exacly changed in callbacks? Something must have!

 

Addition: Yeah I can make null check but that would mean that those 20 entities would not get synced on player join - that would be very bad for client display (in my case).

Noone? :C I am lost here guys.

 

What amazes me is actually how entity can be started to be tracked if it never joined world.

 

Its either that:

* JoinWorld is not called for few entities (wtf?) and they are spawned without calling event.

* They are NOT actually spawned (and thats why JoinWorld is not called), but mistakenly put into EntityTracker's Player mapping where they are not supposed to be (since they are not in world).

 

I am starting to think someone messed up and this might be a bug.

When I get back in few h I will make cleaner test mod (tho my current tests are quite clean since I am just printing stuff from event call).