Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
qwc opened this issue Nov 5, 2016 · 11 comments
Labels
Multiplayer Affects aspects not visible in Singleplayer mode only Type: Bug Issues reporting and PRs fixing problems
Milestone

Comments

@qwc
Copy link
Contributor

qwc commented Nov 5, 2016

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 Cervator changed the title [latest unstable] Crash at some sand mining. Crash in multiplayer - chunk loading / rendering null issue, maybe related to dupe chunk loading Nov 5, 2016
@Cervator Cervator added Type: Bug Issues reporting and PRs fixing problems Multiplayer Affects aspects not visible in Singleplayer mode only labels Nov 5, 2016
@Cervator
Copy link
Member

Cervator commented Nov 5, 2016

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
Copy link
Member

Cervator commented Nov 5, 2016

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
Copy link
Member

nihal111 commented Dec 3, 2016

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

@dkambersky
Copy link
Member

dkambersky commented Mar 4, 2017

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
Copy link
Contributor Author

qwc commented Mar 12, 2017

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

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

@Cervator
Copy link
Member

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

http://pastebin.com/pzmLjHGe

@Cervator
Copy link
Member

Cervator commented May 6, 2017

Stiiiiiill happens

https://pastebin.com/pzjut06J

@emanuele3d
Copy link
Contributor

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

@Cervator Cervator changed the title Crash in multiplayer - chunk loading / rendering null issue, maybe related to dupe chunk loading Crash in multiplayer - chunk loading / rendering null issue, maybe related to dupe chunk loading [$50] May 7, 2017
@Cervator Cervator added the bounty label May 7, 2017
@Cervator
Copy link
Member

Cervator commented May 7, 2017

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

@gianluca-nitti
Copy link
Member

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 Cervator added this to the Alpha 9 milestone Feb 4, 2018
@Cervator
Copy link
Member

Cervator commented Feb 4, 2018

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.

@Cervator Cervator closed this as completed Feb 4, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Multiplayer Affects aspects not visible in Singleplayer mode only Type: Bug Issues reporting and PRs fixing problems
Projects
None yet
Development

No branches or pull requests

6 participants