Better / clearer handling of duplicate chunk loading in multiplayer

[Cervator]

During a multiplayer test event we had a few crashes resulting in an error like http://pastebin.com/xeNM3uCn (snipped inlined below) or https://gist.github.com/rzats/b16a7fd41c0b37033d5de5079500e8c7 where seemingly dupe chunk loading precedes an error where a chunk comparison ends up with a null chunk (a cancelled dupe?)

That's just an unproven theory based on the lines of code involved, but we probably need to figure out why we're getting into loading multiple chunks in the first place. The logging doesn't yield a lot of intel to help figure that out, maybe we can improve it to get better ideas in the future? The spot in ChunkEventErrorLogger has access to EntityRef worldEntity so maybe we could log some more, try to detect what player or other source caused the chunk load request. Or better defeat the multiple loads without risking crashes elsewhere?

I'm really unsure on this one but it did happen multiple times and I've seen the error get logged infrequently over the past few weeks, or likely even longer. Chunk loading / sorting for prioritization could use some work, based on some vague old memories.

Possibly related: #2385

16:55:23.932 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, -2, 3)
16:55:24.162 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 2, 3)
16:55:24.278 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 9707, netId = 5057}
16:55:24.347 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 9710, netId = 5060}
16:55:24.365 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, 0, 4)
16:55:24.454 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 9696, netId = 5054, prefab = 'engine:blockItemBase'}
16:55:24.471 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (5, -1, 4)
16:55:24.508 [main] ERROR o.t.e.event.internal.EventSystemImpl - Failed to invoke event
java.lang.NullPointerException: null
    at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:212)
    at org.terasology.rendering.world.RenderableWorldImpl$ChunkFrontToBackComparator.compare(RenderableWorldImpl.java:447)
    at org.terasology.rendering.world.RenderableWorldImpl$ChunkFrontToBackComparator.compare(RenderableWorldImpl.java:443)
    at java.util.TimSort.countRunAndMakeAscending(TimSort.java:360)
    at java.util.TimSort.sort(TimSort.java:234)
    at java.util.Arrays.sort(Arrays.java:1512)
    at java.util.ArrayList.sort(ArrayList.java:1454)
    at java.util.Collections.sort(Collections.java:175)
    at org.terasology.rendering.world.RenderableWorldImpl.onChunkLoaded(RenderableWorldImpl.java:102)
    at org.terasology.rendering.world.WorldRendererImpl.onChunkLoaded(WorldRendererImpl.java:280)
    at org.terasology.rendering.world.WorldRendererSystem.onChunkLoaded(WorldRendererSystem.java:38)
    at org.terasology.rendering.world.WorldRendererSystemMethodAccess.invoke(Unknown Source)
    at org.terasology.entitySystem.event.internal.EventSystemImpl$ByteCodeEventHandlerInfo.invoke(EventSystemImpl.java:506)
    at org.terasology.entitySystem.event.internal.EventSystemImpl.sendStandardEvent(EventSystemImpl.java:269)
    at org.terasology.entitySystem.event.internal.EventSystemImpl.send(EventSystemImpl.java:260)
    at org.terasology.entitySystem.entity.internal.BaseEntityRef.send(BaseEntityRef.java:145)
    at org.terasology.world.chunks.remoteChunkProvider.RemoteChunkProvider.completeUpdate(RemoteChunkProvider.java:274)
    at org.terasology.rendering.world.RenderableWorldImpl.update(RenderableWorldImpl.java:165)
    at org.terasology.rendering.world.WorldRendererImpl.preRenderUpdate(WorldRendererImpl.java:323)
    at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:356)
    at org.terasology.engine.modes.StateIngame.render(StateIngame.java:209)
    at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:189)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:422)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:368)
    at org.terasology.engine.Terasology.main(Terasology.java:152)
16:55:24.511 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
java.lang.NullPointerException: null
    at org.terasology.rendering.world.RenderableWorldImpl.isChunkValidForRender(RenderableWorldImpl.java:376)
    at org.terasology.rendering.world.RenderableWorldImpl.queueVisibleChunks(RenderableWorldImpl.java:303)
    at org.terasology.rendering.world.WorldRendererImpl.preRenderUpdate(WorldRendererImpl.java:337)
    at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:356)
    at org.terasology.engine.modes.StateIngame.render(StateIngame.java:209)
    at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:189)
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:422)
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:368)
    at org.terasology.engine.Terasology.main(Terasology.java:152)
16:55:24.511 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
16:55:24.548 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown

Want to back this issue? Post a bounty on it! We accept bounties via Bountysource.

[Cervator]

Still seems to be happening, reported by @Rulasmur just now from the Alpha 5 multiplayer test event

http://pastebin.com/nxZJVzjU

[Cervator]

Still happening - Alpha 5 and a half testing and @qwc separately on the same server earlier (noted in #2590)

12:25:11.176 [main] ERROR o.t.p.typeHandling.Serializer - No type handler for type class org.terasology.assets.ResourceUrn used by class org.terasology.eventualSkills.events.SkillTrainedOwnerEvent::skillTrained
12:27:21.128 [main] ERROR o.t.l.debug.ChunkEventErrorLogger - Multiple loads of chunk (-1, 0, -7)
12:27:23.958 [main] ERROR o.t.e.event.internal.EventSystemImpl - Failed to invoke event
java.lang.NullPointerException: null
    at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:212)

[Cervator]

Update: While the "multiple loads of chunk x" still occurs and may have actually gotten worse to now also trigger heavily by replicating #3006 the one null issue in #2590 is resolved!

We could still improve logging related to when multiple loads happen, I expect, so this issue remains valid, just without the crash we just resolved. For instance, don't we / couldn't we track the reason a chunk is requested for loading? It would be swell to see "Chunk x dupe loading: requester was player y entering range at z")

One way to replicate this now with some intense log spam is to (maybe only on a headless server?) wander off a ways from spawn then suiciding and respawning. Possibly the exact range matters. I suspect at least once I hit this while from my death location the edge of loaded chunks were still covering spawn.

[Cervator]

So while #3792 was only a possible fix for this issue the GitHub auto-close thing just saw "fix for" ;-)

During testing of that PR I did still provoke Multiple loads of chunk (0, 0, 0) it didn't result in a crash, and I haven't noticed this outright crash for some time. Going to leave this closed and 🤞 that it is gone.