[1.9][BUG][FIXED] EntityJoinWorldEvent not always called!

[Ernio]

This issue is based on problems described in http://www.minecraftforge.net/forum/index.php/topic,37869.0.html

Note: Reading thread is not really neccesary (I'll cover it here).

 

So I've analised problem deeper with test mod and cleanest launch possible and in result I can present you with instructions on how to replicate problem and why is it "that" bad for (probably) not just my mod.

 

1. This is NEW issue. As described in 1st link it DID NOT occur in past using same code.

 

2. Problem is in fact that when some (described later) prerequisites are fulfilled - game starts to act DIFFERENTLY. If this is not a bug, then I don't know what is.

 

3. How to replicate:

 

Prerequisites:

* Clean server launch (no world)

* Use this source: (comments)

@Mod(modid = "Test", name = "Test", version = "1")
public class Test
{
@Instance("Test")
public static Test INSTANCE;

@EventHandler
protected void preInit(FMLPreInitializationEvent event)
{
	MinecraftForge.EVENT_BUS.register(this);
}

@SubscribeEvent
public void onEntityAttachCapabilities(AttachCapabilitiesEvent.Entity event)
{
	// check for "not-player" is needed. This event is called from constructor where player.toString() is not possible
	// entity.toString() is possible and will return proper entityName and entityId (rest, as in coords, is equal to 0)
	if (event.getEntity() instanceof EntityLivingBase && !(event.getEntity() instanceof EntityPlayer))
	{
		System.out.println(event.getEntity() + " ATTACH");
	}
}

@SubscribeEvent
public void onEntityJoinWorld(EntityJoinWorldEvent event)
{
	if (event.getEntity() instanceof EntityLivingBase)
	{
		System.out.println(event.getEntity() + " JOINED");
	}
}

@SubscribeEvent
public void onPlayerStartTracking(PlayerEvent.StartTracking event)
{
	if (event.getTarget() instanceof EntityLivingBase)
	{
		System.out.println(event.getTarget() + " TRACKING");
	}
}
}

 

How this code ALWAYS worked in past: ATTACH -> JOINED -> TRACKING

As of "some" (unknown to me) change this is no longer a case in ALL situations.

 

Replicating:

1. Launch your clean server once, wait until you get "Done" print:

[server thread/INFO]: Done (3,412s)! For help, type "help" or "?"

Notice:

* During clean server startup you should get prints:

[server thread/INFO] [FML/]: Loading dimension 0 (world) (net.minecraft.server.dedicated.DedicatedServer@ff2f633)
[server thread/INFO] [FML/]: Loading dimension 1 (world) (net.minecraft.server.dedicated.DedicatedServer@ff2f633)
[server thread/INFO] [FML/]: Loading dimension -1 (world) (net.minecraft.server.dedicated.DedicatedServer@ff2f633)
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntitySheep['Sheep'/0, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntitySheep['Sheep'/0, l='world', x=-144,50, y=63,00, z=405,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityChicken['Chicken'/1, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityChicken['Chicken'/1, l='world', x=-85,50, y=63,00, z=332,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityChicken['Chicken'/2, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityChicken['Chicken'/2, l='world', x=-82,50, y=63,00, z=336,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityCow['Cow'/3, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityCow['Cow'/3, l='world', x=-83,50, y=64,00, z=381,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityCow['Cow'/4, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityCow['Cow'/4, l='world', x=-82,50, y=64,00, z=381,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityCow['Cow'/5, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityCow['Cow'/5, l='world', x=-86,50, y=64,00, z=382,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityCow['Cow'/6, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityCow['Cow'/6, l='world', x=-78,50, y=66,00, z=386,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityCow['Cow'/7, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityCow['Cow'/7, l='world', x=-75,50, y=66,00, z=383,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityCow['Cow'/8, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityCow['Cow'/8, l='world', x=-75,50, y=66,00, z=381,50] JOINED
[server thread/INFO] [sTDOUT/]: [Test:onEntityAttachCapabilities:31]: EntityCow['Cow'/9, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT/]: [Test:onEntityJoinWorld:40]: EntityCow['Cow'/9, l='world', x=-76,50, y=66,00, z=385,50] JOINED
// Until DONE print.

* As you can see - entities are constructing and then joining world. Like it was in past.

 

2. Stop the server.

 

3. Launch server again. As of now - launch is not clean and the world will be loading.

Notice:

* You will get prints more like this:

[server thread/INFO] [FML]: Loading dimension 0 (world) (net.minecraft.server.dedicated.DedicatedServer@2d08c71)
[server thread/INFO] [FML]: Loading dimension 1 (world) (net.minecraft.server.dedicated.DedicatedServer@2d08c71)
[server thread/INFO] [FML]: Loading dimension -1 (world) (net.minecraft.server.dedicated.DedicatedServer@2d08c71)
[server thread/INFO]: Preparing start region for level 0
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntitySheep['Sheep'/0, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntityChicken['Chicken'/1, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntityChicken['Chicken'/2, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntityCow['Cow'/3, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntityCow['Cow'/4, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntityCow['Cow'/5, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntityCow['Cow'/6, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntitySquid['Squid'/7, l='world', x=0,00, y=0,00, z=0,00] ATTACH
[server thread/INFO] [sTDOUT]: [Test:onEntityAttachCapabilities:32]: EntitySquid['Squid'/8, l='world', x=0,00, y=0,00, z=0,00] ATTACH
// This goes on and on until "Done" - not SINGLE entity ever joins world.

 

* On contrary to clean start - entities are now only constructed. They never join world (never = we are talking about server loading phase, meaning "Done" message = end).

EDIT: They do JOIN the world. It is just that EntityJoinWorldEvent is not called!

 

4. While still having server on (the 2nd launch one), launch client.

- Login on localhost.

- Look into console.

The prints will be something like this (after "Done"):

[server thread/INFO]: Done (4,946s)! For help, type "help" or "?"
[user Authenticator #1/INFO]: UUID of player Ernio is ***
[Netty Server IO #1/INFO] [FML]: Client protocol version 2
[Netty Server IO #1/INFO] [FML]: Client attempting to join with 4 mods : [email protected],Test@1,[email protected],[email protected]
[server thread/INFO] [FML]: [server thread] Server side modded connection established
[server thread/INFO]: Ernio[***] logged in with entity id 221 at (34.5, 62.0, 250.5)
[server thread/INFO]: Ernio joined the game
[server thread/INFO] [sTDOUT]: [Test:onEntityJoinWorld:41]: EntityPlayerMP['Ernio'/221, l='world', x=34,50, y=62,00, z=250,50] JOINED
[server thread/INFO] [sTDOUT]: [Test:onPlayerStartTracking:50]: EntitySpider['Spider'/69, l='world', x=31,50, y=42,00, z=270,50] TRACKING
[server thread/INFO] [sTDOUT]: [Test:onPlayerStartTracking:50]: EntityChicken['Chicken'/70, l='world', x=16,88, y=64,00, z=263,53] TRACKING
[server thread/INFO] [sTDOUT]: [Test:onPlayerStartTracking:50]: EntityCreeper['Creeper'/88, l='world', x=44,53, y=36,00, z=227,20] TRACKING
[server thread/INFO] [sTDOUT]: [Test:onPlayerStartTracking:50]: EntityBat['Bat'/89, l='world', x=37,98, y=40,10, z=233,75] TRACKING
[server thread/INFO] [sTDOUT]: [Test:onPlayerStartTracking:50]: EntityBat['Bat'/68, l='world', x=28,78, y=37,10, z=234,33] TRACKING
[server thread/INFO] [sTDOUT]: [Test:onPlayerStartTracking:50]: EntityChicken['Chicken'/98, l='world', x=54,60, y=65,00, z=248,11] TRACKING
[server thread/INFO] [sTDOUT]: [Test:onPlayerStartTracking:50]: EntityChicken['Chicken'/99, l='world', x=62,17, y=65,00, z=242,51] TRACKING

 

* As you will see - EntityJoinWorldEvent was never called for entities loaded from NBT.

 

Conclusion;

EntityJoinWorldEvent is NOT always called!

This all leads to non-stable game event ordering.

 

Thank you for reading and I am hoping for fix

 

EDIT (Post updated)

[Ernio]

I think that I tracked down the problem:

 

World#loadEntities is calling EntityJoinWorldEvent.

 

WorldServer#loadEntities is not (override) - Unless I am missing something - this is the change in 1.9.

 

EDIT

https://github.com/MinecraftForge/MinecraftForge/issues/2685

[Ernio]

Sorry for whining (I know it takes time for devs), but I got to ask - does anyone care about this enough to make fix in near future?

 

This is seriously a matter of putting additional statement inside WorldServer#loadEntities if statement.

 

I'd do it myself if I knew how to make patches.

 

Thanks to this someone