search

MovingBlocks / Terasology

Terasology - open source voxel world
http://terasology.org
Apache License 2.0
3.68k stars 1.34k forks source link

Crash in multiplayer - chunk loading / rendering null issue, maybe related to dupe chunk loading [$50] #2590

Closed qwc closed 6 years ago

qwc commented 8 years ago

What you were trying to do

Running around and harvesting some sand.

What actually happened

Crash.

How to reproduce

Goood question, I will update WHEN I am able to reproduce this.

Log details and game version

Logfile: http://pastebin.com/9z7FQ7UK

Latest unstable locally and on server.

Computer details

Arch Linux Client, Ubuntu docker image on server.

Cervator commented 8 years ago

Renamed the title a bit, this is probably our biggest known crash issue at the moment, although narrowing down the details or reproducing reliably is problematic. It seems to have something to do with duplicate chunk loading feeding into a problem when then trying to render a newly loaded chunk. Documented some more over in #2477

Cervator commented 8 years ago

Interestingly it may have just happened for the first time without a reference to dupe chunk loading, but timed superbly to another player joining the server (another way to cause more chunk loads?)

Oddly the log file got cut at one point a few minutes before the crash, started with a Terasology-.log then continued in Terasology-mmo.to-188.68.52.110-25778.log

...
12:37:24.519 [main] INFO  o.t.r.dag.RenderTaskListGenerator - Task list generated in 2.021 ms
12:37:24.520 [main] INFO  o.t.r.dag.RenderTaskListGenerator - 30 nodes, 27 enabled - 88 tasks (excluding marker tasks) out of 115 potential tasks.
12:37:24.520 [main] INFO  o.t.r.dag.RenderTaskListGenerator - ----------------------------------------------------------
12:37:24.668 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'emptyIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UIIconBar","id":"breathBar","icon":"engine:icons#bubble","family":"breathBar","emptyIcon":"engine:icons#burstBubble","halfIconMode":"shrink","spacing":2,"maxIcons":10,"layoutInfo":{"use-content-width":true,"use-content-height":true,"position-left":{"target":"CENTER"},"position-right":{"target":"RIGHT","widget":"healthBar"},"position-bottom":{"target":"TOP","widget":"healthBar","offset":1}}}
12:37:24.669 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'crosshairIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UICrosshair","id":"crosshair","crosshairIcon":"engine:gui#crosshair","layoutInfo":{"use-content-width":true,"use-content-height":true,"position-horizontal-center":{},"position-vertical-center":{}}}
12:37:24.755 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'crosshairIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UICrosshair","id":"crosshair","crosshairIcon":"engine:gui#crosshair","chargeStages":["engine:gui#crosshairCharge1","engine:gui#crosshairCharge2","engine:gui#crosshairCharge3","engine:gui#crosshairCharge4","engine:gui#crosshairCharge5","engine:gui#crosshairCharge6","engine:gui#crosshairCharge7","engine:gui#crosshairCharge8"],"layoutInfo":{"use-content-width":true,"use-content-height":true,"position-horizontal-center":{},"position-vertical-center":{}}}
12:37:25.368 [main] ERROR o.t.p.t.TypeSerializationLibrary - Unable to register field of type ResourceUrn: not a supported type or MappedContainer
12:37:25.369 [main] INFO  o.t.p.t.TypeSerializationLibrary - Unsupported field: 'EventualSkills:SkillTrainedOwnerEvent.skillTrained'
12:37:25.369 [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:37:26.664 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (1039), capping to 1000
12:37:31.672 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3202, netId = 8830, prefab = 'engine:blockItemBase'}
12:37:31.672 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3201, netId = 8829, prefab = 'engine:blockItemBase'}
12:37:31.672 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3145, netId = 8735, prefab = 'ManualLabor:TheHumanMachine'}
12:37:31.673 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3814, netId = 9539, prefab = 'ManualLabor:Stick'}
12:37:31.673 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3142, netId = 8733, prefab = 'engine:player'}
12:37:31.673 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 0}
12:37:31.674 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3319, netId = 8984, prefab = 'engine:blockItemBase'}
12:37:31.674 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3140, netId = 8730, prefab = 'engine:client'}
12:37:31.674 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 4061, netId = 9826, prefab = 'engine:blockItemBase'}
12:37:31.674 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3240, netId = 8898, prefab = 'ManualLabor:CrudeHammer'}
12:37:31.674 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 3144, netId = 8734, prefab = 'engine:gaze'}
12:37:31.676 [main] INFO  o.t.logic.console.ConsoleImpl - [NOTIFICATION] Player "Halamix2" has left the game
<log got split here>
12:37:45.381 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 5625, netId = 9851}
12:38:08.934 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (1618), capping to 1000
12:38:25.979 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 4066, netId = 9843, prefab = 'engine:blockItemBase'}
12:38:29.663 [main] INFO  o.t.logic.console.ConsoleImpl - [CONSOLE] Welcome to the wonderful world of Terasology!

Type 'help' to see a list with available commands or 'help <commandName>' for command details.
Text parameters do not need quotes, unless containing spaces. No commas between parameters.
You can use auto-completion by typing a partial command then hitting [tab] - examples:

gh + [tab] => 'ghost'
help gh + [tab] => 'help ghost' (can auto complete commands fed to help)
giv + [tab] => 'giveBlock giveItem givePermission' (use [tab] again to cycle between choices)
lS + [tab] => 'listShapes' (camel casing abbreviated commands)

12:38:32.431 [main] INFO  o.t.logic.console.ConsoleImpl - [CONSOLE] You received 16 blocks of Torch
12:39:49.485 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12720, netId = 9859}
12:39:51.240 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12766, netId = 9885}
12:39:53.038 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12795, netId = 9890}
12:39:55.629 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12821, netId = 9899}
12:39:58.735 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12915, netId = 9927}
12:39:59.682 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12892, netId = 9924, prefab = 'engine:blockItemBase'}
12:39:59.989 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12959, netId = 9953}
12:40:03.991 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 13064, netId = 9956}
12:40:04.241 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 13087, netId = 9979, prefab = 'engine:blockItemBase'}
12:40:07.034 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 13108, netId = 9982}
12:40:08.334 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 13131, netId = 10005, prefab = 'engine:blockItemBase'}
12:40:19.486 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 12743, netId = 9882, prefab = 'engine:blockItemBase'}
12:40:42.878 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 13576, netId = 10006, prefab = 'engine:blockItemBase'}
12:40:45.840 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 13788, netId = 10007, prefab = 'engine:blockItemBase'}
12:44:16.270 [main] INFO  o.t.logic.console.ConsoleImpl - [NOTIFICATION] Player "Halamix2" has joined the game
12:44:34.335 [main] INFO  o.t.network.internal.ServerImpl - Destroying entity: EntityRef{id = 8210, netId = 9852, prefab = 'engine:blockItemBase'}
12:44:40.161 [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(Unknown Source)
    at java.util.TimSort.sort(Unknown Source)
    at java.util.Arrays.sort(Unknown Source)
    at java.util.ArrayList.sort(Unknown Source)
    at java.util.Collections.sort(Unknown Source)
    at org.terasology.rendering.world.RenderableWorldImpl.onChunkLoaded(RenderableWorldImpl.java:102)
    at org.terasology.rendering.world.WorldRendererImpl.onChunkLoaded(WorldRendererImpl.java:345)
    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:398)
    at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:431)
    at org.terasology.engine.modes.StateIngame.render(StateIngame.java:209)
    at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:190)
    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)
12:44:40.162 [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:412)
    at org.terasology.rendering.world.WorldRendererImpl.render(WorldRendererImpl.java:431)
    at org.terasology.engine.modes.StateIngame.render(StateIngame.java:209)
    at org.terasology.engine.subsystem.lwjgl.LwjglGraphics.postUpdate(LwjglGraphics.java:190)
    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)
12:44:40.162 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
12:44:40.173 [main] INFO  o.t.n.internal.NetworkSystemImpl - Network shutdown
12:44:40.331 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'emptyIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UIIconBar","id":"breathBar","icon":"engine:icons#bubble","family":"breathBar","emptyIcon":"engine:icons#burstBubble","halfIconMode":"shrink","spacing":2,"maxIcons":10,"layoutInfo":{"use-content-width":true,"use-content-height":true,"position-left":{"target":"CENTER"},"position-right":{"target":"RIGHT","widget":"healthBar"},"position-bottom":{"target":"TOP","widget":"healthBar","offset":1}}}
12:44:40.430 [main] WARN  o.t.rendering.nui.asset.UIFormat - Field 'crosshairIcon' not recognized for interface org.terasology.rendering.nui.UIWidget in {"type":"UICrosshair","id":"crosshair","crosshairIcon":"engine:gui#crosshair","layoutInfo":{"use-content-width":true,"use-content-height":true,"position-horizontal-center":{},"position-vertical-center":{}}}
12:44:40.660 [main] WARN  o.t.rendering.nui.skin.UISkinFormat - Failed to resolve UIWidget class UIInputBindButton, skipping style information
nihal111 commented 7 years ago

A crash that happened on a multiplayer test game may be related: http://pastebin.com/uxBNcexD

dkambersky commented 7 years ago

Still happening - happened today during the Alpha 7 prep playtest.

Happened thrice to me right after using hjump to launch myself into the sky, all three in quick succession. Then it happened once when I respawned about 100 blocks away - only thing I noticed was half the world wasn't rendered when the crash happened, but that's pretty standard when respawning.

Weirdly enough, at least if the logs are to be trusted, it doesn't seem to be immediately connected to multiple loads of a chunk - it's only preceded by those in 2 of the logs, and even then it could probably just be happenstance - I've had the 'multiple loads of chunk x' errors popping up pretty consistently even when things were running fine. Every time it happened the game was loading lots of chunks though.

After the initial 4 crashes, I wasn't able to reproduce it at all >.>

Logs here, because pastebin pastes seem to disappear rather quickly: https://gist.github.com/dkambersky/17e6857765aabb3887147b0094f2c62f

EDIT: referencing #2477 as that seems to be closely related, if not a duplicate

qwc commented 7 years ago

Got a similar crash again today on server testing... 1.3.1_SNAPSHOT_1940

Here as gist: https://gist.github.com/qwc/e7e13548fa663287d5b0cea9d9cadddd

Cervator commented 7 years ago

Another play test (Omega 691), another crash like this :-)

http://pastebin.com/pzmLjHGe

Cervator commented 7 years ago

Stiiiiiill happens

https://pastebin.com/pzjut06J

emanuele3d commented 7 years ago

@Cervator: I'm thinking we might want to put a bounty on this one. 50-100 USD?

Cervator commented 7 years ago

@emanuele3d done! We had $50 sitting around in our team account so I added that onto here :-)

gianluca-nitti commented 7 years ago

Not sure if it can be of any help - most likely not - but I have another log of this same issue, which happened to me today during the play test. Posting here with a bit of context: https://pastebin.com/TW1N2ydq. As you can see, it happened shortly after generating a list of render tasks.

Cervator commented 6 years ago

Counting this as RESOLVED with #3249 woohoo! Thanks @vampcat and everybody else having done detective work for this one over time :-)

And hey, bounty!

On its relation to dupe chunk loading, which is definitely still a thing (tracking via #3006 and also with related improvements requested in #2477) then I think that's indirectly related by possibly raising the odds for the issue to occur or it gets provoked by the same sort of scenario that leads to the nulls. So they remain different issues.